FWD » Core Development » Runtime Infrastructure

4GL Logging Facilities

• LOG-MANAGER system handle
  • assign the LOGFILE-NAME attribute to associate a log file with the handle
  • all subsequent logging output goes to that file
  • logging can come from 2 sources
    • implicitly from the 4GL runtime
      • things generated by the runtime that normally would display on STDOUT (e.g. error messages)
      • instrumented logging at defined entry points in the 4GL runtime
      • configured using LOG-MANAGER:LOG-ENTRY-TYPES and LOG-MANAGER:LOGGING-LEVEL
    • explicitly using LOG-MANAGER:WRITE-MESSAGE() which will output whatever the 4GL code wants to write
• -clientLog command line parameter
  • it seems like this may be the equivalent of setting LOG-MANAGER:LOGFILE-NAME
  • however the documentation says it redirects all error messages, warning messages, stack traces to the given log file, these are things that normally go to STDOUT, it is not clear if the LOG-MANAGER also gets all warnings and stack traces
  • there are other command line parameters that seem to map to the LOG-MANAGER features (e.g. -logentrytypes, -logginglevel and others)

We will need to test to see if there are any differences between the command line approach and the LOG-MANAGER facility. We need to confirm that all the implicit and explicit output works the same way no matter if set via the command line or via attributes on the LOG-MANAGER handle.

STDIO

As far as I can tell, the 4GL never outputs to STDERR. I've tried various ways to start the 4GL interactive and batch client sessions with redirected STDERR. All the normal ways to generate output don't go to STDERR. This includes the MESSAGE statement, stream IO like PUT, UI statements like DISPLAY and error output from the 4GL runtime.

STDOUT is different, it is very important.

• interactive 4GL clients
  • redirecting STDOUT at the command line has no effect, any output that normally is displayed to the user is still displayed to the user
  • the logging facilities can be used to allow errors (and maybe warnings and stack traces) to be redirected to a configured log
  • using OUTPUT TO, OUTPUT THROUGH, INPUT-OUTPUT THROUGH@ output that normally goes to STDOUT can be redirected to the given stream
  • STDIN can also be redirected using INPUT FROM, INPUT THROUGH and INPUT-OUTPUT THROUGH, then any input normally read from STDIN will be redirected from the given stream
  • I haven't tested redirecting STDIN from the command line
• batch clients
  • when a batch client is started, you can redirect STDIO using normal command line > and 2> and <
  • redirecting STDERR has no effect
  • redirecting STDOUT and/or STDIN
    • you only have to redirect the ones that are in use
    • will work as expected in a command pipeline or using streams/files
    • this means that input (reading from STDIN) or output (write to STDOUT) will be redirected as used
  • if you do NOT redirect STDIO:
    • if you use input (reading from STDIN) or output (write to STDOUT), then the session will be ended with an error
    • if you do not use interactive input or output, then the session will work normally
  • there is no way to implement the equivalent of the command line redirection
• appserver/REST/SOAP agents
  • these are a form of batch client except the command line redirection or pipelines aren't used
  • the configuration comes from ubroker.properties (classic appserver) or its PASOE equivalent

Constantin: please document how to configure the agent logging in the 4GL and how these agents are different from batch clients with their STDIO.

This task is intended to implement a unified and simple approach for configuring logging. We need to also consider which sources of configuration are needed. I will post more ideas shortly.

Our "internal" FWD-specific logging is written to STDERR. This happens when we write to any Logger instance obtained from the LogHelper, which uses the built-in Java logging facilities.

Converted application output to the "terminal" is written to STDOUT. This is the same as in the 4GL itself.

In FWD, we have the following different ways to configure client-side logging and redirection.

• interactive clients
  • when started via the client.sh, we define a log filename using log="${logdir}/client_$(whoami)_${$}.log" and we redirect STDERR using 2>$log
  • when ClientDriver.main() is invoked by clients that are being spawned using a TemporaryClient instance (the bootstrap config will have a value for server:spawner:uuid), then ClientDriver.setClientLog("client") will be called which will create a log filename in the form "client_%s_%d.log" where System.getProperty("user.name") and System.currentTimeMillis() are substituted, System.setErr() is used to override STDERR
  • no matter how the ClientDriver is launched, the following are also implemented:
    • -clientLog support
      • if the bootstap configuration file contains a non-null logfile name in client:cmd-line-option:clientlog, then it will be passed to ThinClient.initClientLog() which creates an "anonymous" logger instance (from LogHelper) with the handler set to Level.INFO
      • this logger is only used in 2 places which are in turn called from ErrorManager and ThinClient
        • ThinClient.displayErrorMessage() when !noMessageBox and isRedirected()
        • ThinClient.clientLog()
      • right now, some errors, messages and stack traces are written this way when it is set
    • LOG-MANAGER
      • the server side implementation is in LegacyLogManagerImpl
      • the instances of this system handle are managed on the server side by LegacyLogOps
      • the implementation is empty right now, it does nothing and has no integration with the client
  • client side LogHelper loggers
    • various loggers are initialized in the client code, including:
      • ClientCore.initLogging()
        • very early in initialization if bootstrap config has logging:debug:enable set to true
        • in this case the LogHelper will be initalized with "client_dbg_%g.log" as the file handler pattern
        • this is only for debug purposes, it initializes detailed logging in com.goldencode.p2j.net and com.goldencode.p2j.main packages
        • the settings are hard coded
      • all other loggers
        • no proper LogHelper.initialize() call is ever made
        • this means the Java logging is left at this defaults
        • it defaults to STDERR output but this lack of configurability is limiting
        • ClientCore.initializeLogger(), ThinClient and many other client classes
• batch clients
  • when started from the command line, any STDIO redirection on the command line will be honored
  • when started from the spawner:
    • there is an optional redirection of STDOUT
      • that is only implemented if clientConfig/outputToFile is configured
      • when configured it is converted into a command line parameter by ProcessClientBuilder.getSpawnArguments() which generates a -O <logfile> on the spawner command line
      • the configured value is treated as a spec and there are substitution values for %userid% (substituted for the process account name), %timestamp% (substituted for System.currentTimeMillis()) and %appserver% (substituted for the account setting appserver if it is configured in the account)
      • if the spawner fines a -O command line parameter, it replaces any &pid% with its own (spawner) pid and then redirects STDOUT to that file
      • if not configured there is no redirection for STDOUT
  • the STDERR is handled by the ClientDriver the same way as for spawner launched interactive clients
• appserver/SOAP/REST agents - I think everything is the same as batch clients except there is no launching from the command line case

Have I missed anything or gotten anything incorrect?

I think we need to implement the following:

• standard redirections
• log file names and locations
• log helper initialization
• logging configuration
• this should occur for all clients, no matter how they are started (command line or spawner)
• configuration
  • sensible defaults when none are configured
  • server-side directory based
  • overrides in the bootstrap config

I want to avoid different ways to configure by command line or spawner. The command line cases will need to detect if there is already a redirection and honor that. Otherwise everything should be handled the same way.

A related issue to be addressed by the change, as described in #4331:

Standalone clients (confirmed for gui_swing) generate a type of log file (client_gbb_443366.log, described in my previous summary as 2) "%type%_%user%_%date%.log") that is not supposed to be generated (should be there only for spawned processes). Its path cannot be modified at the moment through configs and it gets generated in the client work directory (client-gui/ for testcases).
I believe I know where the problem is - a not very tight condition related to the presence of server:spawner:uuid option, instead of checking its value.
I'm not sure if it needs to be fixed, because some users may use these logs at present.

I'll use this comment to summarize the types of log files we ultimately need (it'll be updated additionally).

• Each system process should have a separate log file.
  • TODO: list all types of processes and come up with log file namings

    System Process [ Entry ]	Expected Log Type (File/Console)
    ServerDriver MODE_START runs StandardServer and SingleProcessClient (ClientCore) in the same process.	File "server_start_20221216_timestamp_0.log" and File ...
    ServerDriver instance Connects to another JVM (creates session) to execute a remote command. MODE_STOP MODE_STATUS MODE_WAIT MODE_START_APPSERVER MODE_RECONFIGURE MODE_START_BATCH_PROCESS MODE_START_METHOD_TRACE MODE_STOP_METHOD_TRACE	Console?
    spawner	TBD
    NativeSecureConnection JVM by spawner	none?
    ClientDriver	File ...

• Screen / client drivers output on the screen except for the batch driver that is not expected to output anything.
  • Why do we support client config outputToFile? Is it due to lack of proper server-side LOG-MANAGER implementation?
• LOG-MANAGER related code should produce logs only server-side, since that's where the ABL apps are executed. But configs will come from the client (cmd line or from process client configs in directory.xml).

• from converted ABL procedures / apps (these should be left to be handled by LOG-MANAGER),
• from FWD Framework for debug purposes (FWD logger).

Client-side code execution should generate only FWD specific logs for debug purposes (FWD logger). One per client process.

Spawner should generate log files for debug purposes. One file per spawn attempt.

Conversion code should be reworked to not be broken by upcoming changes. If possible let's keep it simple (as it is) for now.

FWD logger should be configured in one place for both server and client side, that is directory.xml. File names for FWD logger should not be configurable, but system generated. Only log dirs should be configurable both in server/default/logging as fwdServerLogDir and fwdClientLogDir.

Client bootstrap configs should be used only for LOG-MANAGER features support and should be documented.

A question: If some FWD users want to develop their new Java code extending their app functionality, do they import / integrate with the FWD framework classes or start from zero? In other words do we need to keep backwards compatibility of the runtime framework interface (formed by the public methods and classes)?

• Each system process should have a separate log file.

Yes

• Screen / client drivers output on the screen except for the batch driver that is not expected to output anything.

Mostly yes. There are multiple client types which are variants on the batch mode. This includes appserver agents, REST agents and SOAP agents. These variants handle logging differently than the traditional 4GL batch mode.

• Why do we support client config outputToFile? Is it due to lack of proper server-side LOG-MANAGER implementation?

No. As noted in #1612-150:

The 4GL sets up logging automatically for each appserver agent. This is configured as part of the appserver configuration, but I think that even by default there is some kind of log. Essentially, it is like redirecting STDOUT and STDERR to this log for the given agent. In Progress, batch processes are also supposed to have their output redirected in a similar way. Both appserver agents and batch processes are non-interactive ChUI clients.

And from #1612-151:

For appserver agents (and also batch processes configured in the directory and started via the scheduler) the log is configured via the clientConfig/outputToFile entry.

This means it is primarily to provide a mechanism for a case that is configurable in the 4GL appserver/REST/SOAP approach OR which doesn't exist in the 4GL (batch processes auto-launched by our server).

• LOG-MANAGER related code should produce logs only server-side, since that's where the ABL apps are executed.

No. We need both server side and client side logging. I think most of the time the server side approach will be used and that will be much faster than making a client round-trip for each log entry. BUT, the actual 4GL approach for classic appserver agents is client based (each agent is a separate process and there is no actual server process). If these are launched with specific OS accounts/permissions etc... then it will need a compatible client-side approach.

We must implement both ways, but we will make the server-side approach the default.

But configs will come from the client (cmd line or from process client configs in directory.xml).

Yes

Server-side code execution should generate two types of log files:

• from converted ABL procedures / apps (these should be left to be handled by LOG-MANAGER),
• from FWD Framework for debug purposes (FWD logger).

I think there is a 3rd "redirected output" case which is also needed. This is probably always on the client side (at least for now).

Client-side code execution should generate only FWD specific logs for debug purposes (FWD logger). One per client process.

I think we need the FWD logger to be a more architected approach. The idea is that we will have session-specific FWD logging that must be output. This can happen at either the server side or on the client side. When this logging is generated, it must be output to the FWD log regardless of where the logging output was generated. In addition, there may be logging which should be in the server log (non-session-specific).

All of the output to STDERR needs to go away and move to an architected approach.

Spawner should generate log files for debug purposes. One file per spawn attempt.

Yes, though this should be optional. We would not generate this by default.

Conversion code should be reworked to not be broken by upcoming changes. If possible let's keep it simple (as it is) for now.

Right now, I don't foresee any changes to conversion needed. If that changes, I would agree with this idea.

FWD logger should be configured in one place for both server and client side, that is directory.xml. File names for FWD logger should not be configurable, but system generated. Only log dirs should be configurable both in server/default/logging as fwdServerLogDir and fwdClientLogDir.

Hmm, I'm not sure about this. My intuition is to allow this to be optionally configured via bootstrap configuration override while defaulting to a value that comes from the directory. This would allow us to eliminate the extra debug log (i.e. logging:debug:enable).

Client bootstrap configs should be used only for LOG-MANAGER features support

I think the FWD logger also needs to be configurable this way.

and should be documented.

Yes

If some FWD users want to develop their new Java code extending their app functionality, do they import / integrate with the FWD framework classes or start from zero?

Both are done and both must be supported.

In other words do we need to keep backwards compatibility of the runtime framework interface (formed by the public methods and classes)?

We are at a point where we are still heavily modifying our implementation and that includes our external API. Changes are still possible there. On the other hand, some changes will affect customer code that is already in production to the extent that they have hand-written code that uses our API. For this reason, we will try to limit those changes, but as long as the changes make sense we can move ahead.

At this time, I don't see how our 4GL-compatibility needs to change for this task, but I may be missing something.

Greg Shah wrote:

At this time, I don't see how our 4GL-compatibility needs to change for this task, but I may be missing something.

I was thinking of the LogHelper and its behavior - if that could be changed.

Greg Shah wrote:

We are at a point where we are still heavily modifying our implementation and that includes our external API.

I think Java 11 is already supported. If Java 11 modules are used (even one for the whole app should be enough) external API can be easily distinguished.

Yes, LogHelper can be changed.

We are at a point where we are still heavily modifying our implementation and that includes our external API.

I think Java 11 is already supported. If Java 11 modules are used (even one for the whole app should be enough) external API can be easily distinguished.

We still support Java 8 so at this time we can't commit to this usage.

Greg Shah wrote:

We need both server side and client side logging. I think most of the time the server side approach will be used and that will be much faster than making a client round-trip for each log entry. BUT, the actual 4GL approach for classic appserver agents is client based (each agent is a separate process and there is no actual server process). If these are launched with specific OS accounts/permissions etc... then it will need a compatible client-side approach.

We must implement both ways, but we will make the server-side approach the default.

I will look into the appserver agents. To me this doesn't sound like the same LOG-MANAGER that should support the converted ABL code on the server.

Greg Shah wrote:

Galya Bogdanova wrote:

Conversion code should be reworked to not be broken by upcoming changes. If possible let's keep it simple (as it is) for now.

Right now, I don't foresee any changes to conversion needed. If that changes, I would agree with this idea.

I probably misunderstood the comment #5753-5

TRPL will need changes and there are other dependent projects that may need configuring if they use separate logging (e.g. SLF4J, LOG4J...).

Right now, I don't foresee any changes to conversion needed. If that changes, I would agree with this idea.

I probably misunderstood the comment #5753-5

TRPL will need changes and there are other dependent projects that may need configuring if they use separate logging (e.g. SLF4J, LOG4J...).

Hmmm, no you understood correctly. Greg Shah from the past was thinking more carefully than Greg Shah from the present. :)

In #5753-5 I was not suggesting that the conversion rules needed to generate anything differently. Instead, I was just suggesting that the way we use logging from the TRPL rules (we just output to STDOUT/STDERR) is what needs to change. We need to make those locations use an architected logging helper that will allow us to manage the logfiles explicitly.

This is needed during runtme because TRPL rules are used to convert dynamic queries (which are just 4GL expressions in strings). This is just another location that uses STDOUT/STDERR, but which is less obvious to find since it is not in Java code.

Please review my proposal for standardization of the logging: Logs#Future-Improvements.

Galya Bogdanova wrote:

Please review my proposal for standardization of the logging: Logs#Future-Improvements.

This is good. I have a couple of updates.

1. I don't think we want a separate client and server logging infrastucture. The fact that we have a separation of client and server is an internal implementation detail of FWD but it doesn't match the OE approach. I don't want our logging to make this implementation detail visible. I think this means we have to forward the log output to a single destination instead of having 2 desstinations.

2. In regard to "File names are not configurable to make file identification and sorting easier, but log dir is configurable.", this is documented in 2 places. I'm OK with setting a default filename but I do want to provide a means for customers to control/customize the filename portion. We can't take this out of their hands.

Greg Shah wrote:

1. I don't think we want a separate client and server logging infrastructure. The fact that we have a separation of client and server is an internal implementation detail of FWD but it doesn't match the OE approach. I don't want our logging to make this implementation detail visible. I think this means we have to forward the log output to a single destination instead of having 2 destinations.

In terms of code nothing will be different between the two, so no separate infrastructure. It is a matter only of configuration incl. destination. Client and server are different processes, so Logger will have different instances anyways and it can have different configurations. Actually I don't mind merging fileLevel and consoleLevel for both. But let's discuss the file destination. Currently there are several client log files that are independent of the server log files, that's why I didn't consider it ground breaking to leave two separate files - one for the client and one for the server. If you prefer them to be one, there is only one way to do it - RPC that I wouldn't recommend for such a heavy continuous operation like logging. It will impact the performance and I'm not sure it can be rationalize with any requirements from outside. If the users don't understand FWD has client / server model, I'm not sure they will be able to use it properly anyways. Also there are certain classes shared between the client and the server and having only one log file may make it difficult to debug where the log comes from.

This is my take on the matter, but please let me know what would be the final decision or if there is anything I've missed. Do we go for RPC on each client log write to keep only one file?

P.S. Also let's not forget the logs they are familiar with will be available through LOG-MANAGER, while reading FWD logs might require better understanding of the framework anyways.

Greg Shah wrote:

2. In regard to "File names are not configurable to make file identification and sorting easier, but log dir is configurable.", this is documented in 2 places. I'm OK with setting a default filename but I do want to provide a means for customers to control/customize the filename portion. We can't take this out of their hands.

I think this is a question related to the framework nature of FWD, but I'm not very sure how the users use it. If they expand the code with their own additions, how is the new code deployed? Is it a separate process or just a new lib in the classpath of the server? I'm seeing FWD log as a crash report log that will be sent to us for debugging from time to time. But if it's supposed to be extended by new log writes from the new code of the user, it's not that any more.

Back to question 1: clients are separate processes started with different process ids and user ids - do we want their logs mixed in one file?

Client and server are different processes

This is only because of how we implement in FWD. The equivalent system in OE is a single process. For this reason, we cannot cause log output to be spread across multiple destinations. It must be combined.

Everything in the 4GL is "client". They have no "server" the way FWD does. This means that each appserver agent is really just a client that runs on the server and has jobs sent to it. In FWD, we split off the "client platform" parts into the FWD client and run everything else on the FWD application server. But we need to output our logging in a single destination.

By default, the destination should be on the client side which would match the OE approach. We also want to have a "everything logs on the server" idea which is cleaner and when the log output is primarily generated on the server, this is much faster too. We have implemented this "client stuff optionally running on the server" in #4065. We need to use the same configuration approach used there. I don't know that we need to use the same technical redirection approach but we can do that too if it makes sense.

The only exception to the above would be log entries which only exist outside of a session context. Those can be legitimately considered FWD application server log entries. We may also want to have some small set of session context logging (abends?) be duplicated in the server log. Perhaps we generate some log entry that says "an abend occurred in this context, look at log destination xyz for more details".

so Logger will have different instances anyways and it can have different configurations.

I agree we should have a single configuration too.

If you prefer them to be one,

If we don't do it this way, it will be considered a bug by our customers.

there is only one way to do it - RPC that I wouldn't recommend for such a heavy continuous operation like logging. It will impact the performance and I'm not sure it can be rationalize with any requirements from outside.

Yes, this is exactly why we have been implementing #4065. Most logging will be generated on the server. If we configure server-side logging, then this will not be an issue. But by default, the logging needs to redirect via RPC to the client. We expect most customers will configure server-side logging.

We can use our StateSynchronizer (see how it is used in LogicalTerminal and ThinClient) to "piggyback" our logging output on other round trips to the client or server. I think we use that mechanism here to avoid the penalty. This makes the solution more complicated.

If the users don't understand FWD has client / server model, I'm not sure they will be able to use it properly anyways.

This is already an issue. All of our customers must understand this model. We aren't adding anything special here.

Also there are certain classes shared between the client and the server and having only one log file may make it difficult to debug where the log comes from.

Excellent point. Please consider how we can enhance the logging output to make this clear, always.

If they expand the code with their own additions, how is the new code deployed?

By definition, FWD is used to execute some application written by non-GCD people. Of course, they will change that and add to that system over time. They won't necessarily be changing FWD itself (although they could if they want). They will always be deploying their enhanced application on top of our platform. Any entries in the log that are related to FWD itself are secondary to the logging that would be coming from the application.

Is it a separate process or just a new lib in the classpath of the server?

They will be editing their 4GL code and adding new Java code together into a single server where the core processing is the converted 4GL code.

I'm seeing FWD log as a crash report log that will be sent to us for debugging from time to time. But if it's supposed to be extended by new log writes from the new code of the user, it's not that any more.

The logs are not primarily for us. They are for the application developers and the people that deploy/support the application in production. Yes, some entries may represent bugs that we have to fix. This is not the common use case. We will not design this for our convenience. It is being designed for the convenience and utility of our customers.

Most importantly, we cannot make logging worse than when they ran under OE. When we split this into 2 logs, it was much worse. We are fixing that now.

I'm currently working on a new logger class that encapsulates the previously used Java Logger and handles a lot of the specific FWD complexities. It has to remove current direct use of Java Logger throughout the application. I was able to extract the interface currently in use, but there is one particular part of it I'm very much willing to remove from the code:

   public abstract void setLevel(Level level);
   public abstract Level getLevel();

• AdminServerImpl always sets the logger level to Level.FINER. The class itself logs messages with level WARNING and SEVERE. There is also a method log for logging, but it's never used:
  

     private static void log(Level level, String message)
     {
        LOG.logp(level, "AdminServer", "", LogHelper.generate(message));
     }
  

• SecurityManager reads security/config/debug-level from directory server-side to set the level to one of the custom ones NONE/ERROR/WARNING/STAT/LIST/TRACE/DATA;
• SecurityManager reads logging:debug:enable from bootstrap client-side to set the level to Level.FINEST;
• SecurityManager references Audit to log different messages with level Level.INFO. Audit sets logger level to Level.INFO basically overwriting any other config.

• AdminServerImpl never logs anything below Level.WARNING, so no need to set the level to something explicitly.
• Custom levels defined in SecurityManager are never used anywhere else and don't contribute anything;
• Level of client logging in debug should be set with a standard directory config override instead of logging:debug:enable from now on.
• Separate classes should not have the power to overwrite the customer decision of what level to see in log files. Otherwise Audit will always persist SecurityManager messages. Do we need to keep this?

I need assistance with FWD RPC. I'm trying to use a new interface for clients to send data to the server, but the calls hang without throwing an Exception and the server doesn't seem to receive the calls. Here is what I have:

StandardServer#bootstrap:

      ifaces = new Class[] { CentralLogService.class };
      RemoteObject.registerStaticNetworkServer(ifaces, CentralLogStaticService.class);

public interface CentralLogService
{
   void publish(LogRecord logRecord);
}

public class CentralLogStaticService
{
   public static void publish(LogRecord logRecord)
   {
      CentralLoggerServer.publish(logRecord);
   }
}

public class CentralLoggerServer
{
   public static void publish(LogRecord logRecord)
   {
      fileHandler.publish(logRecord);
   }
}

ThinClient#initializePost:

CentralLogService logService =
            (CentralLogService) RemoteObject.obtainNetworkInstance(CentralLogService.class, session);
         CentralLoggerClient.initialize(logService);

CentralLoggerClient:

logService.publish(logRecord);

Also the param LogRecord is a Java class that implements java.io.Serializable.

Now that logService.publish(logRecord) call from the client never completes and doesn't seem to get to the server or throw an exception. Logging is little messed up now since I'm working on it, so not sure if there is something I could be missing. I debug it manually.

Am I missing some configurations for this to work?

The problem with the new interface was missing directory.xml configs. Fixed.

I'm stuck on a hurdle I have no clue about. The new network interface (sending logs from the client to the server) works well right after obtainNetworkInstance. It has only one method and it's executed right away doing as expected. A reference to the network instance is stored in another class and reused later. That's when the client hangs indefinitely trying to look up for a key: in RemoteObject on line key = hlo.getKey(group, name);. I can debug further in the stack, but it gets to a lower level and it's more unclear to me what's the cause. I guess it might be related to the session being changed, but I inspected it right before execution of the method and it seems the same as the first time. Any ideas?

Is there something I need to know about FWD RPC, threads and Conversation thread?

I made a breakthrough. I was thinking the issues with the freezing client and no exceptions thrown is in the line of configurations and authentication, because it was the SecurityManager that gave indications something was going wrong and a few exceptions were silenced. But it ended up being that using FWD rpc to send logs from the clients to the server for the sake of merging both types of log files is quite troublesome.

The logger having dependencies on SecurityManager and plethora of related classes (those needed for making rpc calls) leads to some entertaining issues: deadlocks when some classes decide to create logs after being called by the logger and the recursion of logging the details of network calls for publishing logs to the server (especially when trace enabled).

Now that I've found the issues, they are solvable, but this feature will definitely need a good regression testing.

Greg, the classes BlockingSSL and NetSocket (LoggingNetSocket / NIOSslSocket) log low level details of the rpc calls when a trace logging level (Level.FINE or lower) is enabled. They work on separate threads and the stacktrace cannot show if the call is for the RemoteObject of the logger. The only way to solve the recursion is to save their logs in a separate file instead of sending them to the server log file. And since their logs don't make sense separated from RemoteObject logs, all of these classes should have a different file.

What do you think?

We've previously noted that making an up (client to server) or down (server to client) call to write the log output will cause a performance issue. In #5703-27, I mentioned that we can "piggyback" our log entries using the StateSynchronizer. The idea here is that we just store the log entries in memory on the local side and do not up or down call. The next time we make a RemoteObject call for some other functional reason (i.e. not logging), the current log output will be transferred as part of the pending state changes and will be written on the other side before the control flow continues there. I think this is also the solution to this current deadlock issue since there will be no calls to RemoteObject needed for either the net package logging or any other logging.

Please look into those classes and ask questions as needed.

Greg Shah wrote:

We've previously noted that making an up (client to server) or down (server to client) call to write the log output will cause a performance issue. In #5703-27, I mentioned that we can "piggyback" our log entries using the StateSynchronizer. The idea here is that we just store the log entries in memory on the local side and do not up or down call. The next time we make a RemoteObject call for some other functional reason (i.e. not logging), the current log output will be transferred as part of the pending state changes and will be written on the other side before the control flow continues there. I think this is also the solution to this current deadlock issue since there will be no calls to RemoteObject needed for either the net package logging or any other logging.

Please look into those classes and ask questions as needed.

While debugging I saw the StateSynchronizer. The only concern would be if some logs will be discarded at the end of the application run. I'll let you know when I try it.

The only concern would be if some logs will be discarded at the end of the application run.

Agreed, we should take care to avoid that.

Greg Shah wrote:

I think this is also the solution to this current deadlock issue since there will be no calls to RemoteObject needed for either the net package logging or any other logging.

I actually solved the deadlock, but the recursion is not solvable because I cannot mute only certain logs in the low level classes (produced way too far from the application logic).

If possible. Of course, a network failure while something is pending will be a problem.

Whether it is recursion or deadlock, the state synch approach should work.

Greg Shah wrote:

If possible. Of course, a network failure while something is pending will be a problem.

I've actually created a mechanism for crash logs that are produced when the app stops before the regular logs are produced (as I've mentioned in one of my emails the loggers need to be initialized at certain point to work). This same mechanism can be used to save any leftover logs on disconnect or another irregular state when the app should shut down.

P.S. Although not ideal, still a way to have it all.

Good

An important question - up till now FWD logs were written to the console by System.err and redirected to a file, so in practice console logs were never read on the console. Now with proper file support, do we need to maintain console handler for the logger? I would recommend to drop it. This way nothing will be printed out with 2>$log and users will find out about the proper logger (which works out of the box with default settings).

This is more a question about the server, because it doesn't make sense to have FWD logs in the console for clients anyways, since that's where the output should reproduce Progress behavior.

• To spend time to rewrite all System.err (which will involve the decision of how important each log is). This way System.err will be available for the logger console handler to output direct logger calls. And after that nobody should use System.err for log messages, because they will not be saved to the file.
• To continue reading System.err and start writing back to the console using System.out. In this case I should make sure it doesn't interfere with chui and the expected output of the standalone batch clients; basically it should work only on the server.
• And of course the third option is my proposal of dropping it, since it has always been used only to generate file logs that we'll have anyways.

So do we have console logs?

Greg, when you wrote:

I think we need to implement the following:
standard redirections

did you have in mind also outputToFile (batch stdout redirect in bgr processes) to be made the same as standalone batch redirect? After merging #5701 outputToFile will be used programatically instead of cmd line, while standalone batch still uses > cmd line. Do I need to rework it to reuse the same method as well?

Let me also raise the question about the new logger name.

• CentralLogger - the base class used throughout the framework to create logs
• CentralLoggerClient - the subclass with client specific logic
• CentralLoggerServer - the subclass with server specific logic
• CentralLogRecord - the Externalizable log record used for transferring data to the server (on certain occasions)
• CentralLogService - the rpc interface (one method only)
• CentralLogStaticService - the rpc interface implementation

I used Central since the base class is used on both client and server side and also that logger should be the only one used in the future.
Do you approve of the name or have another proposal?

I have no objection to the name.

Galya Bogdanova wrote:

Greg, when you wrote:

I think we need to implement the following:
standard redirections

did you have in mind also outputToFile (batch stdout redirect in bgr processes) to be made the same as standalone batch redirect? After merging #5701 outputToFile will be used programatically instead of cmd line, while standalone batch still uses > cmd line. Do I need to rework it to reuse the same method as well?

I'm not sure we can eliminate the command line use of > because customers may have 4GL code used as batch processes in a pipeline. On the other hand, this is only a subset of the cases and generally we do want a consistent approach for all cases.

Can you help me understand what you mean by "rework it to reuse the same method"? In this case, what is "it" and what is "same method"?

Greg Shah wrote:

Can you help me understand what you mean by "rework it to reuse the same method"? In this case, what is "it" and what is "same method"?

Instead of printing on the console in standalone batch execution, we can redirect System.out to outputToFile. There should be a change in the code to handle this case as well.

P.S. Actually not even a redirect. For batch there is a certain method in ErrorWriterBatch that should be reworked to write to outputToFile.

Greg Shah wrote:

I'm not sure we can eliminate the command line use of > because customers may have 4GL code used as batch processes in a pipeline.

What is the connection between the FWD JVM and the 4GL batch processes in the pipeline. Are 4GL processes spawned by Java or the other way around or something completely different?

up till now FWD logs were written to the console by System.err and redirected to a file, so in practice console logs were never read on the console. Now with proper file support, do we need to maintain console handler for the logger?

I don't think there is a need for it. I agree that we don't want our implementation logging to STDERR or STDOUT.

I would recommend to drop it. This way nothing will be printed out with 2>$log and users will find out about the proper logger (which works out of the box with default settings).

I'm OK with dropping it, though I wonder if there will be a problem with non-FWD output.

Currently I've redirected System.err stream to be converted to logs.

This is OK, but in a perfect world we would have all of these outputs be proper logging.

In that context if we need FWD logs in the console output of the server

No, I don't think that FWD output needs to go to the console.

Constantin: Am I forgetting something?

To spend time to rewrite all System.err (which will involve the decision of how important each log is). This way System.err will be available for the logger console handler to output direct logger calls. And after that nobody should use System.err for log messages, because they will not be saved to the file.

This is the preferred way for FWD.

To continue reading System.err and start writing back to the console using System.out. In this case I should make sure it doesn't interfere with chui and the expected output of the standalone batch clients; basically it should work only on the server.

I don't think this is needed.

I think customers still need to redirect STDERR or STDOUT. Thread dumps will still get generated to STDOUT on the server, and other non-FWD code may write to STDERR. If there is anything important in that STDERR output, then it might be the case where we would want to continue reading the output of STDERR and writing it to our proper logs. But this is not optimal, since it let's people be "sloppy" and use System.err for output.

For batch there is a certain method in ErrorWriterBatch that should be reworked to write to outputToFile.

I'm not understanding the idea here.

What is the connection between the FWD JVM and the 4GL batch processes in the pipeline. Are 4GL processes spawned by Java or the other way around or something completely different?

The FWD client JVM is the replacement for the 4GL batch processes in the pipeline. This means we need FWD in batch mode to be able ot read from STDIN and write to STDOUT just like any pipeline program.

I agree with everything said. Let me just explain about batch. At the moment it doesn't work exactly as in Progress where it outputs to the console, as well as to a file with redirect. I think there was even a slight difference between both outputs. FWD implementation of batch uses only one method to write to stdout, that is in ErrorWriterBatch, so if needed it can be used to also write to a file. This was just a side note on console output.

• Rewrite all System.err to proper logger calls.
• Leave 3rd party lib output to directly go to the console and be handled by the user.
• Leave batch as it is - running on the server with output in outputToFile; running standalone with output to console and being redirected by the user.
• Don't output any FWD logs to the console (dropping logger console handler)

At the moment it doesn't work exactly as in Progress where it outputs to the console, as well as to a file with redirect. I think there was even a slight difference between both outputs.

Let's document the differences from Progress in a new task so we don't forget the issue. We will need to fix it at some point.

How do we want to treat the logging level from configs? It could be the min level for all loggers or the default level for all loggers.

• directory.xml logging/file/level is Level.SEVERE;
• CentralLogger.get(AdminServerImpl.class).setLevel(Level.FINER) and then CentralLogger.get(AdminServerImpl.class).log(Level.WARNING, msg).

• pass through all logs generated by AdminServerImpl with Level.FINER or higher;
• don't pass through any AdminServerImpl logs below Level.SEVERE.

If config level is considered min value, then specific logger can only narrow down / filter out their logs.

Use this as the default level. I don't see a good reason for implementing a minimum level.

Greg Shah wrote:

Use this as the default level. I don't see a good reason for implementing a minimum level.

• SecurityManager has a default level of WARNING and reads "/security/config/debug-level" or "logging/debug/enable" which sets it to "DATA" (Level.FINEST).
• AdminServerImpl sets its own level to Level.FINER (hardcoded).

• Audit has its own Java logger with configs in "/security/audit/" - file pattern, count and size.

Do we leave this separate logger?

Use this as the default level. I don't see a good reason for implementing a minimum level.

Then we should have in mind that several classes set their own logger levels programmatically:

• SecurityManager has a default level of WARNING and reads "/security/config/debug-level" or "logging/debug/enable" which sets it to "DATA" (Level.FINEST).
• AdminServerImpl sets its own level to Level.FINER (hardcoded).

I don't think these need to exist.

Also there is this separate logger:

• Audit has its own Java logger with configs in "/security/audit/" - file pattern, count and size.

Do we leave this separate logger?

Yes, this is needed to ensure that other logging changes don't disrupt audit-related logging, which must have a higher/separate priviledge level for security purposes.

We should keep the configuration separate but make the structure of the configuration compatible with our main logging approach.

TransformDriver (ProgressTransformDriver / ConversionDriver) are used as standalone apps and if I'm not wrong they can be also launched runtime on the server as well.

Are there any other entry points in the code? These need to be taken care of in the context of logger having server / client structure.

The obvious ones are ServerDriver, ClientDriver, also NativeSecureConnection.

If you can think of any other please let me know.

⚠ Which entry points are NOT used with p2j classpath?

List of all entry points in FWD Entry Points Table. Please give your input by editing the table!

If I just use com.goldencode.p2j.util.logging.CentralLogger in some of these classes and classpath with p2j is not present (when used as standalone tools), things won't work out.

P.S. To be used with p2j classpath means we're expecting the user to first compile the whole project.

Also System.err can be found in ignored classes:

src/com/goldencode/p2j/e4gl/E4GLParser.java
src/com/goldencode/p2j/preproc/BracesParser.java
src/com/goldencode/p2j/preproc/TextParser.java
src/com/goldencode/p2j/uast/ExpressionEvaluator.java
src/com/goldencode/p2j/uast/ProgressParser.java

Can I have the permission to edit them and replace System.err with a logger?

It seems that some of the main methods are used by Harness for tests.

1. Can we get them out to the test directory?
2. Can I use the logger instead of System prints in these methods?

And about the rest of the classes with main methods: Can I try to move all tools to a separate package, so that we know why there is so much System.err / out prints in them and they will not seed the seed of going against the future rule of using only the logger? If there are no package private dependencies it will work well.

• used for standalone testing, not FWD runtime or conversion:
  

  /src/com/goldencode/expr/TestDriver.java 
  /src/com/goldencode/util/PrintSystemProp.java 
  /src/com/goldencode/p2j/directory/LockManagerTest.java 
  /src/com/goldencode/p2j/uast/FunctionSample.java 
  /src/com/goldencode/p2j/ui/ExtractImageCommand.java 
  

• used at build scripts, not FWD runtime:
  

  /src/com/goldencode/util/NormalizePath.java 
  /src/com/goldencode/p2j/persist/deploy/ScriptRunner.java 
  

• Java UDF support (used at FWD server runtime on H2 server AFAIK); for PL/Java, these are used on postgresql server, in their own JVM. A limit p2jpl.jar is built and loaded for PL/Java support:
  

  /src/com/goldencode/p2j/persist/pl/Contains.java 
  /src/com/goldencode/p2j/persist/pl/Functions.java 
  

• standalone tool, not used by the FWD runtime:
  

  /src/com/goldencode/p2j/directory/LdapMapGen.java 
  /src/com/goldencode/p2j/directory/DirectoryCopy.java 
  /src/com/goldencode/p2j/directory/DirectoryDiff.java 
  /src/com/goldencode/p2j/directory/RemapTestDriver1.java 
  /src/com/goldencode/p2j/pattern/SearchTrees.java 
  /src/com/goldencode/p2j/util/LoadCert.java 
  /src/com/goldencode/p2j/util/ExportCert.java 
  /src/com/goldencode/p2j/util/LoadPrivateKey.java 
  /src/com/goldencode/p2j/uast/SupportLevelDocumentationGenerator.java 
  /src/com/goldencode/p2j/uast/LegacyBuiltInClassSanitizer.java 
  /src/com/goldencode/p2j/test/DirectoryEdit.java 
  /src/com/goldencode/p2j/security/EncryptBase64Value.java 
  /src/com/goldencode/p2j/security/AcmeClient.java 
  /src/com/goldencode/p2j/security/ManagedWebServer.java 
  /src/com/goldencode/p2j/security/SelfSignedCertGen.java 
  /src/com/goldencode/p2j/security/KeyImport.java 
  /src/com/goldencode/ast/DumpBitSet.java 
  /locale/P2JLocaleHelper.java 
  /locale/Code2Name.java 
  /locale/Name2Code.java
  

• conversion only:
  

  /src/com/goldencode/util/DatabaseDumpChecker.java 
  /src/com/goldencode/p2j/report/ReportDriver.java 
  /src/com/goldencode/p2j/util/FileSpecList.java 
  /src/com/goldencode/p2j/util/ExplicitFileList.java 
  /src/com/goldencode/p2j/uast/CallGraphGenerator.java 
  /src/com/goldencode/p2j/uast/ScanDriver.java 
  /src/com/goldencode/p2j/uast/JavaSymbolResolver.java 
  /src/com/goldencode/p2j/convert/ProgressTransformDriver.java 
  /src/com/goldencode/p2j/convert/GenerateWsdl.java 
  /src/com/goldencode/p2j/convert/ConversionDriver.java 
  /src/com/goldencode/p2j/schema/RelationAnalyzer.java 
  /src/com/goldencode/p2j/e4gl/E4GLPreprocessor.java 
  /src/com/goldencode/p2j/e4gl/E4GLLexer.java 
  

• standalone web app (report web server for FWD analytics):
  

  /src/com/goldencode/p2j/report/server/ReportWebServer.java 
  

• used by FWD server or FWD client runtime:
  

  /src/com/goldencode/expr/ExpressionParser.java
  /src/com/goldencode/expr/ExpressionLexer.java 
  /src/com/goldencode/expr/ConstantPool.java 
  /src/com/goldencode/expr/Expression.java 
  /src/com/goldencode/util/RandomWordGenerator.java 
  /src/com/goldencode/util/FibonacciCounter.java 
  /src/com/goldencode/util/HexDump.java 
  /src/com/goldencode/util/NativeTypeSerializer.java 
  /src/com/goldencode/util/PayloadSerializer.java 
  /src/com/goldencode/util/FastSiblingDeque.java 
  /src/com/goldencode/email/Emailer.java 
  /src/com/goldencode/p2j/persist/P2JIndex.java 
  /src/com/goldencode/p2j/persist/id/Range.java 
  /src/com/goldencode/p2j/persist/hql/HQLParser.java 
  /src/com/goldencode/p2j/persist/hql/HQLLexer.java 
  /src/com/goldencode/p2j/persist/orm/FqlToSqlConverter.java 
  /src/com/goldencode/p2j/persist/orm/FQLParser.java 
  /src/com/goldencode/p2j/persist/orm/UdfException.java 
  /src/com/goldencode/p2j/persist/orm/FQLLexer.java 
  /src/com/goldencode/p2j/persist/lock/InMemoryLockManager.java 
  /src/com/goldencode/p2j/pattern/PatternEngine.java 
  /src/com/goldencode/p2j/util/CryptoUtils.java 
  /src/com/goldencode/p2j/util/datetimetz.java 
  /src/com/goldencode/p2j/util/Quoter.java 
  /src/com/goldencode/p2j/util/decimal.java 
  /src/com/goldencode/p2j/util/LogicalExpressionConverter.java 
  /src/com/goldencode/p2j/util/ScopedList.java 
  /src/com/goldencode/p2j/util/DataSetSDOHelper.java 
  /src/com/goldencode/p2j/util/ConnectHelper.java 
  /src/com/goldencode/p2j/util/character.java 
  /src/com/goldencode/p2j/util/date.java 
  /src/com/goldencode/p2j/xml/XmlAst.java 
  /src/com/goldencode/p2j/Version.java 
  /src/com/goldencode/p2j/uast/ProgressLexer.java 
  /src/com/goldencode/p2j/uast/AstKey.java 
  /src/com/goldencode/p2j/uast/ExpressionEvaluator.java 
  /src/com/goldencode/p2j/uast/ProgressParser.java 
  /src/com/goldencode/p2j/convert/NameConverter.java 
  /src/com/goldencode/p2j/reporting/XprHelper.java 
  /src/com/goldencode/p2j/SpiVersion.java 
  /src/com/goldencode/p2j/schema/SchemaLoader.java 
  /src/com/goldencode/p2j/schema/P2OLookup.java 
  /src/com/goldencode/p2j/schema/SchemaDictionary.java 
  /src/com/goldencode/p2j/schema/EntityName.java 
  /src/com/goldencode/p2j/schema/SchemaParser.java 
  /src/com/goldencode/p2j/security/HashPassword.java 
  /src/com/goldencode/p2j/security/SymmetricEncryption.java 
  /src/com/goldencode/p2j/security/SecurityAdmin.java 
  /src/com/goldencode/p2j/security/SSLCertGenUtil.java 
  /src/com/goldencode/p2j/ui/client/format/DateFormat.java 
  /src/com/goldencode/p2j/ui/client/gui/driver/web/res/p2j.canvas_renderer_webgl.js 
  /src/com/goldencode/p2j/ui/Keyboard.java 
  /src/com/goldencode/p2j/cfg/Configuration.java 
  /src/com/goldencode/p2j/cfg/BootstrapConfig.java 
  /src/com/goldencode/p2j/main/ClientDriver.java 
  /src/com/goldencode/p2j/main/ServerDriver.java 
  /src/com/goldencode/p2j/main/ClientsToPortsGenerator.java 
  /src/com/goldencode/p2j/preproc/Preprocessor.java 
  /src/com/goldencode/p2j/preproc/PreprocessorHints.java 
  /src/com/goldencode/proxy/StaticProxy.java 
  

Classes used in FWD runtime should have a common logging approach. The problem here is that some of these classes (like ProgressParser, PatternEngine) are used in conversion, too. Maybe a default, non-configured logger should target STDOUT?

AFAIK FWD builds a single p2j.jar used by both server and client. The only exception is p2jpl.jar, which is loaded into postgresql and a separate JVM instance is started by postgresql when needing to run something within PL/Java. We are deprecating this - Greg, if we introduce other jar dependencies to p2jpl.jar, then this will break fast. I'm OK with breaking it if we are going to deprecate and not support PL/Java at all.

Otherwise, the standalone tool list (and build scripts) still work with the full p2j.jar, and any other jar dependencies required. The problem here: any added logging should default to STDOUT, as the tools are meant to be interactive.

Galya, how do I configure the loggers to log to STDOUT, for the FWD server? This should be the default way.

Constantin Asofiei wrote:

Galya, how do I configure the loggers to log to STDOUT, for the FWD server? This should be the default way.

Good point. I still haven't implemented this 3rd mode. I'll get to it now. In the meantime in Logs under Supported configs you can find the directory.xml configs, including logging/file/dir.

There is a NPE when 'nothing is configured':

NullPointerException.<init>() line: 60 [local variables unavailable]    
Objects.requireNonNull(T) line: 203    
Optional<T>.<init>(T) line: 96    
Optional<T>.of(T) line: 108    
CentralLoggerServer(CentralLogger).getParentLevel() line: 587    
CentralLoggerServer(CentralLogger).isLoggable(Level) line: 422    
CentralLoggerServer(CentralLogger).log(Level, String, String, String, Throwable, Object...) line: 546    
CentralLoggerServer(CentralLogger).log(Level, String) line: 449    
CentralLogger.lambda$logStream$0(String, Level, InputStream, Supplier, Level) line: 198    
2012232625.run() line: not available    
Thread.run() line: 750 [local variables unavailable]    

Hard to spot unless you have breakpoints in java.lang.NullPointerException constructors, which I keep by default :) The exception is ignored, but I think we need to show it:

                       try
                       {
                          while (scanner.hasNextLine())
                          {
                             String line = scanner.nextLine();
                             Level level = recordLevel;
                             if (level == null)
                             {
                                // set default of SEVERE just in case an important msg hasn't been 
                                // transformed to the format
                                level = parseRecordLevel(line).orElse(Level.SEVERE);
                                line = line.replaceFirst(level.getName() + ": ", "");
                             }
                             streamLogger.log(level, line);
                          }
                          TimeUnit.SECONDS.sleep(1);
                       }
                       catch (Exception ignored)
                       {
                          // ignored.
                       }

Constantin Asofiei wrote:

Hard to spot unless you have breakpoints in java.lang.NullPointerException constructors, which I keep by default :) The exception is ignored, but I think we need to show it:
[...]

It's complicated with errors in the logger itself. If it's client it should not print on the console, but it should be fine on the server side. I haven't tested it without configs. I'll fix this too.

Fix for the NPE in r14508. The breakpoint in the NPE class helped. By the way the default location for the log file is the workingDir and if not defined, the server launch dir.

• the logger service runs in its own thread(s), as I see; please name these threads so they can be easily identified in a thread dump or in debugger.
• the logger service threads need to be daemon threads - otherwise the JVM will not terminate when the main thread terminates. See for example the NativeSecureConnection call - that JVM never terminates, and the launch thus never completes.
• there are logging messages added to /opt/spawner, like client_crash_2023-03-06_11-35-30_EET.log - are these from NativeSecureConnection? For NativeSecureConnection, the default logging should be STDOUT/STDERR.

Actually there are several threads related to logging, but the loggers themselves are not on separate threads. The threads are logging System.err streams - one of them is going to be removed, when I replace all System.err occurrences in the code. The other one is logging System.err from the spawner process. These die with the JVM, although they are not daemon threads. They depend on Supplier<Boolean> isProcessRunning which is explicitly set to false on the client and the server. I will add names to the threads according to the logger that uses them.

The crash log files are saving any leftover logs, when the CentralLoggerClient hasn't been able to send them to the server due to some malfunctioning. Since I got blocked with debugging NativeSecureConnection, it might be that it works for you and that's what gets generated. It's expected though that NativeSecureConnection operates as client and send the logs to the server.

• NIO sockets are dead-locking, as you mentioned before.
• without NIO sockets, the NativeSecureConnection doesn't terminate - there must be a bug in CentralLoggerClient.finish();, as the logger thread is not terminated when the command() method finishes. If I make that thread a daemon thread, then NativeSecureConnection terminates and the appserver starts.

• this part blocks for a response from the server:
  

  Unsafe.park(boolean, long) line: not available [native method]    
  LockSupport.parkNanos(Object, long) line: 215    
  AbstractQueuedSynchronizer$ConditionObject.awaitNanos(long) line: 2078    
  LinkedBlockingQueue<E>.poll(long, TimeUnit) line: 467    
  NIOSslSocket.readFully() line: 272    
  NIOSslSocket(NIONetSocketBase).readInt() line: 263    
  LoggingNetSocket.readInt() line: 244    
  SecurityManager.authenticateClientWorker(NetSocket, BootstrapConfig) line: 2172    
  SecurityManager.authenticateClient(NetSocket, BootstrapConfig) line: 2088    
  

  
  where SecurityManager.authenticateClient(NetSocket, BootstrapConfig) line: 2088 locks on SecurityManager.class
• the nioSslTaskWorker thread wants to lock on SecurityManager.class , but it can't:
  

  SecurityManager.getInstance() line: 847    
  CentralLogger$LogFormatter.describeContext() line: 640    
  CentralLoggerClient(CentralLogger).log(Level, String, String, String, Throwable, Object...) line: 553    
  CentralLoggerClient(CentralLogger).log(Level, String) line: 451    
  NIOSslSocket$3(BlockingSSL).processInput() line: 229    
  NIOSslSocket$3(BlockingSSL).checkInput() line: 114    
  NIOSslSocket.lambda$new$1(SocketChannel, CountDownLatch, SSLEngine) line: 177    
  1654589030.run() line: not available    
  ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: 1149    
  ThreadPoolExecutor$Worker.run() line: 624    
  Thread.run() line: 750    
  

  
  where SecurityManager.getInstance() is:
  

     public static synchronized SecurityManager getInstance()
     {
        return securityManager;
     }
  

FWD server side properly sends this data:

               // send the AUTHMODEREQ packet to the client
               try
               {
                  // send the packet
                  socket.writeInt(authModeReq);
                  socket.writeInt(authAction);
                  socket.flush();
               }

Oops, there is one return to be removed in finish that prevents the flag IS_LOGGER_WORK_FINISHED to be set to true and there appears again the deadlock from the rpc to the server logging logs about its logs... that is solved by the flag. Not valid.

Constantin, sorry for the time taken. I was pretty sure this was handled already, but the new case came with the unexpected exception, return where there should not be and revealed this.

Galya Bogdanova wrote:

Constantin, sorry for the time taken.

No problem. Please remove the NIOSslSocket-no-more-indefinite-loops.diff changes from 5703a, once you fix the deadlock.

We are deprecating this - Greg, if we introduce other jar dependencies to p2jpl.jar, then this will break fast. I'm OK with breaking it if we are going to deprecate and not support PL/Java at all.

Is there a requirement to add new dependencies as part of this task or is this just a general statement?

Otherwise, the standalone tool list (and build scripts) still work with the full p2j.jar, and any other jar dependencies required. The problem here: any added logging should default to STDOUT, as the tools are meant to be interactive.

Over the coming months we will be reworking our conversion process and add IDE support to meet several critical requirements. At that time I plan to move all tools to a model where the logging is captured in an architected manner and we include enough additional data that it can used for things like a failure report in an IDE which can be linked back to a given line and column in the source code. I agree that as a fall back, STDOUT is a good choice. We just need to remember that ultimately, we will move even these tools to a managed approach.

Greg Shah wrote:

We are deprecating this - Greg, if we introduce other jar dependencies to p2jpl.jar, then this will break fast. I'm OK with breaking it if we are going to deprecate and not support PL/Java at all.

Is there a requirement to add new dependencies as part of this task or is this just a general statement?

This is a general statement - depending what parts p2jpl.jar reach the new logging approach, PL/Java may not work with just loading p2jpl.jar; at least, we will need the new logger classes added to p2jpl.jar. But I think otherwise we are using Java logging, which is available with no 3rd-party depenency? If so, it may just be a matter to ensure that if there is nothing configured, the logger defaults to STDOUT/STDERR and it should work.

The new logger is very simplified and has no external dependencies. I even removed the dependency on java.util.logging.Logger and java.util.logging.LogManager and left only java.util.logging.FileHandler and java.util.logging.LogRecord. I'll elaborate more on that decision if you want. The only concern will be if the new logger classes are not in the classpath, which it seems might be the case for p2jpl.jar. I'll need time to go through the details about entry points provided by Constantin.

Constantin, please check if I got it right:

• ReportWebServer - I saw it has p2j.jar in the classpath in deploy/server/report.sh, so I think it's safe to use the new logger for that deployment. It will print to stdout;
• Conversion - The fwd_deploy-convert zip seems to have the p2j dir in src, so I think it's safe here too. Printing to stdout;
• Server/Client - These classes should have p2j.jar in classpath, but I'm curious how the main methods are called. Are they processes in separate JVMs? It might interfere with the logger mode - basically printing on stdout instead of redirecting to the server. If there are separate JVMs started programmatically runtime and we can identify the entry points that will do.
• Standalone testing - some classes have dependencies on other p2j classes, that have the new logger. I'll leave the entry classes as they are and the dependencies will print to stdout with the default behavior of the logger. But these might stay amidst the code as exceptions to the rule of using only the logger.
• Build scripts - both classes seem to have dependency on the new logger, using shared classes. I guess they should be used with p2j.jar again?
• p2jpl.jar includes com/goldencode/p2j/util/* already, while the new classes are under com/goldencode/p2j/util/logging. We can add the sub-package as well. I will double check if there are any other dependencies not included in the loggers and let you know.

Galya Bogdanova wrote:

Constantin, please check if I got it right:

• ReportWebServer - I saw it has p2j.jar in the classpath in deploy/server/report.sh, so I think it's safe to use the new logger for that deployment. It will print to stdout;

Agreed.

• Conversion - The fwd_deploy-convert zip seems to have the p2j dir in src, so I think it's safe here too. Printing to stdout;

Agreed.

• Server/Client - These classes should have p2j.jar in classpath, but I'm curious how the main methods are called. Are they processes in separate JVMs?

p2j.jar is used by both server and client - we don't split the logic in different jars. The main classes com.goldencode.p2j.main.ServerDriver and com.goldencode.p2j.main.ClientDriver.

• Standalone testing - some classes have dependencies on other p2j classes, that have the new logger. I'll leave the entry classes as they are and the dependencies will print to stdout with the default behavior of the logger. But these might stay amidst the code as exceptions to the rule of using only the logger.

Agreed.

• Build scripts - both classes seem to have dependency on the new logger, using shared classes. I guess they should be used with p2j.jar again?

The classes used by build scripts will have p2j.jar.

• p2jpl.jar includes com/goldencode/p2j/util/* already, while the new classes are under com/goldencode/p2j/util/logging. We can add the sub-package as well. I will double check if there are any other dependencies not included in the loggers and let you know.

Make sure the logging defaults to stdout.

Something else which I forgot: there are FWD classes used externally by customer applications, for i.e. FWD Java OpenClient calls. The entry points are the LegacyJavaAppserver*.java and they all reach DataSetSDOHelper and AppServerHelper. In all these cases, there is no directory.xml to configure the FWD loggers - they need to default to STDOUT and let any application-specific logger do its work.

I think your only concern is the ClientDriver (which starts the FWD client), where the logging as far as I understand needs to be redirected to the FWD server - Greg, this is correct, right, there will be no more FWD client-side logs?

I think your only concern is the ClientDriver (which starts the FWD client), where the logging as far as I understand needs to be redirected to the FWD server - Greg, this is correct, right, there will be no more FWD client-side logs?

Not always. There are 2 cases here:

• client-side logging is being used
  • should be the default because this is the OE compatible approach
  • in this case the logs are not forwarded to the server and they are written at the client the way OE would do it
  • server-generated log output is sent to the client for output
• server-side logging is configured
  • this would be configured similar to the rest of #4065
  • client-generated output is forwarded to the server
  • this is not compatible with the OE approach but for the majority of output it is likely the fastest approach so we want to use this when possible

Greg, for appservers, there is a single log file where all agents of that appserver are adding the messages. Currently we log (some) of the messages in the client-side log (one per agent), which is doesn't look right.

for appservers, there is a single log file where all agents of that appserver are adding the messages

This sounds vaguely familiar. This is how it works in OE?

Currently we log (some) of the messages in the client-side log (one per agent), which is doesn't look right.

I do recall some customers saying that our per-agent logging was useful in that they could easily match output with a specific agent. But perhaps I am mis-remembering. Surely a common appserver log would at least identify all output by agent.

We definitely need to have a compatible implementation. If indeed it is somehow useful to split things up by agent, then we would want to allow that to be configured and we would want all output to go to the agent log, not just some.

Greg Shah wrote:

for appservers, there is a single log file where all agents of that appserver are adding the messages

This sounds vaguely familiar. This is how it works in OE?

Yes, this is how it works in OE.

I do recall some customers saying that our per-agent logging was useful in that they could easily match output with a specific agent. But perhaps I am mis-remembering. Surely a common appserver log would at least identify all output by agent.

The OE appserver logs do identify the agent in the message log, so if we use a common log file, we will need this, too. What I found difficult with the current way is that each agent creates its own file, and when restarting the FWD server a lot, the log files add up. And the same happens when the agents are trimmed and/or restarted, the log files will add up.

If indeed it is somehow useful to split things up by agent, then we would want to allow that to be configured and we would want all output to go to the agent log, not just some.

I agree.

For now, let's just focus on the single common log per appserver with the properly formatted headers. I thought we had a customer bug report about this, but I can't find it.

About the client/server entry points - ClientDriver is the only one that will trigger client mode and ServerDriver is the only one starting server mode of the logger at the moment. Client and server modes expect configs to be read from client.xml / directory.xml. Although there are defaults and it can work without any actual configs, the call to the method for setting configs is the logger initialization that makes a huge difference. Before configs kick in loggers cannot decide what logs are eligible for saving (based on the logging level), so that's the pre-init phase, where everything is saved in-memory. And reading configs can't be the first statement in a driver (not to mention the class loaders start producing logs even before the main method call). So marking the process as running in client/server mode makes the logger wait for initialization. If initialization doesn't happen, logs will be stored in-memory indefinitely which you can imagine how bad could be.

We can mark other entry points (JVMs) as servers/clients and then we should also call the initialization, so I need to know exactly what these entries are. For clients, there is even more to it: state sync. If a process is marked to run client logger, it needs to use the state sync of ThinClient.getChanges() -> Protocol.applyChanges(). If that is not supported in the client, it will also store the logs in-memory indefinitely.

The default mode flushes everything directly to stdout, no in-memory.

Now back to the entry classes for client / server: There are a lot in the list, but I know how only two of them are used. If the other can be started as separate JVMs, they will use the default mode as it is now. So if there are separate JVMs, we need to identify them and make sure to set the appropriate logger mode.

Also let's keep OE logging and FWD logging as separate topics. OE logging is #3853 that waits for review. I've noticed broker/agent logs are separate from the main OE logs and they have an honorable mention in Appserver Logs, but I haven't looked into it very much. I think we should deal with it after merging #5703 and what is done in #3853, since broker/agent logs seem to share a lot with #3853.

I updated the wiki Logs to help us better distinguish between different logs in OE and FWD, current and future state. Please feel free to add any info that might be useful.

I also added a line in FWD Framework Future State to explain the future state of slf4j. I'm removing the implementations (slf4j-simple and slf4j-jdk14) from build dependencies and creating a custom simple binding that will forward 3rd party logs using slf4j to CentralLogger. That will provide consistent formatting of the output of libs like com.mchange, org.reflections, gwt-validation and jetty.

Now that we've decided that the new logger can be used pretty much everywhere, what do we do with the ignored classes. Can I have the permission to update them?

src/com/goldencode/p2j/e4gl/E4GLLexer.java
src/com/goldencode/p2j/e4gl/E4GLParser.java
src/com/goldencode/p2j/e4gl/E4GLParserTokenTypes.java
src/com/goldencode/p2j/persist/hql/HQLLexer.java
src/com/goldencode/p2j/persist/hql/HQLParser.java
src/com/goldencode/p2j/persist/hql/HQLParserTokenTypes.java
src/com/goldencode/expr/ExpressionLexer.java
src/com/goldencode/expr/ExpressionParser.java
src/com/goldencode/expr/ExpressionParserTokenTypes.java
src/com/goldencode/p2j/preproc/BracesLexer.java
src/com/goldencode/p2j/preproc/BracesParser.java
src/com/goldencode/p2j/preproc/TextLexer.java
src/com/goldencode/p2j/preproc/TextParser.java
src/com/goldencode/p2j/preproc/PreprocTokenTypes.java
src/com/goldencode/p2j/schema/SchemaParser.java
src/com/goldencode/p2j/schema/SchemaParserTokenTypes.java
src/com/goldencode/p2j/uast/ProgressLexer.java
src/com/goldencode/p2j/uast/ProgressParser.java
src/com/goldencode/p2j/uast/ProgressParserTokenTypes.java
src/com/goldencode/p2j/uast/ExpressionEvaluator.java
src/com/goldencode/p2j/uast/ExpressionEvaluatorTokenTypes.java
src/com/goldencode/p2j/persist/orm/FQLLexer.java
src/com/goldencode/p2j/persist/orm/FQLParser.java
src/com/goldencode/p2j/persist/orm/FQLParserTokenTypes.java

Otherwise the configured log files might be missing logs.

Galya, these classes are generated by ANTLR - the changes need to be in their .g part (text.g, fql.g, progress.g, etc).

Yes, you can make changes to the ANTLR code but please post an example here first and we will review before you go too far in a wrong direction.

Also, it is important that you have your branch rebased to the latest trunk as there are many parsing changes. We don't want your work to be harder to merge later.

Thank you for the responses. Then I'll leave it for later and will post an example before starting.

com.goldencode.p2j.preproc.Preprocessor supports cmd line options for writing out, err and warn to separate files. We've marked the class as part of the client / server deployment. Can you tell me more about it and do we keep these separate files? If yes, I need to add some info to the wiki.

P.S. It is used also in SchemaLoader, AstGenerator and ProgressParser.

Also ext/sheet/build.gradle uses compile time the fwd build folder ../../build/classes, so I guess p2j.jar is in the classpath runtime. Why is this directory then separately deployed?

About the interactive tools - I've marked in the table the classes using System.in, but there might be more. System.err reworked to the new logger will print messages in a different format and that may be a problem if they get mixed. I'll have to verify the end result of refactoring later, especially for the interactive tools.

There is a problem: There are 100 entry points in the code. Most of them have System.out and System.err. If System.err is replaced by calls to CentralLogger they will be formatted differently than the System.out prints. The logger format is a little heavy with all the details (date, context - where the log comes from). On the other side if there are dependencies on other classes that have CentralLogger output, that will also lead to different formats. I don't like the options here:

A. Replace everything (System.err, System.out) with the new logger, but then all the output will be heavy with all kinds of info that makes it difficult to read on the console.
B. Try to identify interactive tools and don't replace their output, but if there are any dependencies, output formatting might be mixed.
C. Replace everything (System.err, System.out) with the new logger and create a new formatter for the default logger mode that has very little info except the msg itself, but it will not be a real log then.

I really want to move all Harness tests (only the main methods) out of the source code into the test dir. Can we do that?

Do we need exceptions in the GWT front-end of admin/client saved in the central log file or leave them show up only in the web / js console?

Attention! ⚠ Replacing System.err in the project will affect the content of the -err and -warn log files generated by Preprocessor execution. This further affects AstGenerator, passing down to Preprocessor Configuration.getParameter(ERR_DEST_KEY) as err log destination. I can't assess what's the damage of having the two streams merged into -out, but that is the result of having the default logger in the place of System.err writes. Each log record will have its level printed out, so no information will be lost, but it will all go to System.out. Can we do that and discard the -err, -warn, Configuration.getParameter(ERR_DEST_KEY), Configuration.getParameter(WARN_DEST_KEY) args?

Galya Bogdanova wrote:

com.goldencode.p2j.preproc.Preprocessor supports cmd line options for writing out, err and warn to separate files. We've marked the class as part of the client / server deployment. Can you tell me more about it and do we keep these separate files? If yes, I need to add some info to the wiki.

P.S. It is used also in SchemaLoader, AstGenerator and ProgressParser.

As noted in #7180, we plan to implement an abstract API for recording logging output and results of the conversion run, including any logging done by these classes.

We have no 4GL compatibility requirements here. Separating out the warnings is a useful thing. Separating out from err probably is not needed. The idea behind the API is that it would be the "one ring to rule them all" for logging/errors/status in conversion tooling.

Please note that the conversion output for running the tools outside of runtime is the more important case. The runtime case (which is really what matters for this task) is really a kind of special case that is only used for dynamic temp-tables and dynamic queries.

Galya Bogdanova wrote:

Also ext/sheet/build.gradle uses compile time the fwd build folder ../../build/classes, so I guess p2j.jar is in the classpath runtime. Why is this directory then separately deployed?

We have to keep the spreadsheet code separated for licensing reasons.

Greg Shah wrote:

Please note that the conversion output for running the tools outside of runtime is the more important case. The runtime case (which is really what matters for this task) is really a kind of special case that is only used for dynamic temp-tables and dynamic queries.

Who can divide the conversion code for runtime from the tools for me, so that I know what I'm changing?

Galya Bogdanova wrote:

About the interactive tools - I've marked in the table the classes using System.in, but there might be more. System.err reworked to the new logger will print messages in a different format and that may be a problem if they get mixed. I'll have to verify the end result of refactoring later, especially for the interactive tools.

In case there is any question, all System.in cases are either command line utilities (not runtime code) OR they are test harnesses (also not runtime code).

If runtime conversion and tools conversion don't share any classes, then minding my own refactoring will be easy. Otherwise the output of the tools will be inevitably affected.

Do we need exceptions in the GWT front-end of admin/client saved in the central log file or leave them show up only in the web / js console?

These can be in the browser instead of our central log file.

Galya Bogdanova wrote:

If runtime conversion and tools conversion don't share any classes, then minding my own refactoring will be easy. Otherwise the output of the tools will be inevitably affected.

It is completely common code.

Greg Shah wrote:

It is completely common code.

Then my changes - replacing System.err will change the output in both runtime and conversion. While runtime will run in the server mode of the logger and logs will be saved to the file, running the tools will lead to System.err going to System.out (the default mode of the logger).

I think we should implement a version of the #7180 API and switch all the conversion-tooling to use it. We can install a runtime version of the backing implementation which uses CentralLogger and a conversion time version of the implementation which outputs to System.err or the warning log in a compatible way with the current code. I don't think we need to separate out and err.

We can mark the tools entry points to run CentralLogger with a new mode that writes to the API and we'll have to replace System.out as well.

I guess the API will be backed by a new DB table?

I prefer that the API be the main entry point for the tooling and CentralLogger only used in one implementation of the interface. The conversion tooling should not know about CentralLogger.

Galya Bogdanova wrote:

I guess the API will be backed by a new DB table?

Not at this time. For now, the conversion-time implementation can just duplicate the current output.

Greg Shah wrote:

I prefer that the API be the main entry point for the tooling and CentralLogger only used in one implementation of the interface. The conversion tooling should not know about CentralLogger.

But that's the issue, it already does, since being called runtime is expected to save logs to the server log, right?

I'm not able to determine in depth which files are part only of the conversion tool and which are shared with other runtime executed classes like Configuration, so at the end of the day there will be logger references in the tools classes.

But that's the issue, it already does,

What do you mean by "it already does"? In your changes?

since being called runtime is expected to save logs to the server log, right?

This would happen by plugging in a different implementation of the API at runtime (the one that calls CentralLogger) from the one that is used at conversion time (which just outputs to System.err directly).

Galya Bogdanova wrote:

I'm not able to determine in depth which files are part only of the conversion tool and which are shared with other runtime executed classes like Configuration, so at the end of the day there will be logger references in the tools classes.

Anything that ever gets used at conversion time would use this API instead of direct usage of CentralLogger.

Greg Shah wrote:

Anything that ever gets used at conversion time would use this API instead of direct usage of CentralLogger.

I don't really see the benefit of another logger on top of the one pretty much complete, that supports different modes determined runtime.
Also I don't think I'm able to cut out the all dependencies.

The API is not really about logging. It is about recording the details of the conversion/tools processing in a manner that can be accessed in multiple ways. Think about the case of IDE integration which needs to show a list of errors and link back to the location of the problem.

The CentralLogger is not that.

Greg Shah wrote:

Think about the case of IDE integration which needs to show a list of errors and link back to the location of the problem.

How do you integrate the IDE with an API to find the stacktrace source?

CentralLogger is just an interface. Its various implementations may or may not have anything in common.
As far as I understand CentralLogger will have to share the interface with the new API caller class which sounds to me pretty much the same.

Think about the case of IDE integration which needs to show a list of errors and link back to the location of the problem.

How do you integrate the IDE with an API to find the stacktrace source?

The IDE will not use the reporting API, it will be using a different interface to access the data and to get event notifications.

As far as I understand CentralLogger will have to share the interface with the new API caller class which sounds to me pretty much the same.

No, I don't think so. The two APIs may look similar now but they will not look that way later.

Greg Shah wrote:

No, I don't think so. The two APIs may look similar now but they will not look that way later.

Since I need to implement it now, how do I make it look?

Use the minimum necessary to replace the current calls.

The interface and implementations should live inside com.goldencode.p2j.convert.

Call it Status.

Preprocessor is not in com.goldencode.p2j.convert. So let me get back to my initial question.

Greg Shah wrote:

Anything that ever gets used at conversion time

needs a definition.

So I guess I need to:

1. Get Constantin's exhaustive list of conversion tools that are in different directories:

/src/com/goldencode/util/DatabaseDumpChecker.java 
/src/com/goldencode/p2j/report/ReportDriver.java 
/src/com/goldencode/p2j/util/FileSpecList.java 
/src/com/goldencode/p2j/util/ExplicitFileList.java 
/src/com/goldencode/p2j/uast/CallGraphGenerator.java 
/src/com/goldencode/p2j/uast/ScanDriver.java 
/src/com/goldencode/p2j/uast/JavaSymbolResolver.java 
/src/com/goldencode/p2j/convert/ProgressTransformDriver.java 
/src/com/goldencode/p2j/convert/GenerateWsdl.java 
/src/com/goldencode/p2j/convert/ConversionDriver.java 
/src/com/goldencode/p2j/schema/RelationAnalyzer.java 
/src/com/goldencode/p2j/e4gl/E4GLPreprocessor.java 
/src/com/goldencode/p2j/e4gl/E4GLLexer.java

2. Find somehow (hopefully gradle will work out) all their dependencies on other com.goldencode classes.
3. Replace all private static final CentralLogger LOG = CentralLogger.get(.class); with com.goldencode.p2j.convert.StatusImpl = StatusImpl.get(.class) (which already doesn't sound right).
4. Then replicate the CentralLogger interface in Status.
5. Implement the interface in StatusImpl making it reroute to CentralLogger.

Does it sound correct?

Anything in these directories is conversion or dev tool related:

src/com/goldencode/p2j/convert/
src/com/goldencode/p2j/e4gl/
src/com/goldencode/p2j/pattern/
src/com/goldencode/p2j/preproc/
src/com/goldencode/p2j/report/
src/com/goldencode/p2j/uast/
src/com/goldencode/p2j/schema/

Replace all private static final CentralLogger LOG = CentralLogger.get(.class); with com.goldencode.p2j.convert.StatusImpl = StatusImpl.get(.class) (which already doesn't sound right).

No. Implement a Configuration.getStatus() method that returns the Status instance. It should hide the runtime vs devtime decision from the caller. I'm not sure we even need the per-class concept but we can leave it for now.

Then replicate the CentralLogger interface in Status.

CentralLogger has lots of implementation we don't need for a simple status API. Keep the Status API to a minimum.

Greg Shah wrote:

It should hide the runtime vs devtime decision from the caller.

Are the two distinguishable? Is there a difference in calling the main method?

It should hide the runtime vs devtime decision from the caller.

Are the two distinguishable? Is there a difference in calling the main method?

The Configuration class will know the difference and provide back the correct implementation class for Status. The caller doesn't need to care.

Replace all CentralLogger references only in the seven conversion / tool directories and don't care about dependencies.

This one.

This Status, API, IDE thing - isn't it like any cloud logging + IDE plugin? Any cloud logging has an API and a Java library to send requests. For google cloud logging for example all the complexity is hidden behind simple java.util.logging.Handler - link. Simplicity can help a great deal in maintaining the source. Also that way I won't have to rename CentralLogger to SideLogger.

This Status, API, IDE thing - isn't it like any cloud logging + IDE plugin? Any cloud logging has an API and a Java library to send requests. For google cloud logging for example all the complexity is hidden behind simple java.util.logging.Handler - link.

No, this isn't really about logging. For the dev tools side of the project, it is more like we have a live list of the problems that have occurred and it is more than just text output.

Simplicity can help a great deal in maintaining the source.

I strongly agree. But simplicity that doesn't meet the design needs is not a good idea.

Also that way I won't have to rename CentralLogger to SideLogger.

I don't see why this is needed regardless of the approach.

Greg Shah wrote:

Also that way I won't have to rename CentralLogger to SideLogger.

I don't see why this is needed regardless of the approach.

I was kidding. :) Thanks for the explanation. I had to make sure we're not reinventing the wheel.

Constantin, you asked before about the appserver/broker logs and what is happening with them.

With #5753 there will be no change. With this task #5703 the change would be as follows:
- up till now each broker client produced a log with System.err redirected which wasn't compliant with OE output;
- from now on all client System.err logs go to the central server log. That is not the OE behavior, so I'm suggesting to leave it to #3853 to generate those separate files based on the base LOG-MANAGER implementation #5753. Broker log content also needs to be replicated from OE 1:1 which it's not currently.

Also that way I won't have to rename CentralLogger to SideLogger.

I don't see why this is needed regardless of the approach.

I was kidding. :)

Nice. I was hoping so but there was no smiley so I didn't want to presume. ;)

Galya Bogdanova wrote:

Broker log content also needs to be replicated from OE 1:1 which it's not currently.

Please describe what broker log content you refer to. You mean the case when the appservers are started on another machine (remotely) via a FWD Broker?

Constantin Asofiei wrote:

Please describe what broker log content you refer to. You mean the case when the appservers are started on another machine (remotely) via a FWD Broker?

I presumed the broker is an appserver broker, but now that you're asking it should be the remote launch. Actually the OE appserver broker is like load balancer and I think FWD doesn't have that, right?

Correct, FWD doesn't have a broker in OE terms. The broker is used only for remote launching; Greg, I think any log messages generated by it should be dispatched to the server log.

Constantin Asofiei wrote:

Correct, FWD doesn't have a broker in OE terms. The broker is used only for remote launching; Greg, I think any log messages generated by it should be dispatched to the server log.

This seems reasonable.

• SERVER, Session:00000007, Thread:0000001F, User:bogus
  • I assume this is from the FWD Server JVM
  • Thread - can we specify the thread name here, too? Like Conversation, Reader, Writer, etc. This indicates what thread wrote this message.
  • Session - this is the FWD client session ID on the FWD Server JVM, correct?
• CLIENT pid:167348, Thread:main
  • I assume these are incoming from the FWD Client JVM
  • pid doesn't get us much. I think we need standardize this and get the same data as for the FWD server messages, like CLIENT, Session:...., Thread:...., User:..., pid:. This allows us to match the log message with a user session.
• there is SERVER, Session:00000007, Thread:0000001F, User:bogus and CLIENT pid:167732, Thread:main - I think we need a comma after CLIENT to be in sync with the SERVER, message
• with this task, the FWD Client's diagnostic info will be written to the common log (which includes FWD Server and all FWD Clients). I assume this is expected, as all FWD Client logging is redirected to the FWD Server.
  

  23/03/23 16:26:26.325+0200 | INFO    | com.goldencode.p2j.main.ClientCore | CLIENT pid:167348, Thread:main | ClientDriver: 38 arguments =
     [
        'server:spawner:uuid=12093503-d5ad-412c-8f66-a5599ba143dc',
        ....
     ]
     Product Version FWD v4.0.0_p2j_5703a_14521
     JVM Version 1.8.0_362
     JVM Memory: free = 291319048; total = 355467264; max = 3693084672;
     JVM Available CPUs: 12
     JVM Properties =
     ...
  

The Session/Thread/User combo context came as ported from LogHelper where it was used only for some logs. I tried to use it for all logs, but there are some constraints - the details come from SessionManager and require SecurityManager.getInstance() to return an instance and SecurityManager.initialized() and sm.hasContext() to be true, which is not the case for some logs. Also these methods are synchronized and it leads in some cases to dead locks, so for example if NIOSslSocket is in the stacktrace, this context is not applied (that's the deadlock case Contantin helped me figure out).

The client pid could be used as a link between the FWD logs and the LOG-MANAGER client logs (that have pid for each log record). Also it the only unique identifier I could think of to differentiate between clients of the same type. Let's say there are two standalone batch client running at the same time. Their logs will be all mingled in the mix.

There are changes in 486 files and more to come. Am I expected to update all file headers?

Galya Bogdanova wrote:

There are changes in 486 files and more to come. Am I expected to update all file headers?

There is a script named gen_headers.py in ~/usrbin, as part of the standard dev setup - details how to use it are at User_Account_Configuration_Reference, look for gen_headers.py in the wiki.

I haven't use it in a while, but I didn't have 100s of files changed at once... please try out this tool (make copies of the project before running it) and let Hynek know if you have any questions/problems (he wrote the tool).

Constantin Asofiei wrote:

There is a script named gen_headers.py in ~/usrbin, as part of the standard dev setup - details how to use it are at User_Account_Configuration_Reference, look for gen_headers.py in the wiki.

I'll try it, thanks.

Does someone know why is this dependency in build.gradle: fwdConvertServer group: 'org.jboss.logging', name: 'jboss-logging', version: '3.1.0.GA'. There is no import in the code.

Galya Bogdanova wrote:

Does someone know why is this dependency in build.gradle: fwdConvertServer group: 'org.jboss.logging', name: 'jboss-logging', version: '3.1.0.GA'. There is no import in the code.

From the wiki, this looks like it was a dependency on Hibernate (which was removed).

Roger, I can't find the build dependency tree for all the jar libraries - is this somewhere in the wiki?

fwdspi.jar doesn't include the logging classes and FwdCollatorProvider fails runtime. I'm not sure how/when the class is called, but I guess it will be fine to be left without logger.

Constantin Asofiei wrote:

Roger, I can't find the build dependency tree for all the jar libraries - is this somewhere in the wiki?

Did you run ./gradlew generateLicenseReport then look in ./build/reports? Is that what you are looking for? How about ./gradlew dependencies?

Roger Borrello wrote:

How about ./gradlew dependencies?

Thanks, I see only root references for +--- org.jboss.logging:jboss-logging:3.1.0.GA I think it can be removed from build.gradle.

I will run the dependency tree generation and confirm my statement that no class is explicitly imported, but I'm asking, because some dependencies like slf4j implementation are runtime used without imports and I'm not sure how jboss is used.

It should be though that it's not in use any more. I'll remove it.

Branch 5703a, r14573 is ready for a pre-final code review. There are still no file headers and I need to go through all the changes in the 499 files again to look for any small mistakes, so at this point the code review is for the reviewer to get familiar with what has been done, not so much to focus on small issues.

To see the changes do: bzr diff -r-51.

The major classes for review are in com.goldencode.p2j.util.logging.

If testing make sure to change directory.xml configs, remove the "logging" container and add a new one like the one here.

• cmd line args -err, -warn in com.goldencode.p2j.preproc.Preprocessor;
• com.goldencode.p2j.preproc.Configuration.getParameter(ERR_DEST_KEY) and Configuration.getParameter(WARN_DEST_KEY) in AstGenerator;
• com.goldencode.p2j.preproc.Environment methods getErr, getWarn, eprint, print
• com.goldencode.p2j.util.ScopedDictionary.dump

They will not be reworked with the current task and may still produce some output in server.log in runtime.

Does 5703a depend on any work from 5753d?

Constantin Asofiei wrote:

Does 5703a depend on any work from 5753d?

No

At the moment there are two base log levels to be configured - one for the spawner messages and one for everything else. These can be further changed programmatically by creating a logger for a package and setting a level to it. It will take immediate effect on all child packages and classes.

In the old internal logging approach in FWD, we could configure logging at any class or package level. Most of the logger instances were made at the class level so this worked well. It gave a large amount of granularity of control (e.g. enabling detailed logging for only a small number of classes). Are you saying that this is being removed and replaced with 2 levels of control?

The included files is how the naming works. The prefix log-name is the only configurable part of the name. The date time part is the only readable sortable option without whitespaces. I included the .lck file on purpose, because Java logger (file handler) locks the number 0 file and uses it all the time for the latest logs while the last file has actually the first logs generated. It's very unintuitive in my opinion, that's why I've described it in Logs.

The old approach give 100% control to the admin since the STDIO of the process could be redirected to anything. In the new approach, we certainly do need to control (or have the ability to control) the numbering for the generations of logs. But other than that we should not define the log file location or naming pattern. That control must stay with the admin that is implementing the server.

I think we need a "substitutions" approach (similar to what is being done in #5753) for the naming here.

• The admin would specify a "spec" that would include zero or more % placeholders which we will substitute whenever we create a log filename.
• The spec itself will allow any static portions of the name to be completely controlled by the admin.
• I think in general we should provide strong control to the admin to format the substitutions as they like. For example, people have very different ideas about how date and time values should be formatted. Why do we care to interfere with the admin on that? Numeric values are another example where there may be some variation in how admins what things done. I don't want to re-invent the wheel. I'd like to reuse the converter specs from https://docs.oracle.com/javase/8/docs/api/java/util/Formatter.html where possible.
• If the spec is not provided, we should have a sensible default.
• Substitutions should include:
  • date/time values
  • server name
  • log generation number
  • pid
• If the log generation spec is not provided, we will have to augment the spec with a default for that.
• The log generation spec should also be flexible and follow the Formatter conventions. For example, many admins would want there to be zero-padded generation numbers so that the filenames will naturally sort in numeric order.

About the format of the messages themselves I went back and forward many times and this is what I ended up with. Date time format is taken from the original OE logs for the sake of consistency with LOG-MANAGER implementation. Only the clutter is removed - @ between date and time and side brackets. The divider between sections is | as in log4j which is a common Java log format. After the class name (logger name) that's the context description - shows if it's a log generated on the server or on the client, adds client pid if native layer is initialized, adds thread name or SecurityManager details (user, session).

As with the log filenames, we also need to provide flexibility in the format of the logging.

• The approach will be the same: allow the admin to specify a formatting spec that honors a set of substitutions PLUS provide a sensible default.
• There should be two default specs.
  • Legacy spec for LOG-MANAGER output which should be completely compatible with the 4GL spec. This will make it easy for customers to migrate any pre-existing log analysis processing for OE. I know you "cleaned things up" but I think it must match 100% (or as much as we can reasonably match).
  • FWD spec for our internal logging. I think the default here should also be close to the 4GL spec by default but we would probably output things like the class name instead of the 4GL entry-type.
• Use the Formatter conversions as much as possible and add consistent formatting options for special substitutions like pid, tid or context. This means names get formatted using the same options as strings, numerics get formatted with the same options as numbers.
• Substitutions should include:
  • date/time
  • server pid
  • client pid
  • session ID
  • thread ID
  • userid
  • class name (base name only)
  • class name (fully qualified)
  • logging level (Java)
  • logging level (4GL)
  • entry type (4GL)
  • message
• One tricky part of this is what to do when a value doesn't exist. For example, if we are logging on a server-only context (no client process), then how do we cleanly render logging of client-specific pid?

with this task, the FWD Client's diagnostic info will be written to the common log (which includes FWD Server and all FWD Clients). I assume this is expected, as all FWD Client logging is redirected to the FWD Server.

If clientLog is specified, then won't we output everything to that log?

This points out that we really do need to set a default here for our FWD-specific output. I don't want that co-mingled in the server log by default. Customers see a stderr log today for every client and I think we need to retain something similar by implementing a default FWD client log file if clientLog is not specified.

Greg Shah wrote:

In the old internal logging approach in FWD, we could configure logging at any class or package level.

It will be added. I was waiting for feedback on this matter. Anyways the format of the configs will be more flexible, so it should be reimplemented.

The old approach give 100% control to the admin since the STDIO of the process could be redirected to anything. In the new approach, we certainly do need to control (or have the ability to control) the numbering for the generations of logs. But other than that we should not define the log file location or naming pattern. That control must stay with the admin that is implementing the server.

There is this dir config (logging:file:dir) you might have noticed that allows you to choose the location. The old approach gave you server.log without any placeholders that got overwritten by mistake. There is also the logging:file:namePrefix config in the new approach. I've added hardcoded datetime, rotation number and .log extension, thinking that framework can allow itself to that invasive. Removing is easy.

I think we need a "substitutions" approach (similar to what is being done in #5753) for the naming here. The admin would specify a "spec" that would include zero or more % placeholders which we will substitute whenever we create a log filename.

That should be specified, placeholders for what.

Greg Shah wrote:

For example, people have very different ideas about how date and time values should be formatted. Why do we care to interfere with the admin on that? Numeric values are another example where there may be some variation in how admins what things done. I don't want to re-invent the wheel. I'd like to reuse the converter specs from https://docs.oracle.com/javase/8/docs/api/java/util/Formatter.html where possible.

So we need a format and locale as separate configs defined in "logging"? Hope our customers are Java pros that will know how to write valid patterns in xml. Still not sure where the args for the patterns will come from if that should be full Formatter support. Obviously to match patterns with args, you need to reinvent the wheel.

• Substitutions should include:
  • date/time values
  • server name
  • log generation number
  • pid

Does the server has a name - is it the default / standard? And that pid, isn't it somewhat confusing, since inside are the logs of many processes.

Greg Shah wrote:

• Use the Formatter conversions as much as possible and add consistent formatting options for special substitutions like pid, tid or context. This means names get formatted using the same options as strings, numerics get formatted with the same options as numbers.

Well, Formatter is used for logs with message format and parameters. All is supported. Don't get your point. Do we need a new wheel here?

Greg Shah wrote:

If clientLog is specified, then won't we output everything to that log?

This points out that we really do need to set a default here for our FWD-specific output. I don't want that co-mingled in the server log by default. Customers see a stderr log today for every client and I think we need to retain something similar by implementing a default FWD client log file if clientLog is not specified.

clientlog lives its own 4GL life, let's not enhance it.

CentralLogger writes all that is written to it explicitly.

There is this dir config (logging:file:dir) you might have noticed that allows you to choose the location. The old approach gave you server.log without any placeholders that got overwritten by mistake.

We don't want to require all configuration to be in the bootstrap cfg. The directory should provide a configuration value which can be overridden by bootstrap cfg. If not specified in either place, we should safely default.

There is also the logging:file:namePrefix config in the new approach.

This is no longer needed. I think that we would have a directory entry that allows the spec to be provided. It is OK to add a bootstrap cfg value as an override.

That should be specified, placeholders for what.

I'm referring to the items listed in "Substitutions should include:".

So we need a format and locale as separate configs defined in "logging"?

The format is whatever Formatter conversion spec is provided as the substitution placeholder. I don't see why we would need a separate entry.

The locale isn't necessary. Our server already runs in some locale. We don't need to specify anything different for logging.

Hope our customers are Java pros that will know how to write valid patterns in xml.

We are providing safe defaults. All of the admins are IT pros. Surely they can read the Formatter documentation and experiment to get the results they want if they need something custom.

Still not sure where the args for the patterns will come from if that should be full Formatter support.

We are only supporting a short list of values. You would create a placeholder for things like a pid or userid. These would act like Formatter specs but would be different.

Obviously to match patterns with args, you need to reinvent the wheel.

Yes, there is some work here but we are trying to reuse a common standard as much as possible.

Does the server has a name - is it the default / standard?

Yes, our default server name is standard.

And that pid, isn't it somewhat confusing, since inside are the logs of many processes.

As I've been trying to highlight, we are really trying to have separate logs for each process. If something is truly generated on the server, then it doesn't seem to be a problem to output the server pid. If there is output from many processes in the same log, then using the server pid for server output is in fact a really useful thing.

Well, Formatter is used for logs with message format and parameters. All is supported. Don't get your point. Do we need a new wheel here?

I'm pretty sure what I'm asking for does not exist in your code today.

clientlog lives its own 4GL life, let's not enhance it.

You are suggesting that we implement a 2nd logfile for default logging in FWD? That would be OK. What is not OK is putting all the client logging into the server log by default.

CentralLogger writes all that is written to it explicitly.

I don't understand your point here.

Greg Shah wrote:

• Legacy spec for LOG-MANAGER output which should be completely compatible with the 4GL spec. This will make it easy for customers to migrate any pre-existing log analysis processing for OE. I know you "cleaned things up" but I think it must match 100% (or as much as we can reasonably match).

• Add a few redundant symbols to date
• Add pid to logs, that we don't have quite often
• Add the empty thread id
• Replace the 8 java logging levels with the 5 OE levels
• Replace the fully qualified class name of loggers with 10 symbols
• Remove FWD context or concatenate it to the actual message
• Reformat Throwable to show stacktrace in 4GL way

Is this what needs to be done?

Greg Shah wrote:

There is this dir config (logging:file:dir) you might have noticed that allows you to choose the location. The old approach gave you server.log without any placeholders that got overwritten by mistake.

We don't want to require all configuration to be in the bootstrap cfg. The directory should provide a configuration value which can be overridden by bootstrap cfg. If not specified in either place, we should safely default.

There is some misunderstanding. CentralLogger is never configured by client configs. It's one file with configs in directory.xml. Maybe the way I show the configs is confusing, let it be logging/file/dir. Please take a brief look at the configs in Logs wiki.

Greg Shah wrote:

clientlog lives its own 4GL life, let's not enhance it.

You are suggesting that we implement a 2nd logfile for default logging in FWD? That would be OK. What is not OK is putting all the client logging into the server log by default.

So you're suggesting that we know what log is written to clientlog and not write it to server.log? Well, this would be an amazing achievement. Since LOG-MANAGER can change its configs programmatically and is different for different clients.. So if it gets disabled we reroute to server.log, when it gets programaticaly enabled back, stop writing to server.log that type of messages, but only for that particular client. Am I getting it?

Add the empty thread id

Why is it empty?

Is this what needs to be done?

If this is the list of deviations for the LOG-MANAGER output, yes. It should not be done for the non-legacy output (the FWD-specific logging).

So you're suggesting that we know what log is written to clientlog and not write it to server.log?

I don't know what you mean by this.

The clientLog controls the destination of the LOG-MANAGER output, right? The value for clientLog will be passed as a bootstrap cfg value. By providing substitution placeholders, we can enable a situation where even web clients which share the same bootstrap cfg value will actually have unique clientLog values.

If every client has its own unique clientLog value, then any LOG-MANAGER output in the security context associated with that client (or in the FWD client process itself) should end up in that logfile and not in the server log.

Since LOG-MANAGER can change its configs programmatically and is different for different clients.. So if it gets disabled we reroute to server.log, when it gets programaticaly enabled back, stop writing to server.log that type of messages, but only for that particular client. Am I getting it?

I don't see why LOG-MANAGER output would ever end up in the server log. The entire idea of LOG-MANAGER is that there is some named logfile that is the destination. Each context should get its separate output. Do we have any cases where we would generate legacy LOG-MANAGER output that would not be in a specific client context? I generally wouldn't expect it.

As far as "disabling" LOG-MANAGER, I guess you mean calling CLOSE-LOG()? At that point I would expect us to do the same thing as the 4GL. Doesn't the 4GL generate an error if there is logging but there is no logfile opened?

What is the case where the server log is part of this solution?

Greg Shah wrote:

As far as "disabling" LOG-MANAGER, I guess you mean calling CLOSE-LOG()?

There are 5 different ways to disable LOG-MANAGER at will in OE.

Greg Shah wrote:

I don't see why LOG-MANAGER output would ever end up in the server log.

All System.err does to server log. All OE errors go to LOG-MANAGER, when LOG-MANAGER is enabled (which is the choice of the programmer, admin). If and which logs go to both places I don't know, it's possible. Someone can make sure no OE errors go to server log by checking ErrorManager. But noone should be able to determine if the OE errors went somewhere... LOG-MANAGER can be and should be possible to be disabled in several different ways.

Greg, on my interview you said you're reproducing OE with the typos and all its flaws.

How does disabling LOG-MANAGER come into this discussion of the server log? If it can be disabled in 5 ways, that is fine. Why is our implementation any different?

on my interview you said you're reproducing OE with the typos and all its flaws.

The server log doesn't have a counterpart in OE so it is not related to compatibility behavior.

• build.gradle - org.slf4j:slf4j-api:1.7.5 remains and slf4j-jdk14 was removed. Software_Dependencies will need to be updated.
• com.goldencode.expr, com.goldencode.email (and others) now depend on com.goldencode.p2j.util.logging. Greg, I recall we wanted to keep the com.goldencode. packages as non-dependent on com.goldencode.p2j as possible. Is this still in place? Do we want to have a com.goldencode.logging implementation with no dependencies on com.goldencode.p2j code?
• there is a new src/org/slf4j/impl package with the implementation of slf4j to redirect to CentralLogging. From the javadoc for src/org/slf4j/impl/StaticLoggerBinder:
  

  The class name and package name should exactly match what slf4j lib expects to find for it to be able to load this custom implementation. This is a very standard implementation.
  

  
  I understand that we need this exact class to exist. Greg, what's the approach here? At least CentralSlf4jLogger and CentralSlf4jLoggerFactory I think can be moved to com.goldencode.p2j.util.logging.slf4j.
• there is a new com.goldencode.p2j.util.StringUtil class - I think these helpers are better in com.goldencode.util.StringHelper (we already have a helper class)
• for example, in RuntimeJastInterpreter, there is code like:
  

     private Object getCache(Aast node, String key)
     {
        Object o = node.getAnnotation(key);
        if (o != null)
        {
           LOG.finer("Found cached " + key + " for " + node.toString() + 
                              "(" + node.getText() + ") = " + o);
        }
        return o;
     }
  

  
  where previously was:
  

     private Object getCache(Aast node, String key)
     {
        Object o = node.getAnnotation(key);
        // debug only
        //if (o != null)
        //{
        //   System.err.println("Found cached " + key + " for " + node.toString() + 
        //                      "(" + node.getText() + ") = " + o);
        //}
        return o;
     }
  

  
  Any logging which is not part of an unexpected behavior (like a catch block), and it computes a complex message (not just a simple string concatenation, but even that may be expensive) must be wrapped in a e.g. if (LOG.isLoggable(Level.FINER)) block. This is because otherwise the log message still gets computed - we need to avoid this especially in code part of critical runtime components, like persist.
• in CentralLogger.get(), there is this comment:
  

              // The deployment hasn't been explicitly marked as server or client. It's not clear what 
              // configurations are present, so using the default fallback to stdout. No shut down hook here, no
              // crash log files generated.
              mode = Mode.DEFAULT;
  

  
  Is it ever possible to go into Mode.DEFAULT for the FWD client, before ClientDriver.main gets executed? I ask because writing logs to STDOUT is not OK, on the FWD Client.
• CentralLoggerServer$ConfigsBuilder.fileDir and also @CentralLoggerServer$Config.<constructor> have this code:
  

           String workingDir = Utils.getDirectoryNodeString(null, "clientConfig/workingDir", null, false);
  

  
  clientConfig/workingDir is for FWD clients. There is no reason for the FWD Server to be dependent on it. Also, maybe some access checks should be done, that the FWD Server can actually write to this folder, as a fail-safe.
• CentralLoggerServer.fileHandler - is this automatically closed on JVM shutdown?
• CentralLoggerClient.finish() is being called from CommonDriver.process. There was already a dependency on ClientCore.isCauseStop() in there, but, can we move the client-specific code from the catch block to ClientDriver.start, and leave only the default -13 exit there?
• CentralLogFormatter - it is hard to match together a message incoming from the FWD client with a message for the same FWD client, but emitted by the FWD Server. Currently for the FWD Server there is this logged:
  

  Session:%08X, Thread:%08X, User:%s
  

  
  while for messages incoming from a FWD client there is only a PID and a ThreadName. I think we already have this problem with trunk, we can't really match messages from the FWD client erorr logs with the FWD server messages. What I'm thinking is we can get this info (like Sesssion and User) during ClientCore.start, this code:
  

           if (session != null)
           {
              CentralLogService logService =
                 (CentralLogService) RemoteObject.obtainNetworkInstance(CentralLogService.class, session);
              CentralLoggerClient.setLogService(logService);
           }
  

  
  can call back to the server, determine the Session ID and the FWD User, and cache them at the CentralLoggerClient.
• Eugenie, please take a look at src/native. The point here is that the STDERR of the spawner is linked with the FWD server's log, and all messages are written to that. As a first note, there are still debug_opt_found references in spawn.c.

Constantin Asofiei wrote:

[...]
can call back to the server, determine the Session ID and the FWD User, and cache them at the CentralLoggerClient.

• Eugenie, please take a look at src/native. The point here is that the STDERR of the spawner is linked with the FWD server's log, and all messages are written to that. As a first note, there are still debug_opt_found references in spawn.c.

I have reviewed changes. Yes, debug_opt_found can be removed, it is always 0 in new code so useless.

I'm OK with changes if the additional debug option can be used with new approach. Please explain how to configure it now to get previous debug level in server.log. This is very important for native code debugging especially on Windows target system. I would say sometimes it is the only way to debug spawner failure in Windows environmnt.

Greg, I recall we wanted to keep the com.goldencode. packages as non-dependent on com.goldencode.p2j as possible. Is this still in place?

Yes.

Do we want to have a com.goldencode.logging implementation with no dependencies on com.goldencode.p2j code?

Yes, we would want any code that doesn't have to be in the src/org/slf4j/impl/StaticLoggerBinder to be in our packages.

At least CentralSlf4jLogger and CentralSlf4jLoggerFactory I think can be moved to com.goldencode.p2j.util.logging.slf4j.

I like that idea.

• p2j.admin.server.ReportServlet - logger is defined on ClientCore, not ReportServlet.
• p2j.admin.server.reports.AbstractReportBuilder - logger is defined on PdfReportBuilder not on AbstractReportBuilder
• p2j.main.AppServerConnectionPool - this code (and others):
  

                LOG.logp(Level.SEVERE,
                          "Could not perform the " + type + " services authentication!",
                          "",
                          "!",
                          e);
  

  
  does not match the arguments with the semantic of the parameters. But this is not from your changes, this is already in trunk.
• missing javadoc in:
  • p2j.main.ClientCore.isNativeLayerInitialized
  • p2j.main.ClientDriver.initializeLogging
  • p2j.main.CommonDriver.initializeLogging
  • p2j.main.ServerDriver.initializeLogging
  • p2j.net.NetResource.LOG
• please bracket the LOG.finer/finest/etc calls with a if (LOG.isLoggable(...)) block, to avoid computing the log message. This is a performance concern.
  • p2j.net.NetResource.netAccessWorker
  • p2j.net.NIONetSocket.readFully - there is an additional code on line 195
  • p2j.net.Protocol$Reader.run
  • p2j.security.AdminResource.nodeWorker
  • p2j.security.BitFlagsResource.accessWorker
  • p2j.security.SecurityManager.authenticateClientWorker
  • p2j.security.SecurityManager.sendAuthResult
  • p2j.security.StringConditionResource.isAllowed
  • p2j.security.SystemResource.systemAccessWorker
  • p2j.ui.client.OutputManager
  • p2j.ui.client.chui.driver.ChuiOutputManager
  • p2j.persist.RuntimeJastInterpreter - save the result of LOG.isLoggable(Level.FINER) in a class field and use that; this is a performance concern.
  • p2j.persist.RuntimeJastInterpreter.buildTypeExpression - in all places where LOG.finer or any other logging is called, it needs to be in a if (finerLoggingEnabled) block. We really need to avoid computing the logging message if not needed. This is a real performance concern.
• p2j.main.ClientSpawner.spawn - there is CentralLoggerServer.logSpawnerStream after cb.localStart. My assumption is that we are capturing the spawner's error stream after the spawn process has started. What happens with any messages logged between the time after cb.localStart is called and logSpawnerStream is called? Are they cached in the error stream and FWD will see them? Can messages be lost?
• p2j.main.ServerDriver.initializeLogging - ds.bind() is called but ds.unbind() is never called.
• p2j.main.ServerDriver.main - shouldn't CentralLogger.handleShutDown(); be in a finally block?
• p2j.main.StandardServer.boostrap - there is some commented code related to sfh (SecureFileHandler), I think this needs to be removed
• p2j.net.Protocol.applyChanges - this code:
  

           if (smsg.getState() instanceof ClientState)
           {
              ClientState clientState = (ClientState) smsg.getState();
              CentralLogStaticService.publish(clientState.logRecords);
           }
  

  
  needs to be in LogicalTerminal.applyChanges
• in p2j.oo., JsonArray, JsonConstruct and JsonObject state that the logger can't be static. But in LegacySocketLibrary.LOG, this is still static. What problems can there be if the logger is static or not? I don't think there should make any differences, the logger needs to be static and any context-local state (if needed) kept at the CentralLogger.
• the changes in p2j.security.Resolver I think can be backed out; I don't see a need for them:
  • constants can remain as-is, this just adds an anonymous class.
  • Integer.valueOf(lvl.intValue()); avoids the auto-boxing for small values.
• p2j.util.RemoteErrorData has no actual change, just the end of file new line.
• p2j.persist.dialect.MariaDbDialect - it has lots of new imports which are unused, please clean them.
• p2j.persist.pl adds dependency on CentralLogger, and affects p2jpl.jar. Is CentralLogger added to p2jpl.jar?
• if is not already in the wiki, we need documentation:
  • any removed bootstrap or directory config
  • any new bootstrap (like client:logging:fileLevel) or directory config
• just to note, these still have TBD/TODOs
  • p2j.convert.ConversionStatus
  • p2j.ui.chui.ThinClient.clientLog

Hynek, please review the ext/ changes.

if (LOG.isLoggable(...)) should never be called any more from performance stand point. Only in cases of very complex calculations / replacements in the message. It's the first statement in the log methods and it's not very cheap.

I had to remove isLoggable actually, but it was too much work. For very heavy log messages use the method overload with suppplier () -> {} - delayed execution.

Let me repeat just to make sure I'm understood: isLoggable is the first statement in the log methods.

      LOG.finer(typedExpr.dumpTree(true));

• typedExpr.dumpTree(true) is executed always
• there are 3 calls before if(!canLog(level, msg)) is reached in ultimateLog

In a performance point of view, we need to never reach LOG.finer if this logging level is not enabled. Using a lambda is not an option - we've seen real performance degradation when this gets into millions of calls.

Galya Bogdanova wrote:

if (LOG.isLoggable(...)) should never be called any more from performance stand point.

This flag can be cached as a class field and used, instead of calling LOG.isLoggable(...) always.

The flag cannot be cached and should not be cached, because it's dynamic.

First of all it's dynamic, because all logging is allowed before initialization for the sake of not loosing logs. Then after initialization in theory any code can set a Logger level for a package that affects all child classes and packages.

Constantin Asofiei wrote:

Hynek, please review the ext/ changes.

The changes are good.

Constantin Asofiei wrote:

p2j.main.ClientSpawner.spawn - there is CentralLoggerServer.logSpawnerStream after cb.localStart

There is no other way and I've found that all messages are logged even though the logging starts after the process. Java doc doesn't give a clue how it's expected to work, but it did work in my tests.

Galya Bogdanova wrote:

First of all it's dynamic, because all logging is allowed before initialization for the sake of not loosing logs. Then after initialization in theory any code can set a Logger level for a package that affects all child classes and packages.

I understand this, but AFAIK we are not doing this in FWD trunk and we don't plan to do this. Greg: is this correct?

This is Java logger functionality and as I've said we're doing dynamic isLogging, because of the delayed initialization.

Galya Bogdanova wrote:

This is Java logger functionality and as I've said we're doing dynamic isLogging, because of the delayed initialization.

But the code I'm referring to is not part of initialization; when RuntimeJastInterpreter is executed, the logging is already initialized. Am I misunderstanding something?

Constantin Asofiei wrote:

But the code I'm referring to is not part of initialization; when RuntimeJastInterpreter is executed, the logging is already initialized. Am I misunderstanding something?

Yes. Everything happening on the system before the configs are read and applied to CentralLogger is called pre-initialization. It includes dozens of classes, class loaders, I would imagine you wouldn't be able to reason about the tree dependencies here before deciding to cache.

Galya Bogdanova wrote:

Everything happening on the system before the configs are read and applied to CentralLogger is called pre-initialization.

When is pre-initialization finished? At FWD server startup (when "Server ready" is written in the log)?

We could provide an invalidation mechanism:

static boolean isDebug = MightyLogger.isLoggableAndInvalidate(Level.DEBUG, (newValue) -> isDebug = newValue);

Is it worth the hassle? I'm not sure.

Galya, another question for review: FWD trunk has a logging/loggers setting in directory.xml where you can specify per-package (or class) logging levels. I can't find this in 5703a - will it be replaced with something else?

Hynek Cihlar wrote:

We could provide an invalidation mechanism:

[...]

Is it worth the hassle? I'm not sure.

Hynek, please implement it in your next non-related task.

Constantin Asofiei wrote:

Galya Bogdanova wrote:

First of all it's dynamic, because all logging is allowed before initialization for the sake of not loosing logs. Then after initialization in theory any code can set a Logger level for a package that affects all child classes and packages.

I understand this, but AFAIK we are not doing this in FWD trunk and we don't plan to do this. Greg: is this correct?

No, we DO plan to implement fully dynamic logging levels. See #1848.

However, I do think we will implement this as a listener model so that we can store the flags as static booleans. Also, I don't have a scheduled time for #1848 yet.

The current design is that client and server logging levels are independent, so that the client doesn't have to read directory.xml and can filter out logs on its own instead of syncing tons of debug logs with the server. Adding more logger levels to directory configs will affect only server-side. Are we ok with it?

5703a rebased on trunk r14536.

This is not a final response to all code review questions raised. Wait for more.

Changes in r14594:

• Support for multiple server-side logger levels declared in directory.xml (check #5703#note-205);
• Slf4j impl classes moved to com.goldencode.p2j.util.logging (except StaticLoggerBinder);
• StringUtil methods moved to StringHelper;
• JavaDoc on initializeLogging;
• Simplified / cheaper CentralLogger.getParentLevel (basically isLoggable optimized by introducing proper data structure);
• The example of uncommented debug code in RuntimeJastInterpreter is now wrapped by isLoggable check;
• Closing CentralLoggerServer.fileHandler on shutdown;
• Support for Formatter date / time specifiers in CentralLogger file name (check more in question 2 below);
• debug_opt_found removed in native code.

Answers to questions:

1. Constantin Asofiei wrote:

Is it ever possible to go into Mode.DEFAULT for the FWD client, before ClientDriver.main gets executed? I ask because writing logs to STDOUT is not OK, on the FWD Client.

No, it's not possible to have Mode.DEFAULT on a client started by ClientDriver, nor on server started by ServerDriver. This is the mode for utility processes.

2. Constantin Asofiei wrote:

clientConfig/workingDir is for FWD clients. There is no reason for the FWD Server to be dependent on it. Also, maybe some access checks should be done, that the FWD Server can actually write to this folder, as a fail-safe.

In OE logs go to work dir. In directory.xml you can configure logging dir (check the Logs wiki), but if you don't, the fallback is the work dir like in OE. Don't forget that client logs are also part of the CentralLogger file now, so no good reason to shy away from work dir. If it's not declared, then the location fallbacks to the server dir.

3. Greg Shah wrote:

As with the log filenames, we also need to provide flexibility in the format of the logging.

We can implement more flexible formatter for log records in a future task, when the separate spawner process is removed (quite possible to happen in the near future). Currently one and the same formatter is used to generate the logs in the p2j.jar in /opt/spawn, and then to parse them on the server. To have this working with changeable formatting configs the spawner should be receiving directory.xml configs, which is an effort we can spare ourselves, if the whole process is to be reworked soon. TBD in #7279 as future improvements to CentralLogger.

4. Eugenie Lyzenko wrote:

Please explain how to configure it now to get previous debug level in server.log.

The spawner log levels are now attached to the message itself as a prefix. Messages in stderr without log level as prefix are logged as WARNING. The spawner logger level is defined in directory.xml as logging/spawner/level (check Logs wiki). You can set the config to ALL before starting the server and all the logs from the spawner will be logged in the new server log file.

Questions:

1. Constantin Asofiei wrote:

CentralLoggerClient.finish() is being called from CommonDriver.process. There was already a dependency on ClientCore.isCauseStop() in there, but, can we move the client-specific code from the catch block to ClientDriver.start, and leave only the default -13 exit there?

How so? CentralLoggerClient.finish() should be called before System.exit() and it doesn't matter if the client ends with a success or failure.

2. Greg Shah wrote:

• Substitutions should include:
  • date/time values
  • server name
  • log generation number
  • pid

• I added full java.util.Formatter date time specifiers support;
• The generation number will not be directly modifiable like it is in OE (it's added automatically before the extension, otherwise it affects the configured rotation), but I'll add a config for leading zeros;
• pid is accessible only in Java 9 or with native code, which is available only on the clients;
• server name - is it relevant, since there is only one log file for the whole FWD server instance?

Galya Bogdanova wrote:

2. Constantin Asofiei wrote:

clientConfig/workingDir is for FWD clients. There is no reason for the FWD Server to be dependent on it. Also, maybe some access checks should be done, that the FWD Server can actually write to this folder, as a fail-safe.

In OE logs go to work dir. In directory.xml you can configure logging dir (check the Logs wiki), but if you don't, the fallback is the work dir like in OE. Don't forget that client logs are also part of the CentralLogger file now, so no good reason to shy away from work dir. If it's not declared, then the location fallbacks to the server dir.

Working dir in OE is something relative to the client; in FWD, working dir can also be a path for some remote FWD client (spawned by the broker), on a different machine, which does not exist on the FWD server machine. More, the FWD server may have no access to this working dir (as it is used/accessed using the OS credentials for that spawned FWD client). So, clientConfig/workingDir is a path which should never be resolved/used by the FWD server (as it may not exist on the FWD server at all, the FWD server may not have access to it, etc). If you want to use a default folder for CentralLoggerServer, then it should default to the FWD server's working dir.

1. Constantin Asofiei wrote:

CentralLoggerClient.finish() is being called from CommonDriver.process. There was already a dependency on ClientCore.isCauseStop() in there, but, can we move the client-specific code from the catch block to ClientDriver.start, and leave only the default -13 exit there?

How so? CentralLoggerClient.finish() should be called before System.exit() and it doesn't matter if the client ends with a success or failure.

This code in CommonDriver.process is executed for both FWD server and client processes:

      catch (Throwable thr)
      {
         // STOP conditions don't need to be reported, they are an expected
         // mechanism to terminate
         if (ClientCore.isCauseStop(thr) || thr.getCause().getClass().equals(ApplicationRequestedStop.class))
         {
            CentralLoggerClient.finish();
            System.exit(0);
         }

         logger.severe("System exits with code -13 caused by:", thr);

         CentralLoggerClient.finish();
         System.exit(-13);
      }

You can add the client-specific code to ClientDriver.start and leave here only this here:

         logger.severe("System exits with code -13 caused by:", thr);
         System.exit(-13);

         // STOP conditions don't need to be reported, they are an expected
         // mechanism to terminate
         if (ClientCore.isCauseStop(thr) || thr.getCause().getClass().equals(ApplicationRequestedStop.class))
         {
            CentralLoggerClient.finish();
            System.exit(0);
         }

         logger.severe("System exits with code -13 caused by:", thr);

         CentralLoggerClient.finish();
         System.exit(-13);

Discussion from email:

On 4/18/23 10:37, Galya Bogdanova wrote:

Constantin,

I'm not asking about concatenation. I want a clear statement on the String literals. You know these are stored in a pool and reused. While an actual calculation is done in isLoggable (it's a different question that previously that was hidden in Java classes, but now the implementation is exposed). I have some doubts which one is cheaper. In Any case I would recommend to wrap only dynamically generated strings, not add isLoggable just in case everywhere.

Best,

Galya

On 18.04.23 г. 10:35 ч., Constantin Asofiei wrote:

Galya,

Yes, if previously it was enclosed in a "if (LOG.isLoggable" test, then we need to keep that. If you have questions about some specific code, please post at the task.

As a side note: the performance issue related to java.lang.String is two-fold: one is the actual concatenation, and the other is the garbage collection of these instances; both get problematic when there are millions of instances.

Thanks,

Constantin

On 4/18/23 10:22, Galya Bogdanova wrote:

Hello Constantin,

I have a blocker question about your vision on logging performance:

Do you consider using String literals a performance issue in the critical (e.g. net) classes? In the context of creating these literals for logs that will not be logged, based on their logging level.

Best,

Galya

Constantin Asofiei wrote:

You can add the client-specific code to ClientDriver.start and leave here only this here:
[...]
while the ClientDriver.start will have the full code:
[...]

The code in CommonDriver is in a catch clause wrapping start. To make the same thing work in ClientDriver.start instead of throwing, the method needs to first catch the exception. Do we want to duplicate the logic? CentralLoggerClient.finish() is indeed called from the common driver, but it's first statement is to check if the process is working in client mode, so it does nothing in the rest.

Please advise - do I need to catch all Throwables in ClientDriver.start and duplicate the validation for the sake of semantics?

Galya, I agree that string literals are kept on the constant pool, and do not pose a garbage-collection problem, but my issue is the number of calls until the logging is veto'ed by FWD:

1. NetResource.netAccessWorker (assume that is a literal):
   

   
         LOG.finer("Search open: resId " + resourceIndex + ", instance " +
                      instanceName + ", mode " + mode + ", handle " + handle);
   
   

2. CentralLogger.finer:
   

      public void finer(String msg)
      {
         log(Level.FINER, msg);
      }
   

3. CentralLogger.log:
   

      public void log(Level level, String msg)
      {
         ultimateLog(level, (Throwable) null, null, null, true, msg);
      }
   

4. CentralLogger.ultimateLog:
   

      private void ultimateLog(Level level, Throwable t, String sourceClass, String sourceMethod,
                               boolean addContext, String msg, Object... params)
      {
         if (!canLog(level, msg))
         {
            return;
         }
   

5. CentralLogger.canLog:
   

      private boolean canLog(Level level, String msg)
      {
         if (level == null)
         {
            throw new IllegalArgumentException(
               "Log record level cannot be null" + 
                  (msg == null ? "." : " for msg: " + msg));
         }
         return !IS_LOGGER_WORK_FINISHED.get() && isLoggable(level);
      }
   

6. CentralLogger.isLoggable:
   

      public boolean isLoggable(Level logLevel)
      {
         Level loggerLevel = getLevel();
         return loggerLevel == null || logLevel.intValue() >= loggerLevel.intValue();
      }
   

We have 5 calls until the log is veto'ed. Using something like LOG.isLoggable can be done in a single call, right? Also, about getLevel - I understand this can be expensive, as it needs to look through all parents to find a level. But, something else to note: logging levels is something which can be changed (theoretically) in small circumstances. So, why not calculate the real logging level (in a different field), cache it on the first isLoggable call, and invalidate it when this instance's or parent's logging level gets changed? This will avoid getParentLevel calls for each and every isLoggable call.

As a side note, I would switch !IS_LOGGER_WORK_FINISHED.get() && isLoggable(level); conditions, as the veto is done by isLoggable.

!IS_LOGGER_WORK_FINISHED.get() is a simple boolean check, while isLoggable(level) is more complex method, no reason to switch them.

I don't get it, what is worrisome about bigger stacktrace? I see hundreds of overloaded methods all over the code. It's not like there something produced down the line. Stacktrace depth should not cause performance issues, at least not comparable to calling isLoggable twice.

Constantin Asofiei wrote:

So, why not calculate the real logging level (in a different field), cache it on the first isLoggable call, and invalidate it when this instance's or parent's logging level gets changed? This will avoid getParentLevel calls for each and every isLoggable call.

I don't want to keep references to loggers anywhere except where they are used. Although that's mostly in static fields (due to the highly static nature of the code). Managing listeners or keeping references to the loggers for the sake of invalidation is complicating matters unnecessarily. A fairly simple logic gets out of hand, when this type of mechanisms are added often. Not to mention how caching is a lovely place for bugs.

• clutter the code;
• do it for consistency instead of reason;
• duplicate logic - isLoggable is already part of log methods;
• duplicate execution - almost certain for levels higher or equal to INFO;
• isLoggable checks only if the certain level is loggable, but not if the CentralLogger is in a state to actually log it.

• deeper stacktrace - it's present when the message is loggable anyways;
• string literals that might not get used are added to the pool;

Changes in r14595:

• JavaDoc added for ClientCore.isNativeLayerInitialized and NetResource.LOG.
• Wrong logger names fixed (ReportServlet, AbstractReportBuilder).
• I checked all logp calls and there were a few with wrong signature, fixed now.
• Reverted the logic for finding the closest logger level (changed in the previous revision), because TreeMap didn't work as I expected (as Tree, but it's just a fancy Map). If isLoggable needs to get cheaper I probably need to implement black-red tree, but not sure how much it will improve after all the objects needed for its support.
• Added isLoggable to a few methods, caching the response only in the methods (not on the class level). To be further discussed.
• Session and user id added to client logs to allow matching a message incoming from the FWD client with a message for the same FWD client, but emitted by the FWD Server, e.g. 23/04/18 09:28:31.983+0300 | INFO | com.goldencode.p2j.ui.client.gui.theme.ThemeManager | CLIENT, PID:42836, ThreadName:main, Server Session:00000003, User:appserver_process | UI Theme successfully changed to 'windows10'.
• ServerDriver.initializeLogging DS unbind added.
• Changed the calls to CentralLogger.handleShutDown() and CentralLoggerClient.finish() to be executed in all process exit cases.
• Reverted most of p2j.security.Resolver although I'm not convinced in these so called performance improvements: 1. One object wrapper less for the whole process as a trade-off to assignment closer to declaration and 2. explicit call to a method called by autoboxing anyways.
• Cleaned up MariaDbDialect imports.

Answers:

1. Constantin Asofiei wrote:

p2j.main.StandardServer.boostrap - there is some commented code related to sfh (SecureFileHandler), I think this needs to be removed

I think it's not related to this task and I prefer not to change it, since I don't know what it is. But even if I do, it's still not related to the changes.

2. Constantin Asofiei wrote:

p2j.net.Protocol.applyChanges - this code:
[...]
needs to be in LogicalTerminal.applyChanges

It can't be. LogicalTerminal.applyChanges is not always called and some logs disappear in thin air.

3. Constantin Asofiei wrote:

in p2j.oo., JsonArray, JsonConstruct and JsonObject state that the logger can't be static. But in LegacySocketLibrary.LOG, this is still static. What problems can there be if the logger is static or not? I don't think there should make any differences, the logger needs to be static and any context-local state (if needed) kept at the CentralLogger.

This is taken from the exception thrown, when the fields are static. Json objects are parsed and for some reason ContextLocal doesn't like parsing json objects with static fields. There is no state in logger instances, they are completely safe for GC and recreation.

4. Constantin Asofiei wrote:

• p2j.persist.pl adds dependency on CentralLogger, and affects p2jpl.jar. Is CentralLogger added to p2jpl.jar?

Yes, I added com/goldencode/p2j/util/logging/* to <jar jarfile="${build.home}/lib/p2jpl.jar" in build.xml.

5. Constantin Asofiei wrote:

• if is not already in the wiki, we need documentation:
  • any removed bootstrap or directory config
  • any new bootstrap (like client:logging:fileLevel) or directory config

There is already documentation on the new configs in Logs wiki, it doesn't state clearly the previous "logging" container is removed, but the new configs are clearly different. Adding it now.

6. Constantin Asofiei wrote:

• just to note, these still have TBD/TODOs
  • p2j.convert.ConversionStatus
  • p2j.ui.chui.ThinClient.clientLog

ConversionStatus is to be completed in #7180 and ThinClient.clientLog is removed in the latest fixes.

Questions:

1. Constantin Asofiei wrote:

• p2j.util.RemoteErrorData has no actual change, just the end of file new line.

How did you see this? In bzr status -r-59 it's not listed.

Galya Bogdanova wrote:
1. Constantin Asofiei wrote:

p2j.main.StandardServer.boostrap - there is some commented code related to sfh (SecureFileHandler), I think this needs to be removed

I think it's not related to this task and I prefer not to change it, since I don't know what it is. But even if I do, it's still not related to the changes.

SecureFileHandler was removed with 5703a. What you have commented there is a remnant of this, and can never be used again.

2. Constantin Asofiei wrote:

p2j.net.Protocol.applyChanges - this code:
[...]
needs to be in LogicalTerminal.applyChanges

It can't be. LogicalTerminal.applyChanges is not always called and some logs disappear in thin air.

p2j.net.Protocol can't have any dependency on the SyncMessage.state implementation. What is the case where logs disappear? You mean logs incoming before Protocol.ssync has been registered?

3. Constantin Asofiei wrote:

in p2j.oo., JsonArray, JsonConstruct and JsonObject state that the logger can't be static. But in LegacySocketLibrary.LOG, this is still static. What problems can there be if the logger is static or not? I don't think there should make any differences, the logger needs to be static and any context-local state (if needed) kept at the CentralLogger.

This is taken from the exception thrown, when the fields are static. Json objects are parsed and for some reason ContextLocal doesn't like parsing json objects with static fields. There is no state in logger instances, they are completely safe for GC and recreation.

In FWD, when a static ContextLocal field exists defined in a p2j.oo class, this is assumed as a legacy static class field. Only these fields are 'loaded' when a legacy class is loaded in a FWD client. The previous LOG field was already static. What has changed that this is no longer possible?

1. Constantin Asofiei wrote:

• p2j.util.RemoteErrorData has no actual change, just the end of file new line.

How did you see this? In bzr status -r-59 it's not listed.

When doing bzr status, bzr diff, etc, use -r 14527, where 14527 is the trunk revision where the current 5703a is rebased from. Using -r-59 works but is unnecessary complicated, as this value must be changed with every commit.

why not calculate the real logging level (in a different field), cache it on the first isLoggable call, and invalidate it when this instance's or parent's logging level gets changed?

This is similar to my listener idea. Design it with a static flag and then change the flag in the very rare case when a dynamic change is made.

We can implement more flexible formatter for log records in a future task, when the separate spawner process is removed

What do you mean by "the separate spawner process"? I'm OK with implementing the flexible formatter in a separate task but I'm not OK deferring it to an indefinite time in the future.

I added full java.util.Formatter date time specifiers support;

Yes, that is good.

The generation number will not be directly modifiable like it is in OE (it's added automatically before the extension, otherwise it affects the configured rotation), but I'll add a config for leading zeros;

I'm looking for the position in the filename to be controllable, not the number itself.

pid is accessible only in Java 9 or with native code, which is available only on the clients;

Changes for #4065 mean that we actually have access to the libp2j on the server now, so it can be used.

server name - is it relevant, since there is only one log file for the whole FWD server instance?

Yes, it is relevant. We have configurations were the directory values can be shared between multiple servers. Implementing this substitution means that those values can be common code which makes the deployment easier.

Galya Bogdanova wrote:

The current design is that client and server logging levels are independent, so that the client doesn't have to read directory.xml and can filter out logs on its own instead of syncing tons of debug logs with the server. Adding more logger levels to directory configs will affect only server-side. Are we ok with it?

No, we do want to be able to define the logger levels for the client in the directory. Our approach is always to minimize the amount of client-side configuration and scripting while maximizing the ability of controlling things from the server side. That reduced admin effort and complexity of deployment.

Constantin Asofiei wrote:

2. Constantin Asofiei wrote:

p2j.net.Protocol.applyChanges - this code:
[...]
needs to be in LogicalTerminal.applyChanges

It can't be. LogicalTerminal.applyChanges is not always called and some logs disappear in thin air.

p2j.net.Protocol can't have any dependency on the SyncMessage.state implementation. What is the case where logs disappear? You mean logs incoming before Protocol.ssync has been registered?

Yes, I guess. There was no right synchronizer registered. The logs were not processed by LogicalTerminal, died in Protocol.

Greg Shah wrote:

What do you mean by "the separate spawner process"? I'm OK with implementing the flexible formatter in a separate task but I'm not OK deferring it to an indefinite time in the future.

I see the potential for this being my next task. Let's discuss it in #7279 and not pollute this task.

Greg Shah wrote:

Galya Bogdanova wrote:

The current design is that client and server logging levels are independent, so that the client doesn't have to read directory.xml and can filter out logs on its own instead of syncing tons of debug logs with the server. Adding more logger levels to directory configs will affect only server-side. Are we ok with it?

No, we do want to be able to define the logger levels for the client in the directory. Our approach is always to minimize the amount of client-side configuration and scripting while maximizing the ability of controlling things from the server side. That reduced admin effort and complexity of deployment.

I don't understand you. Do you want separate levels for clients at all or one global level for all processes is enough?

Galya Bogdanova wrote:

I don't understand you. Do you want separate levels for clients at all or one global level for all processes is enough?

Now it might be the right time to decide this :)

Greg Shah wrote:

I'm looking for the position in the filename to be controllable, not the number itself.

How will you guarantee the customer will define it?

P.S. OE doesn't allow it (just by the way, again) - the freedom of deciding if you want and how you want a rotation number.

Galya Bogdanova wrote:

Yes, I guess. There was no right synchronizer registered. The logs were not processed by LogicalTerminal, died in Protocol.

OK, we really need for this to be in LogicalTerminal.applyChanges. There is another LocalStateSync.sync() which synchronizes state.

The problem is that LogicalTerminal.init() gets called only when this class gets initialized (i.e. accessed) by the FWD server for this client. ThinClient.getChanges() will transfer state to the FWD server before LogicalTerminal.init() got a chance to be executed.

Can we delay the cs.logRecords = CentralLoggerClient.pullLogs(); via a flag 'server-side logging initialized' at ThinClient, which can be via some ClientExports API which just sets this flag, called from LogicalTerminal.init()? This would allow the FWD client to cache logging records until this flag gets set, and after that LogicalTerminal.applyChanges() can work properly.

As a side note: CentralLoggerClient.pullLogs needs to return null if there are no records, to avoid transferring a zero-length array.

Another note, this code in CentralLoggerClient:

   public static CentralLogRecord[] pullLogs()
   {
      CentralLogRecord[] logRecords = LOG_BUFFER.toArray(new CentralLogRecord[0]);
      LOG_BUFFER.clear();
      return logRecords;
   }

Let's confirm: After LogicalTerminal.init() is called on the client, then it's safe to send logs to be handled in LogicalTerminal.applyChanges() on the server?

Or if I got it wrong and LogicalTerminal.init() should be called on the server, then how do I push the init state to the client? Polling for it doesn't sound right.

Greg Shah wrote:

This is similar to my listener idea. Design it with a static flag and then change the flag in the very rare case when a dynamic change is made.

Have you considered moving to another programming language - an event-driven, functional one - there will be no object wrappers and object lambdas and lots of events.

Do you want separate levels for clients at all or one global level for all processes is enough?

A global level is enough for now.

How will you guarantee the customer will define it?

If it is not there, then we can add it in the default position.

OE doesn't allow it (just by the way, again) - the freedom of deciding if you want and how you want a rotation number.

Understood. It is good to be better than OE.

Have you considered moving to another programming language - an event-driven, functional one - there will be no object wrappers and object lambdas and lots of events.

Most if not all dynamic JVM-hosted languages (e.g. Groovy) are very slow compared to native Java. Languages like Python are even slower. None of those are an option or are of interest. I'd have to check on Kotlin and Scala specifically, but we would be restricted to JVM-hosted options. Anyway, I'm not sure we should spend time on this right now.

Greg Shah wrote:

Have you considered moving to another programming language - an event-driven, functional one - there will be no object wrappers and object lambdas and lots of events.

Anyway, I'm not sure we should spend time on this right now.

Agreed, although it might flow more naturally with FWD coding style and will make sense to new devs. Groovy obviously is not an option.

Galya Bogdanova wrote:

Let's confirm: After LogicalTerminal.init() is called on the client, then it's safe to send logs to be handled in LogicalTerminal.applyChanges() on the server?

• a ClientExports.loggingInitialized() API
• a ThinClient.loggingInitialized() implementation which just sets a flag
• ThinClient.getChanges() is aware of this flag (which defaults to false), to not pull logging data unless this flag is true.
• LogicalTerminal.init() calls client.loggingInitialized() sometime after client is resolved.
• move the code from Protocol.applyChanges() to LogicalTerminal.applyChanges().

Constantin, I reverted the loggers in the Json* classes to static, because I cannot reproduce the problem now, but I'm pretty sure I saw it while testing in customer app. After the code review is done, I'll test again and let you know if I spot it again.

Greg,

I think we need to consider a few aspects with this global server-side logging level. With last minute changes to the design (laid in the wiki a while ago) I might not take everything into consideration.

Actually the logging level on the server is a more complicated matter - now we support more logger levels in directory.xml + dynamic setting of levels by using setLevel().

I see a few options:
1. Send all logs (on all levels) from all clients to the server with the state sync and filter them out on the server. It might end in a substantial change in message size.
2. Before each log fetch all the server logger levels and do the filtering on the client.
3. Adding inter-process listeners - reinventing message queues, that invalidate cached log levels on clients (near real-time with acceptable delay) - we're flying rockets in the space. + of course 2, but in moderation.

I think we have a winner, right?

P.S. We'll also have to disable setLevel() on clients.

I suspect your winner is not my winner. ;)

Options 1 and 2 are performance killers so we cannot use them.

Option 3 is not as hard as it sounds. At client startup, the logging levels have to be retried by a single up or down call. We would add a client-side remote call to notify when any logging level is changed. The client side implementation of that call can have a simple set of listeners and call those classes whose logger has changed. The server-side cross-session notification doesn't need to be implemented now because we don't yet support #1848.

Greg Shah wrote:

I suspect your winner is not my winner. ;)

You underestimate my estimation. :)

Nice! I stand corrected.

Is it alright in general for ThinClient.getChanges() to be executed before LogicalTerminal.init()? I mean do we need the flag to prevent only logging changes?

Greg, if a formatted rotation number is needed for CentralLogger files, then a custom FileHandler (the core of the current implementation) will be needed. If you think it's worth it to handle file writes and rotation manually for the sake of improved formatting of rotation numbers, please create a new task. Java logging doesn't support that, here is an excerpt from java.util.logger.FileHandler:

A pattern consists of a string that includes the following special components that will be replaced at runtime:

    "/" the local pathname separator
    "%t" the system temporary directory
    "%h" the value of the "user.home" system property
    "%g" the generation number to distinguish rotated logs
    "%u" a unique number to resolve conflicts
    "%%" translates to a single percent sign "%" 

Any of above-mentioned specifiers will be available for customers to define in the name of the log file.

• Client CentralLogger initialized after LogicalTerminal#init() completion on the server and reading logs moved from Protocol to LogicalTerminal#applyChanges.
• Client-side setting of logging levels disabled. Log levels received on initialization from the server and invalidated with every server-side dynamic change.
• Work dir no longer used for a default location of log files. If no directory is specified with logging/file/path, then the server launch dir will be used.
• Atomic operations introduced for collections that should get queried and cleared at the same time.

Question:
Where is System.loadLibrary("p2j") called server-side, so that the native lib can be used to access process id (refs #4065)?

If you think it's worth it to handle file writes and rotation manually for the sake of improved formatting of rotation numbers, please create a new task. Java logging doesn't support that

We can postpone this. Make it clear in our documentation that this is a limitation in the current implemention.

Where is System.loadLibrary("p2j") called server-side, so that the native lib can be used to access process id (refs #4065)?

This is done in LibraryManager but probably should be in something more generic.

Greg Shah wrote:

Where is System.loadLibrary("p2j") called server-side, so that the native lib can be used to access process id (refs #4065)?

This is done in LibraryManager but probably should be in something more generic.

Yes, I find it difficult to reason about where OSResourceManager is first accessed server-side, so that the static field ContextLocal<OSResourceManager> mgr is initialized. Can you give me a hint?

Galya Bogdanova wrote:

Greg Shah wrote:

Where is System.loadLibrary("p2j") called server-side, so that the native lib can be used to access process id (refs #4065)?

This is done in LibraryManager but probably should be in something more generic.

Yes, I find it difficult to reason about where OSResourceManager is first accessed server-side, so that the static field ContextLocal<OSResourceManager> mgr is initialized. Can you give me a hint?

We might want to have an explicit step in the StandardServer.bootstrap() process.

Hynek/Constantin: What are your opinions?

Constantin Asofiei wrote:

Galya Bogdanova wrote:

In OE logs go to work dir. In directory.xml you can configure logging dir (check the Logs wiki), but if you don't, the fallback is the work dir like in OE. Don't forget that client logs are also part of the CentralLogger file now, so no good reason to shy away from work dir. If it's not declared, then the location fallbacks to the server dir.

Working dir in OE is something relative to the client; in FWD, working dir can also be a path for some remote FWD client (spawned by the broker), on a different machine, which does not exist on the FWD server machine. More, the FWD server may have no access to this working dir (as it is used/accessed using the OS credentials for that spawned FWD client). So, clientConfig/workingDir is a path which should never be resolved/used by the FWD server (as it may not exist on the FWD server at all, the FWD server may not have access to it, etc). If you want to use a default folder for CentralLoggerServer, then it should default to the FWD server's working dir.

What should be the default folder for LegacyLogManager?

Also please understand that there is no CentralLogerClient and CentralLoggerServer, but only CentralLogger. The logs are mixed in one file. I see client logs in workDir and this is used by LOG-MANAGER (which is also produced server-side), so please explain the difference.

...and appserver logs go to work dir, which is probably quite a server.

Greg Shah wrote:

We might want to have an explicit step in the StandardServer.bootstrap() process.

Hynek/Constantin: What are your opinions?

OSResourceManager context local state is initialized on the first memptr/library access (currently) which does the System.loadLibrary("p2j");.

We can add a standard hook in StandardServer.registerDefaultServices, which just calls LibraryManager.init(). But if we don't do this conditionally (i.e. server-side memptr or library), then any installation will require the p2j library added to the server.sh library path.

Constantin Asofiei wrote:

Greg Shah wrote:

We might want to have an explicit step in the StandardServer.bootstrap() process.

Hynek/Constantin: What are your opinions?

OSResourceManager context local state is initialized on the first memptr/library access (currently) which does the System.loadLibrary("p2j");.

We can add a standard hook in StandardServer.registerDefaultServices, which just calls LibraryManager.init(). But if we don't do this conditionally (i.e. server-side memptr or library), then any installation will require the p2j library added to the server.sh library path.

The questions is how to know if in CommonDriver#process on line 533 the library can be accessed.

Galya Bogdanova wrote:

The questions is how to know if in CommonDriver#process on line 533 the library can be accessed.

At that point, it can't be initialized via the init hooks for StandardServer, as they are called by start().

Galya Bogdanova wrote:

What should be the default folder for LegacyLogManager?

If the logging directory is not specified, log a warning and default to the FWD server's working dir. We can't rely on clientConfig/workingDir. As I understand, the FWD client never actually writes the logs by itself, just transfers log records to the FWD server.

But even if the FWD client would write to the log file itself, defaulting to the JVM's working dir will work, as this would be just clientConfig/workingDir.

Ok, r14598 removed workingDir from LOG-MANAGER as well. Now all is going to be dumped by default in the server launch dir.

Greg, what do we do with the pid?

Also please understand that there is no CentralLogerClient and CentralLoggerServer, but only CentralLogger. The logs are mixed in one file. I see client logs in workDir and this is used by LOG-MANAGER (which is also produced server-side), so please explain the difference.

Are you talking about the output being mixed in one file or the code for generating the output being mixed in one file? The latter is OK, the former is not.

But if we don't do this conditionally (i.e. server-side memptr or library), then any installation will require the p2j library added to the server.sh library path.

We don't want to require this in all cases.

I don't have time right now to go through all the details for all questions that have been posted recently. One thing that concerns me is the comment about "As I understand, the FWD client never actually writes the logs by itself, just transfers log records to the FWD server.".

This suggests that log files can never be written on the client side which is a problem. Although we want to use server-side logging as much as possible, we can't always know that that will be OK. In other words, requiring only server-side logging is not OK.

Galya Bogdanova wrote:

Greg, what do we do with the pid?

If you have to implement the pid and it the library is not loaded, then do a late load of the native library and call it.

Greg, you make me worried extremely. Let me repeat what I've said (hoping it's received on the other end many time already) about how your idea of mixed logging works in my implementation:
1. Client starts, get initialized, accesses server by sending successful state syncs, all its logging is written out by the server.
2. Client starts, doesn't get initialized for some reason or cannot access the server, all logs are output to a crash log on shutdown.

... hope we can merge now...

Greg Shah wrote:

If you have to implement the pid and it the library is not loaded, then do a late load of the native library and call it.

This will be a 100% executed early load... in CommonDriver#process. That's where it's needed.

Actually even before that, since it needs to be done only on the ServerDriver.

Constantin, what do I do with that last blocker: Fixed it.

Exception in thread "main" java.lang.UnsatisfiedLinkError: no p2j in java.library.path
    at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1860)
    at java.lang.Runtime.loadLibrary0(Runtime.java:843)
    at java.lang.System.loadLibrary(System.java:1136)
    at com.goldencode.p2j.main.ServerDriver.main(ServerDriver.java:992)

It's done and done in r14601. Please confirm it's done.

65 revisions later and 508 files updated, let's do it!

Galya, System.loadLibrary("p2j"); in ServerDriver.main will force any installation to require the p2j library added to the server.sh library path.

Galya Bogdanova wrote:

Greg, you make me worried extremely. Let me repeat what I've said (hoping it's received on the other end many time already) about how your idea of mixed logging works in my implementation:
1. Client starts, get initialized, accesses server by sending successful state syncs, all its logging is written out by the server.
2. Client starts, doesn't get initialized for some reason or cannot access the server, all logs are output to a crash log on shutdown.

... hope we can merge now...

It sounds like there is a misunderstanding here. I've mentioned from the start that the logging cannot only be on the server. Please see #5703-12, #5703-86 and probably other places.

If logging in only ever on the server, then it will break some use cases that work today.

Greg Shah wrote:

Galya Bogdanova wrote:

Greg, you make me worried extremely. Let me repeat what I've said (hoping it's received on the other end many time already) about how your idea of mixed logging works in my implementation:
1. Client starts, get initialized, accesses server by sending successful state syncs, all its logging is written out by the server.
2. Client starts, doesn't get initialized for some reason or cannot access the server, all logs are output to a crash log on shutdown.

... hope we can merge now...

It sounds like there is a misunderstanding here. I've mentioned from the start that the logging cannot only be on the server. Please see #5703-12, #5703-86 and probably other places.

If logging in only ever on the server, then it will break some use cases that work today.

Which use cases, let's be specific what is the acceptance criteria and tests for this task?

Did I somehow leave wrong impressions on what I'm doing for these few months? I created the Logs wiki quite early I believe.

LOG-MANAGER generates different files for each client process and appserver, it logs on the server with some logs coming from the client. LOG-MANAGER is ContextLocal instantiated on the server, receiving logs from WRITE-MESSAGE calls from the server Conversation thread. If you want it the other way around, what's the reasoning behind it? How do you imagine to keep an appserver instance of LOG-MANAGER on the client?

Output redirect is done on the client.

CentralLogger generates one file on the server.

Do you need all the logging to be done either client-side or server-side or you want multiple processes to write to the same file?

Status report 01/13/2023

Galya Bogdanova wrote:

I'll need a few days to analyze what types of 4GL errors and alert boxes are shown client-side in FWD and how that could be handled on the server or passed down to the server, which is not ideal - each rpc will add some latency although I don't know how performant FWD rpc calls are... something to get familiar with later on if unavoidable.

Re: Status report 01/13/2023

Greg Shah wrote:

The RPC is fast, but when used heavily it is still costly. To keep it fast, we make sure to implement Externalizable instead of using the slower built-in Serializable. We try to avoid a round trip (initiated from either direction) whenever possible. We have done quite a bit of optimization including using a kind of "side-channel" for state synchronization that defers updates until the next RPC, piggybacking on the same transfer.

Did you think I'll be using it to send server logs to the clients?

#5703#note-40

Greg Shah wrote:

Whether it is recursion or deadlock, the state synch approach should work.

From the server to the client?

#5703#note-27

Greg Shah wrote:

The equivalent system in OE is a single process. For this reason, we cannot cause log output to be spread across multiple destinations. It must be combined.

We also want to have a "everything logs on the server" idea which is cleaner and when the log output is primarily generated on the server, this is much faster too. We have implemented this "client stuff optionally running on the server" in #4065. We need to use the same configuration approach used there. I don't know that we need to use the same technical redirection approach but we can do that too if it makes sense.

It is "everything logs on the server" in one destination with #5703. It's probably not the same configuration approach. It's state sync. What is the downside?

The issue is related to LOG-MANAGER where the 4GL code (or via command line) the customer can specify a client-side filename and they do this today in OE. The OE client is sometimes on the same system as a server process (e.g. appserver/REST/SOAP cases) but otherwise the client may be on a completely different system. In FWD, we allow this remote client case for when it is needed but we also try to move as much to the server, when possible.

What I've been trying to say, unsuccessfully, is that in a perfect world we would want to be able to do the logging on the server-side but in some customer cases the file will really need to be on the client side. This means we implement both approaches and allow them to be configurable so that whenever possible we can get the faster servers-side logging. The assumption here is that most LOG-MANAGER records will be generated on the server rather than the client. The state sync is just a way to avoid up calls for every log message, so it is just an optimization. And state sync can be used in 2 directions. No matter whether we implement the actual output on the client or on the server, we can gather changes on "remote side" and use state sync to get the content to the "output side".

Since this is related to LOG-MANAGER and we just implemented support for LOG-MANAGER to target a separate file, we can do a 2nd phase to implement the configurable client vs server output.

Constantin: Do you see a problem with that plan?

Greg Shah wrote:

Since this is related to LOG-MANAGER

What about FWD logging for these remote clients?

If you are talking about the output redirect, that would remain on the client side.

Is it separate from the "server log"? If so, I think it is OK. This is the replacement for the old stderr output and if it is unique to a client instance, then it won't be intermixed and thus it will be easy to correlate and use for debugging.

Greg Shah wrote:

Is it separate from the "server log"? If so, I think it is OK. This is the replacement for the old stderr output and if it is unique to a client instance, then it won't be intermixed and thus it will be easy to correlate and use for debugging.

No, it's just an excerpt from the "server log" that you wanted to have all client logs mixed in.

you wanted to have all client logs mixed in.

I don't recall wanting that.

If I remember correctly the whole point of the task was to reduce the number of log files by merging them. I initially opposed, believing that standard logging is every process to have its own file.

Galya Bogdanova wrote:

If I remember correctly the whole point of the task was to reduce the number of log files by merging them. I initially opposed, believing that standard logging is every process to have its own file.

Not exactly. One objective was to see if there were some opportunities to merge things together. Merging the FWD client logs with the FWD server logs is not one of the opportunities that I was envisioning.

I do think we need to separate these. If I gave a different impression at some point in our discussion, I apologize but that was not my intention. If we dump all these client logs into the server, it will be a mess. Debugging will mostly be harder.

On 7th Feb

1. #5703#note-23

Greg Shah said:

1. I don't think we want a separate client and server logging infrastucture. The fact that we have a separation of client and server is an internal implementation detail of FWD but it doesn't match the OE approach. I don't want our logging to make this implementation detail visible. I think this means we have to forward the log output to a single destination instead of having 2 desstinations.

2. I oppose in #5703#note-24:

Galya Bogdanova said:

In terms of code nothing will be different between the two, so no separate infrastructure. It is a matter only of configuration incl. destination. Client and server are different processes, so Logger will have different instances anyways and it can have different configurations. Actually I don't mind merging fileLevel and consoleLevel for both. But let's discuss the file destination. Currently there are several client log files that are independent of the server log files, that's why I didn't consider it ground breaking to leave two separate files - one for the client and one for the server.
Also there are certain classes shared between the client and the server and having only one log file may make it difficult to debug where the log comes from.

3. In #5703#note-26 I remind you to confirm this ground-breaking requirement of merging files.

Galya Bogdanova said:

Back to question 1: clients are separate processes started with different process ids and user ids - do we want their logs mixed in one file?

4. In #5703#note-27
Greg Shah said:

"everything logs on the server"
We can use our StateSynchronizer

Then
5. From 10th Feb to 23rd March in the status report 5703 todo list I had the point add client pid / server mark in each log record to distinguish the source; based on the

6. On 10th March I said in the status report:

I started merging server/client logs and created a new interface for rpc.

7. Later switched to StateSynchronizer

1. LOG-MANAGER logging
   • this is the legacy application logging, does not include FWD runtime Java logging for misc messages
   • log records for this type of logging can be generated by either the FWD server or FWD client. In both cases, they need to end up on the LOG-MANAGER's log file
   • currently, these log records are written on the FWD server side. This was mentioned in #5753-148: it will pose problems for remote clients or any other case where the FWD server doesn't have access to the location where this file needs to be created, as the application may assume the logging must be done using the FWD client's rights.
2. FWD runtime logging on server-side (this includes STDOUT or STDERR being written to logs)
   • this is everything written to server.log (or stdout.log, previously)
3. FWD runtime logging on client-side (this includes STDERR being written to logs)
   • with this task, now all log records are transferred to the FWD server, and written to server.log

• by default, FWD client logs to its own log files
• allow a flag to dump everything to the server log (or maybe only for some clients?)
• some other approach?

There is also #5703-263 which relates to the 'pid' dependency on libp2j.so for FWD server.

In regard to all the communications noted in #5703-280, I never intended to have the client logging go into the server log. Just because we output our FWD logging on the server does not mean it is mixed together into a single server log.

by default, FWD client logs to its own log files

Do we ever need the client logs mixed into the server logs? I'm not sure, but I know that certainly by default each client's logging should be separate. I think we are OK for now to not even give an option to merge it all into the server log, since I really don't know of a specific customer that would want it.

Please address these items before the code can be merged to trunk:

• Split client logging into its own log file instead of the shared server log.
• Handle the pid dependency of #5703-263.

Greg Shah wrote:

by default, FWD client logs to its own log files

Do we ever need the client logs mixed into the server logs? I'm not sure, but I know that certainly by default each client's logging should be separate. I think we are OK for now to not even give an option to merge it all into the server log, since I really don't know of a specific customer that would want it.

The only issue I had when investigating logs was 'mapping' a server.log line with a certain client log file, which sometimes was difficult (i.e. rely on the timestamp of the logs). If we can add a marker common to both the log records in the server.log file and the FWD client log file name (or the log records), then this will help a lot. I'm thinking the FWD client PID to be common for both server.log and client_%PID.log filename (or the log records).

I feel I still don't understand something:

1. What do I use state sync for, when the client and server loggers are separate?
2. How do I get pid without loading the native library every time on server launch?

Greg Shah wrote:

• server-side logging is configured
  • this would be configured similar to the rest of #4065
  • client-generated output is forwarded to the server
  • this is not compatible with the OE approach but for the majority of output it is likely the fastest approach so we want to use this when possible

Galya Bogdanova wrote:

I feel I still don't understand something:

1. What do I use state sync for, when the client and server loggers are separate?

State sync I not needed if the client does not transfer the log records to the server.

2. How do I get pid without loading the native library every time on server launch?

I think the solution here is to have the native library dependency only if the pid is used in the log name. If pid is needed, load the library; is OK to abend the server startup if it can't be found, as it needs to be configured - just make sure the exception contains a message that the library needs to be loaded because of the pid dependency.

Greg Shah wrote:

Galya Bogdanova wrote:

The current design is that client and server logging levels are independent, so that the client doesn't have to read directory.xml and can filter out logs on its own instead of syncing tons of debug logs with the server. Adding more logger levels to directory configs will affect only server-side. Are we ok with it?

No, we do want to be able to define the logger levels for the client in the directory. Our approach is always to minimize the amount of client-side configuration and scripting while maximizing the ability of controlling things from the server side. That reduced admin effort and complexity of deployment.

Since we just removed the client-side configurations for logging I guess I have to introduce some back. Do we still want to keep the server sync for logging levels and only configure log file in the client configs?

Greg, I'll wait for your confirmation.

Constantin Asofiei wrote:

Galya Bogdanova wrote:

I feel I still don't understand something:

1. What do I use state sync for, when the client and server loggers are separate?

State sync I not needed if the client does not transfer the log records to the server.

The question is: Do I remove all client to server log writes?

Galya Bogdanova wrote:

Since we just removed the client-side configurations for logging I guess I have to introduce some back. Do we still want to keep the server sync for logging levels and only configure log file in the client configs?

Basically, if you don't have access to the server and you need log files locally, do you still depend on the server admin to decide your client logging levels?

Do I remove all client to server log writes?

No. The idea is that there are 2 modes for logging: server-side and client-side. The state sync is used when server-side mode is used.

if you don't have access to the server and you need log files locally, do you still depend on the server admin to decide your client logging levels?

Yes, however we will also provide the bootstrap cfg overrides.

Greg Shah wrote:

The idea is that there are 2 modes for logging: server-side and client-side.

How do I know if the client is local or remote?

Yes, however we will also provide the bootstrap cfg overrides.

The client.xml logging level configs will override the server ones? But the server ones are dynamic. How does this work?

Galya Bogdanova wrote:

Greg Shah wrote:

The idea is that there are 2 modes for logging: server-side and client-side.

How do I know if the client is local or remote?

Actually this was a question for #5753 / #7291. For #5703 I think we decided it's a mess to mix client logs with server logs, so we remove any client to server writes.

Am I correct?

Actually if it was a new software (more web oriented) that was developed, I would suggest if customers want to use remote clients, to enable cloud logging and we can integrate it with some providers or even offer it in some sort of system admin menu in FWD, so that it's all logged on the server, but they still have access to it.

The idea is that there are 2 modes for logging: server-side and client-side.

How do I know if the client is local or remote?

Use the same configuration mechanism as #4065.

Yes, however we will also provide the bootstrap cfg overrides.

The client.xml logging level configs will override the server ones? But the server ones are dynamic. How does this work?

This is the same as would happen with the 4GL command line parameters -logentrytypes, -logginglevel and so forth. Specifying the corresponding values in the bootstrap cfg means we must pass these through in the ClientParameters and apply them on the server side.

For #5703 I think we decided it's a mess to mix client logs with server logs, so we remove any client to server writes.

No. When server-side logging is defined, we just output the client logs on the server but to a session-specific log file instead of the server log.

Greg Shah wrote:

The client.xml logging level configs will override the server ones? But the server ones are dynamic. How does this work?

This is the same as would happen with the 4GL command line parameters -logentrytypes, -logginglevel and so forth. Specifying the corresponding values in the bootstrap cfg means we must pass these through in the ClientParameters and apply them on the server side.

It's not the same, because you can set multiple logging levels in the client configs and then change them programmatically on the client in the FWD code, while in LOG-MANAGER there is only one logging level and it can be changed only on the server (the conversation thread).

For #5703 I think we decided it's a mess to mix client logs with server logs, so we remove any client to server writes.

No. When server-side logging is defined, we just output the client logs on the server but to a session-specific log file instead of the server log.

All clients to one log file on the server or each client in its individual log file?

OK, so implement context-local CentralLogger, configured by directory.xml, but with initial overrides from client.xml (root and any other logger), disable dynamic levels on the client, allow them on the server, but they will not be global, because they will take effect only on the specific context. So any static initializers setting levels will work once for the lifespan of the server JVM and it will be not 100% clear on which context they are executed.

Am I getting somewhere?

It's not the same, because you can set multiple logging levels in the client configs and then change them programmatically on the client in the FWD code, while in LOG-MANAGER there is only one logging level and it can be changed only on the server (the conversation thread).

I'm only referring to the LOG-MANAGER command line parameter replacements. The internal FWD logging would not be overridden by the client, it would only come from the server.

each client in its individual log file?

This one.

so implement context-local CentralLogger, configured by directory.xml

Yes

but with initial overrides from client.xml (root and any other logger)

No, this is only for the LOG-MANAGER feature.

disable dynamic levels on the client

No, I don't think we need to do that.

allow them on the server, but they will not be global, because they will take effect only on the specific context

Yes

So any static initializers setting levels will work once for the lifespan of the server JVM and it will be not 100% clear on which context they are executed.

I'm not sure what you mean by this.

, allow them on the server, but they will not be global, because they will take effect only on the specific context

Greg Shah wrote:

So any static initializers setting levels will work once for the lifespan of the server JVM and it will be not 100% clear on which context they are executed.

I'm not sure what you mean by this.

, allow them on the server, but they will not be global, because they will take effect only on the specific context

I've seen code like this:

class RandomNotRelated
{
   CentralLogger LOG = CentralLogger.get(RandomNotRelated.class);

   static {
      LOG.setLevel(iKnowBetterThanConfigs);
   }

}

This will be executed the first time the class is accessed, RandomNotRelated is not ContextLocal, so it will execute on whatever context it's first accessed and will set the level only there, but the developer will imagine he did it to all cases.

Greg Shah wrote:

disable dynamic levels on the client

No, I don't think we need to do that.

So allow dynamic logging levels two-way?

At this time we assume that the same logging levels will apply to all contexts. Even in the future where we have implemented #1848, it still may be server-wide.

I don't know that we care about per-context logging levels EXCEPT for the LOG-MANAGER stuff. In the FWD logging we have no existing requirements for per-context logging.

Galya Bogdanova wrote:

Greg Shah wrote:

disable dynamic levels on the client

No, I don't think we need to do that.

So allow dynamic logging levels two-way?

What do you mean by dynamic logging levels?

Greg Shah wrote:

What do you mean by dynamic logging levels?

LOG.setLevel() called programmatically.

Greg Shah wrote:

I don't know that we care about per-context logging levels EXCEPT for the LOG-MANAGER stuff. In the FWD logging we have no existing requirements for per-context logging.

So there will be no config overrides for FWD logging levels?

P.S. wrong quote. Fixed it.

I don't know that we care about per-context logging levels EXCEPT for the LOG-MANAGER stuff. In the FWD logging we have no existing requirements for per-context logging.

So there will be no config overrides for FWD logging levels?

Correct

And what do we do with the dynamic levels that can be set server-side and client-side in the code at any time?

What do you mean by dynamic logging levels?

LOG.setLevel() called programmatically.

Leave this alone unless there is a reason to do otherwise. I expected #1848 to implement an admin interface and proper listeners/notifications for modifying levels dynamically. I did not plan for #5703 to implement this. Anything you've done can remain unless there is a reason to make a change.

And what do we do with the dynamic levels that can be set server-side and client-side in the code at any time?

Where is this done?

Greg Shah wrote:

What do you mean by dynamic logging levels?

LOG.setLevel() called programmatically.

Leave this alone unless there is a reason to do otherwise. I expected #1848 to implement an admin interface and proper listeners/notifications for modifying levels dynamically. I did not plan for #5703 to implement this. Anything you've done can remain unless there is a reason to make a change.

I haven't done it by my design, it was already there and used.

Is there a reason to change it right now?

Greg Shah wrote:

Is there a reason to change it right now?

Yes, the logger is now distributed. I need to know what to sync and how.

Unexpected behavior - isn't it a definition of a bug. If it's not defined, it will be unexpected -> bug.

I would recommend disabling setLevel for now, if we're not clear how this should work out. It's messy even with one process.

Where is it used today?

Greg Shah wrote:

Where is it used today?

On trunk AdminServerImpl -> LOG.setLevel(Level.FINER); and and SecurityManager -> LOG.setLevel(debugLevel).

Tomorrow it might be used somewhere else, if not disabled.

The question is do we keep it part of the interface of the logger.

Where is it used today?

On trunk AdminServerImpl -> LOG.setLevel(Level.FINER); and and SecurityManager -> LOG.setLevel(debugLevel).

Neither of these is dynamic. One is hard coded in the source and the other is read from the directory and only ever set once. I don't see a reason to change them at this moment.

Greg Shah wrote:

Neither of these is dynamic. One is hard coded in the source and the other is read from the directory and only ever set once. I don't see a reason to change them at this moment.

Maybe I wasn't very clear. It's dynamic in that it can be set after the initialization of the logger, which means it doesn't come with the configs, but later. A level can be be set server-side or client-side. It can be dynamic. It might not be at the moment in it's full sense of dynamicity... so just pretend I don't see it? Ok...

The two cases are exclusively server-side and only occur at the very initialization of the logger. The SM case is driven by configuration and we haven't decided whether to unify it or not. There is a good reason to keep it separated (security features need to be managed by admins with higher privilege) which is a similar case for how we handle auditing support. On the other hand, it makes the solution more complex which I don't like but probably have to live with.

I think these two items can be handled when we implement #1848.

I remember there was a mention of client permissions in the context of remote clients. What about local clients, isn't it the same? The client might be able to write to the place it defines in bootstrap configs, but the server, not?

Galya Bogdanova wrote:

I remember there was a mention of client permissions in the context of remote clients. What about local clients, isn't it the same? The client might be able to write to the place it defines in bootstrap configs, but the server, not?

Permissions are always an issue in client scenarios, remote or local. The client must have proper permissions for the file system and if the client and server are on the same system, the permissions for a given location may differ since the FWD server OS account really should be different from the FWD client OS account (for security purposes).

Greg Shah wrote:

Permissions are always an issue in client scenarios, remote or local. The client must have proper permissions for the file system and if the client and server are on the same system, the permissions for a given location may differ since the FWD server OS account really should be different from the FWD client OS account (for security purposes).

Then in what cases is it appropriate to write client logs from the server process?

I'm reading #4065 and the code. I believe the core concept is the only one relevant here. If I understand properly, client work should move to the server as much as possible. These TCP/IP proxies for remote clients are hidden behind naming resources. But all of that will not introduce any performance improvements. Actually for logging, that would be extra network calls, if only the server should know how to write to files and the logs and file system are on the client. But it could be excusable, if the end goal is merging the client and server at some point (when all this complexity will get redundant).

Logging doesn't need native library calls, so we already have in place the infrastructure of RPC interfaces with their network implementations, that could be expanded to share file system checks. The whole abstraction of OS resources seems irrelevant to logging and I don't see its performance benefit. Also multiple times configuration was mentioned. The only configuration I see in #4065 is hardcoded configs in directory.xml, that enable those abstract resources on the server-side.

You need to excuse my ignorance, but none of it makes sense in the context of logging.

• the same number of files in comparison to the initial state of the system
• substantial complexity introduced in the code (in a naturally simple feature as logging)
• more redundancy with all kinds of network calls

Since there is no merging of client and server files in any of the supported cases, I want to present a well-rounded solution:
- client and server processes write their own log files;
- client has its own bootstrap configs for log file destination and rotation, receives directory.xml logger levels to get logging initialized;
- there is no sync of logs between client and server
- there is logging levels invalidation from the server to the clients, when levels get changed

All the enhancements to logging already introduced will still be available like:
- unified interface for logging
- logger instances consistent GC and restoration
- clear and timely init points and no logs missing (by introducing pre-init buffers and many related changes)
- improved logging context allowing logs to be matched between server and clients
- support for class loader logs
- redundant logging libraries cleaned up
- single format for all output with the single formatter and the slf4j implementation
- unified logging level configs
- many more...

Permissions are always an issue in client scenarios, remote or local. The client must have proper permissions for the file system and if the client and server are on the same system, the permissions for a given location may differ since the FWD server OS account really should be different from the FWD client OS account (for security purposes).

Then in what cases is it appropriate to write client logs from the server process?

When the admin has defined it to work that way. In other words, when they activate server-side logging by configuring it in the directory. That means they are accepting that the logs will move to the server and that the server process will be writing them.

But all of that will not introduce any performance improvements. Actually for logging, that would be extra network calls, if only the server should know how to write to files and the logs and file system are on the client.

I don't understand your point here. For any LOG-MANAGER usage, if configured as server-side logging, then there will be a savings since we don't have to down-call to write the logs.

Client-side logging (when used) is compatible with the 4GL and also is certainly slower than server-side logging since it would require a network round trip. That is why we have been implementing #4065, so that things which can be safely moved to the server will have a much faster implementation. Logging is just one more "resource" which we are trying to move to the server when possible. But as noted above, it is not always possible.

Let's put LOG-MANAGER aside and discuss it in #7291.

Why do we need to write client logs from the server for FWD logs - client logs are generated on the client and server logs on the server and both should not be mixed in the same file as stated in #5703#note-283. Also clients have different permissions. What would be the reason to make round trips to the server or form the server?

Why do we need to write client logs from the server for FWD logs - client logs are generated on the client and server logs on the server and both should not be mixed in the same file as stated in #5703#note-283.

When we are configured for server-side logging, it no longer makes sense for there to be a separate FWD client log on the client side. The admin will expect all the logging to be on the server.

Also clients have different permissions.

In server-side logging, the admin has already determined that this is not an issue.

What would be the reason to make round trips to the server or form the server?

In server-side logging, since we use state sync, there are no extra round trips from the client to the server to write FWD client logging output, right?

And when server-side logging is active, there are no down-calls from the server to the client to write logs because we are writing everyting on the server.

Only in the client-side logging case should we get extra down calls.

Greg Shah wrote:

When we are configured for server-side logging, it no longer makes sense for there to be a separate FWD client log on the client side. The admin will expect all the logging to be on the server.

So the admin can put a flag in directory.xml saying "I don't care about any remote clients, that want to write to their local folders. All is written on the server no matter where it comes from"? Basically what it does is to disable client host logging?

In server-side logging, since we use state sync, there are no extra round trips from the client to the server to write FWD client logging output, right?

So the server never uses the resource on the client with server-side logging enabled by a flag in directory.xml?

Then client-side logging is the absence of the flag in directory.xml and it doesn't matter if it's a local or remote client, it should do it's own logging, while the server does its own thing?

When we are configured for server-side logging, it no longer makes sense for there to be a separate FWD client log on the client side. The admin will expect all the logging to be on the server.

So the admin can put a flag in directory.xml saying "I don't care about any remote clients, that want to write to their local folders. All is written on the server no matter where it comes from"? Basically what it does is to disable client host logging?

Roughly, yes. Since it is the admin who sets up and controls the installation, it is not so much the remote clients that "want to write to their local folders" as it is "I've determined that it is safe to use server-side logging".

Over time, we expect that the FWD client logging will become greatly reduced as bugs are fixed and other support implemented such that we don't see any severe issues that need to be reported on the client's health. The logging that is generated by the server side will become the most important aspect of logging.

In server-side logging, since we use state sync, there are no extra round trips from the client to the server to write FWD client logging output, right?

So the server never uses the resource on the client with server-side logging enabled by a flag in directory.xml?

Yes

Then client-side logging is the absence of the flag in directory.xml and it doesn't matter if it's a local or remote client, it should do it's own logging, while the server does its own thing?

Kind of. The server will need to write LOG-MANAGER output to the client side but otherwise yes.

• there is a directory.xml flag logging/serverSide by default false (when missing)
• client logging get initialized by the server (as it does in the latest 5703a revision) and receives the flag
• if serverSide is true, the clients sync logs with the server as they do in the current implementation (the current CentralLoggerClient)
• if serverSide is false, the clients write their own log files (I'll introduce the CentralLoggerRemoteClient that reuses some of the CentralLoggerServer logic)

And this should fulfill the requirements.

Also when server-side enabled I have to fix it to produce separate files by generating them dynamically based on some default pattern.

Good

In regard to the AdminServerImpl use of LOG.setLevel(Level.FINER);, I think it should be deleted. There is no reason to hard code it there.

The SecurityManager usage should not be changed.

Can someone give me an example of access rights expressions (refs com.goldencode.p2j.security.VariablePool)? getRequestedDebugLevel doesn't have a direct ref, is it used with reflection?

Using Expressions in Access Rights

Since the only security issue here is related to log file output, I think the danger is quite limited. Rather than hold this up for the security changes, I'd prefer to defer them.

In regard to how the security changes might look, 4065a has examples of the needed changes. In fact, some of that filesytem-related code probably needs to be used for this solution as well, so it is better if we work this part after 4065a gets merged.

Constatin: Please review the latest 5703a.

• Its custom levels are one to one mapping to java levels, so it was an obvious transition.

• The client bootstrap logging:debug:enable is no longer a valid config, so it's removed.
• Server-side directory.xml security/config/debug-level is replaced by logging/levels/com.goldencode.p2j.security.SecurityManager.

I need to add back the default level of WARNING. Done in r14606. The custom logging methods are replaced with standard ones, but the end result is the same. Even improved with Constantin's request to wrap all FINER logs with a check if loggable, so the string pool will be spared.

I've completed all that was on my mind with this task. Today I added some final touch-ups to the yesterday's changes and did some testing. So I'll be waiting for the code review.

I'm trying to run hotel-gui with 5703a, but I'm getting different exceptions. On ant deploy.all:

     [java] ThreadName:main | FAILURE in tryLoadClass()
     [java] java.lang.RuntimeException: Cannot find class/interface IF in PROPATH.
     [java]     at com.goldencode.p2j.uast.SymbolResolver.reportClassNotFound(SymbolResolver.java:9855)

It's not my first time running the app, but every time I encounter different issues. The only clue I found in Redmine is related to importing skeleton, but Hotel gui doesn't have it.

With a certain customer project I got another one, when running the server:

23/05/04 10:36:21.084+0300 | WARNING | com.mchange.v2.resourcepool.BasicResourcePool | ThreadName:C3P0PooledConnectionPoolManager[identityToken->z8kfsxav1rqap53t4zw6x|7c5dbca5]-HelperThread-#1 | com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@472b38a4 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: 
org.h2.jdbc.JdbcSQLNonTransientConnectionException: Unsupported connection setting "RTRIM" [90113-200]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:622)
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
    at org.h2.message.DbException.get(DbException.java:205)
    at org.h2.message.DbException.get(DbException.java:181)
    at org.h2.engine.ConnectionInfo.readSettingsFromURL(ConnectionInfo.java:269)
    at org.h2.engine.ConnectionInfo.<init>(ConnectionInfo.java:78)
    at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:158)
    at org.h2.Driver.connect(Driver.java:69)
    at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:175)
    at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:220)
    at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203)
    at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1138)
    at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1125)
    at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44)
    at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1870)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)

that causes:

23/05/04 10:36:21.085+0300 | SEVERE  | com.goldencode.p2j.main.CommonDriver | ThreadName:main, Session:00000000, Thread:00000001, User:standard | System exits with code -13 caused by:
com.goldencode.p2j.cfg.ConfigurationException:  Initialization failure
    at com.goldencode.p2j.main.StandardServer.hookInitialize(StandardServer.java:2183)

So no testing today.

Galya Bogdanova wrote:

I'm trying to run hotel-gui with 5703a, but I'm getting different exceptions. On ant deploy.all:

[...]

It's not my first time running the app, but every time I encounter different issues. The only clue I found in Redmine is related to importing skeleton, but Hotel gui doesn't have it.

Are you saying that it fails differently each time you run ant deploy.all with the current version of 5703a?

org.h2.jdbc.JdbcSQLNonTransientConnectionException: Unsupported connection setting "RTRIM" [90113-200]

One quick thing to check is that there is only one H2 jar deployed. We recently made changes in how H2 processes RTRIM and mismatching jars with the FWD code is not good.

Greg Shah wrote:

Are you saying that it fails differently each time you run ant deploy.all with the current version of 5703a?

No, actually I as trying to fix an SQL issue first and on redeploy this one appeared.

We recently made changes in how H2 processes RTRIM and mismatching jars with the FWD code is not good.

This should be it.

I'll have to rebase to test with the customer project according to #7143#note-137, so I'll be waiting for the final review.

I can still test with hotel gui if Cannot find class/interface IF in PROPATH. is resolved somehow.

• NIONetSocket - please add the if (isFineLoggable) condition to the previous tracef messages
• ChuiOutputManager.box - enclose the message in a if (LOG.isLoggable(Level.FINER))
• ProcessBuilderParameters - there is a TODO in getOutputToFile
• CentralLogFormatter.describeContext - I would rather ensure that all logging from NetSocket (and maybe others?) which can deadlock will, pass a flag like 'don't resolve context', than relying on the current stacktrace to see if we are in NetSocket class. This is very expensive.
• CentralLogger.setLevel - shouldn't excludeSecurityManagerContext @CACHED_LOGGER_NAME_LEVELS be invalidated for all its children?
• the support for logging/loggers configuration was renamed to logging/levels?

There are some inconsistencies with the logging in the Socket classes.

public interface NetSocket
{
   /** Trace network operations' flag */
   static final boolean TRACE = LOG.isLoggable(Level.FINEST);

   NetSocketFactory FACTORY = new NetSocketFactory()
   {
      public NetSocket create(Socket socket) throws IOException
      {
         NetSocket ns = new NetSocketWrapper(socket);
         return TRACE ? new LoggingNetSocket(ns) : ns;
      }
   }

   default void traceln(String message)
   {
      if (LOG.isLoggable(Level.FINER))
      {
         LOG.log(Level.FINER,
               String.format("%s: %s\n", Thread.currentThread().getName(), message));
      }
   }
}

NetSocket instantiates LoggingNetSocket as a wrapper when Level.FINEST is loggable, but LoggingNetSocket is logging all its messages using NetSocket.traceln(String) on Level.FINER. I think the definition of TRACE got lost between developers.

What do you think is the proper level of trace and LoggingNetSocket? I think the lowest FINEST is probably better suited, since that is when the wrapper gets instantiated and it doesn't make sense if it logs everything on a higher level.

Code review requests applied with 5703a r14625 and r14626:

• NIONetSocket checks for loggable before each log statement, except the last one where no concatenation / formatting is applied and an external log method wrapper is used with its own check. Sockets TRACE made to be Level.FINEST consistently.
• ChuiOutputManager.box isLoggable check added.
• ProcessBuilderParameters TODO removed as not valid, actually the client can't read from the server right away, since the session is still not open, when outputToFile needs to be created (as early as possible).
• excludeSecurityManagerContext removed and replaced by a flag to logger instance creation called excludeSMContext that is true for all Sockets. I've tested this one quite well a few months ago and I can only hope I don't miss anything retesting it in the last minute. It can be a critical bug.
• Invalidation on CentralLogger.setLevel was missing server-side indeed, added.
• logging/levels renamed to logging/loggers - it was evolving on its own, but ended up being the same thing, so it's best to keep the old name.

I added another improvement on my own: CentralLogFormatter to support any number of Formatter date time specifiers anywhere in the filePath (it was originally limited to one place in brackets). Now there is the freedom to use it in path definition as well to create folders based on datetime:

        <node class="container" name="logging">
          <node class="container" name="file">
            <node class="string" name="path">
              <node-attribute name="value" value="logs/%tY/%tB/%td/fwd_%tH-%tM-%tS_%g.log"/>
            </node>
          </node>
        </node>

This path will create deploy/server/logs/2023/May/08/fwd_11-48-40_0.log.

What do you think is the proper level of trace and LoggingNetSocket? I think the lowest FINEST is probably better suited, since that is when the wrapper gets instantiated and it doesn't make sense if it logs everything on a higher level.

Agreed.

Galya, I think just some tests to see that appserver/batch/UI client work OK, in both nio and non-nio SSL, should be enough.

If all is good, we can put this in the queue to merge to trunk.

Constantin Asofiei wrote:

Galya, I think just some tests to see that appserver/batch/UI client work OK, in both nio and non-nio SSL, should be enough.

What was the trick to enable / disable nio socket?

• server.sh for FWD server startup
• client.sh or other script to launch individual clients
• in directory, in clientConfig/cfgOverrides

A few more classes (e.g. SSL, BlockingSSL) had to exclude SecurityManager context. Now the tests pass for net:socket:nio=true.

1. (This should be expected, just to keep it in mind) The appserver client now creates a separate log file, while I believe in the past these logs were part of the server.log. It goes to the client folder (workingDir), probably that is the launch dir for appserver.
2. The server should invalidate the log levels on all clients on a server-side change in levels. But CentralLoggerServer doesn't keep a reference to all active ClientExports, so currently it sends a call only to one client - the one associated with LogicalTerminal.getInstance() from the current context. We can fix it in #1848 if you're ok to delay proper dynamic log levels support.

Please advise on the above.

Galya Bogdanova wrote:

(This should be expected, just to keep it in mind) The appserver client now creates a separate log file, while I believe in the past these logs were part of the server.log. It goes to the client folder (workingDir), probably that is the launch dir for appserver.

Oh, I actually forgot the most important here. Since appserver client doesn't do state sync, the whole file is dumped at the end of the server life (on application exit).

Galya Bogdanova wrote:

Galya Bogdanova wrote:

(This should be expected, just to keep it in mind) The appserver client now creates a separate log file, while I believe in the past these logs were part of the server.log. It goes to the client folder (workingDir), probably that is the launch dir for appserver.

Oh, I actually forgot the most important here. Since appserver client doesn't do state sync, the whole file is dumped at the end of the server life (on application exit).

I don't understand - are you saying that you don't see the log messages until the appserver is terminated?

Constantin Asofiei wrote:

I don't understand - are you saying that you don't see the log messages until the appserver is terminated?

Ops, sorry for the scare. I was imagining things with the help of a delayed file sync in the IDE. It seems there is state sync. The file is produced on time. The first statements about appserver are still valid though.

I'm very confused from the whole logging epic. If you check how the Global Lifecycle section in Logs ended up being, you'll catch a glimpse of why that is.

What was originally server.log and System.err redirects on the clients, now is living on its own and adding that many more new files. And I realized that we don't have configurations for the log file names on the clients. The directory.xml "logging" section is the only relevant config for the loggers as of now and there are some hardcoded defaults.

Greg Shah said (in #5703#note-171):

There is also the logging:file:namePrefix config in the new approach.

This is no longer needed. I think that we would have a directory entry that allows the spec to be provided. It is OK to add a bootstrap cfg value as an override.

That's when the client configs support was removed.
Do we need it back in the logging:file:path variation?

There is a hard-coded default now for clients fwd_client_" + SORTABLE_DATETIME_FORMAT + "_" + "%uos_%pid_%uf_%g.log. But I don't understand how one entry in directory.xml configured by the admin will be sufficient to handle all clients if he decides to go with "client.log".

Also it needs to be path for client-side logging and a name for server-side logging. Another funky aspect.

(This should be expected, just to keep it in mind) The appserver client now creates a separate log file, while I believe in the past these logs were part of the server.log. It goes to the client folder (workingDir), probably that is the launch dir for appserver.

This is OK for now and some customers may even prefer it. But this is a deviation from the OE approach and we will need to resolve it in another task. Please create a task for this. See #5703-89 and surrounding notes.

The server should invalidate the log levels on all clients on a server-side change in levels. But CentralLoggerServer doesn't keep a reference to all active ClientExports, so currently it sends a call only to one client - the one associated with LogicalTerminal.getInstance() from the current context. We can fix it in #1848 if you're ok to delay proper dynamic log levels support.

Dynamic log levels was always expected to be worked in #1848, not here. That hasn't changed.

And I realized that we don't have configurations for the log file names on the clients.

Are you saying that we don't upcall to determine the log file names when logging on the client?

Greg Shah wrote:

(This should be expected, just to keep it in mind) The appserver client now creates a separate log file, while I believe in the past these logs were part of the server.log. It goes to the client folder (workingDir), probably that is the launch dir for appserver.

This is OK for now and some customers may even prefer it. But this is a deviation from the OE approach and we will need to resolve it in another task. Please create a task for this. See #5703-89 and surrounding notes.

What do you mean by deviation from OE? LOG-MANAGER creates one log file with OE messages for appserver. FWD now creates one as well. It's for the whole life of the server. Exactly the same. Of course there might be related logs server-side as well. But that is how FWD works with all its clients.

Dynamic log levels was always expected to be worked in #1848, not here. That hasn't changed.

I wasn't implementing dynamic levels here, but replacing the basic java logger functionality, somewhat improved and enhanced. It has always been possible with some caveats before.

Are you saying that we don't upcall to determine the log file names when logging on the client?

Client file names are hard-coded default. There is only the server file log config in directory.xml. Remember that I've just split the files. The question is how this is supposed to work.

I was wrong about the appserver. Actually we had that as another log file from stderr (currently on trunk it's %type%_%user%_%date%.log), which is now replaced by CentralLogger.

Greg, then I'll be waiting for your feedback on what client log file configs we want (#5703-360, #5703-361, #5703-362) to complete the task.

(This should be expected, just to keep it in mind) The appserver client now creates a separate log file, while I believe in the past these logs were part of the server.log. It goes to the client folder (workingDir), probably that is the launch dir for appserver.

This is OK for now and some customers may even prefer it. But this is a deviation from the OE approach and we will need to resolve it in another task. Please create a task for this. See #5703-89 and surrounding notes.

What do you mean by deviation from OE? LOG-MANAGER creates one log file with OE messages for appserver. FWD now creates one as well. It's for the whole life of the server. Exactly the same. Of course there might be related logs server-side as well. But that is how FWD works with all its clients.

In #5703-89 we aren't talking about LOG-MANAGER, we are talking about the implicit logfile that every appserver has. On OE, all of the agents log into one logfile per appserver. An appserver can be thought of as a collection of agents that share the same configuration and which handle RPC calls for the same appserver name.

There is a hard-coded default now for clients fwd_client_" + SORTABLE_DATETIME_FORMAT + "_" + "%uos_%pid_%uf_%g.log. But I don't understand how one entry in directory.xml configured by the admin will be sufficient to handle all clients if he decides to go with "client.log".

It won't work well, but so what? The admin needs to configure this thoughtfully. That is OK.

Client file names are hard-coded default. There is only the server file log config in directory.xml. Remember that I've just split the files. The question is how this is supposed to work.

As with nearly everything we configure, we expect there to be the following:

• A directory entry that allows configuration at multiple levels (group|account or global|server|group|account).
• A sensible default in the code that reads the directory.

For some items, where we know we want to expose more flexibility, we also provide a bootstrap cfg entry that is intended to override (take precedence over) the directory/default value.

Constantin Asofiei wrote:

What I found difficult with the current way is that each agent creates its own file, and when restarting the FWD server a lot, the log files add up.

I believe the new implementation won't create a separate file for each agent. Not sure how to test it.

Greg Shah wrote:

As with nearly everything we configure, we expect there to be the following:

• A directory entry that allows configuration at multiple levels (group|account or global|server|group|account).
• A sensible default in the code that reads the directory.

For some items, where we know we want to expose more flexibility, we also provide a bootstrap cfg entry that is intended to override (take precedence over) the directory/default value.

How do you expect client-side logging to be configured with this approach?

Galya, some notes related to client logs.

In appserver case, for OE/legacy output, FWD must allow to send all these logs to a single appserver log file. This includes LOG-MANAGER messages (Greg, LOG-MANAGER:WRITE-MESSAGE works in appserver, and it just uses this 'legacy log file'). The file is configured via client:cmd-line-option:clientlog, which for appservers (and Web clients) is set in clientConfig/cfgOverrides, in directory.xml.

For FWD error messages/debugging, this is a separate log file - which can remain as a single file per agent (or Web/GUI/ChUI clients). This is configured via client:logging:path, is optional, and defaults to CentralLogger.DEFAULT_CLIENT_FILE_NAME . I think this is what Greg mentions to be configured per each client, in directory.xml. Currently, we have the logging node, for which the lookup is done on a per-server basis (check the javadoc for Utils.findDirectoryNodePath, which is called in CentralLoggerServer.fromDirectory). Greg I think proposes for the log config lookup, in case of the FWD client logs, to be done on a per-account basis, so you can have a logging node under /server/default/runtime/<account>/logging, from which to configure the FWD client err/debug logging for this account. This can be done by passing scope = true for the Utils.findDirectoryNodePath call.

But, this poses a problem: we can't read this configuration until the FWD client has connected to the FWD server, and any log messages until then must be recorded and logged only after the configuration has finished. Once the server connection has been established, we can use a server API call to get this configuration, and after that override the configuration using any bootstrap config (like client:logging:path).

Constantin: Thanks for explaining it. You did better than me. :)

Constantin Asofiei wrote:

Greg I think proposes for the log config lookup, in case of the FWD client logs, to be done on a per-account basis, so you can have a logging node under /server/default/runtime/<account>/logging, from which to configure the FWD client err/debug logging for this account. This can be done by passing scope = true for the Utils.findDirectoryNodePath call.

• I'm not sure if Greg wants all logging configs to be available for each account. There is the path, but also rotation size and count?
• Also do we keep server/default/logging for file path for the server and rotation configs or this will be covered by the runtime configs?
• If server/default/logging is supposed to be fallback for runtime/account/logging? If yes, do we use the same pattern for the server and all clients log files?

But, this poses a problem: we can't read this configuration until the FWD client has connected to the FWD server, and any log messages until then must be recorded and logged only after the configuration has finished.

The logging levels come from directory.xml and the client doesn't start logging before the server sends the configs, so I'll be adding just another property.

My biggest concern would be if serverSide is false and the client should write to a path configured on the server...

Galya Bogdanova wrote:

My biggest concern would be if serverSide is false and the client should write to a path configured on the server...

For any path configured for a specific client is the responsibility of that admin to make sure that path is valid for that client. This includes remote clients, clients running under different OS accounts, the case when there is server-side logging for the FWD client, etc. I don't see something to worry here. We just need to validate that the FWD client can write on that path.

runtime/<account>/logging can this be used by the server account?

Galya Bogdanova wrote:

runtime/<account>/logging can this be used by the server account?

If you are referring for calls from CentralLoggerServer.fromDirectory, this will not be resolved by the FWD server context. This is meant only for FWD client contexts (on server-side).

Galya Bogdanova wrote:

• I'm not sure if Greg wants all logging configs to be available for each account. There is the path, but also rotation size and count?

I think the logging levels are global (can't be set for each account). Everything else can be specific to a client. Please remind me, for the FWD client side, how are the logging levels resolved?

• Also do we keep server/default/logging for file path for the server and rotation configs or this will be covered by the runtime configs?

The current approach for the CentralLoggerServer.fromDirectory is OK and can remain as is - this is how the FWD server is configured.

• If server/default/logging is supposed to be fallback for runtime/account/logging? If yes, do we use the same pattern for the server and all clients log files?

Correct - if no per-account config exist, FWD will naturally default to the 'per-server' config. Nothing to worry about here.

Constantin Asofiei wrote:

I think the logging levels are global (can't be set for each account). Everything else can be specific to a client. Please remind me, for the FWD client side, how are the logging levels resolved?

On LogicalTerminal.init the configs are sent from the server to ClientExports - currently includes the levels and the flag serverSide. We'll be adding now the file path and rotation size and count if resolved for the account or from server/default/logging, which means the hard-coded defaults will be unlikely to ever be used. Then the client will overwrite these configs with its own client.xml path and/or rotation configs. Does it sound right?

Soooo for serverSide logging, the client should send the configs to the server to overwrite directory.xml?

Constantin Asofiei wrote:

Galya Bogdanova wrote:

• If server/default/logging is supposed to be fallback for runtime/account/logging? If yes, do we use the same pattern for the server and all clients log files?

Correct - if no per-account config exist, FWD will naturally default to the 'per-server' config. Nothing to worry about here.

A caveat to this is the fact that client paths support more placeholders: Both server and client paths support date time, the default Formatter specifiers and the custom %pid, but clients have the additional "%uf (fwd user), %uos (OS user) and %as (appserver name).

We'll be adding now the file path and rotation size and count if resolved for the account or from server/default/logging, which means the hard-coded defaults will be unlikely to ever be used.

Optimally, these defaults would be set on the server side when the directory is queried for each value. Then you always at least get that default even if the directory has no configuration. And it is all in one location.

Then the client will overwrite these configs with its own client.xml path and/or rotation configs. Does it sound right?

Yes, but only if these were passed on the command line or added in a bootstrap cfg. In most cases these will not be present.

Both server and client paths support date time, the default Formatter specifiers and the custom %pid, but clients have the additional "%uf (fwd user), %uos (OS user) and %as (appserver name).

To the degree this stuff needs to be resolved on the server, we should send this information in the ClientParameters.

Greg Shah wrote:

Both server and client paths support date time, the default Formatter specifiers and the custom %pid, but clients have the additional "%uf (fwd user), %uos (OS user) and %as (appserver name).

To the degree this stuff needs to be resolved on the server, we should send this information in the ClientParameters.

I'm mentioning it, because both the server and client path can be read from the same config in default/logging if nothing else is defined. So if client placeholders are added at the moment they won't be resolved for the server file.

Move ClientParameters processing earlier in ClientCore.initialize().

Greg Shah wrote:

Move ClientParameters processing earlier in ClientCore.initialize().

Don't worry about the implementation details. It's not how it will be, because it is server-side driven. I'm asking only theoretically.

I'm asking about the logic of what is the expected behavior of the configs.

Client sessions, even when processed on the server-side, should support the same substitutions as if the processing happened on the client side.

Greg Shah wrote:

Client sessions, even when processed on the server-side, should support the same substitutions as if the processing happened on the client side.

Of course... Let me change the wording: If default/logging is used as a fallback / default for client file names and certain client supported placeholders are used in its definition, then the server log file won't have them resolved. Now that it's all so intertwined, I'll have to add some garbage code to deal with it, so no worries.

Also it means that there is no default fwd_server...log file ever, because the default constant that is a fallback for missing default/logging can be used for the clients as well. So no fwd_server...log ever except if we don't introduce a new placeholder called %a for type (since %t is date time specifier).

This is lovely. I can confirm that now we can configure logging everywhere in every way we like. :D

Default logging container in directory.xml, account logging container in directory.xml, clientConfig cfgOverrides in directory.xml, client bootstrap configs in xml or cmd line launching a client. Or no configs at all for peaceful mind. I think it was worthy of a ticket on its own. All of this supported with all specifiers / placeholders, both with server-side and client-side logging.

5703a r14630 is up for review.

• CentralLoggerServer.isLogicalTerminalInitialized and CentralLogger.invalidateLoggerTreeLevelCache - this is a question for #1848, but I think invalidateLoggerTreeLevelCache may need to go through all FWD client JVMs to push the new logging levels.
• CentralLoggerServer.initialize - in processIdSupplier lambda, enclose the code in a try/catch(Throwable) and show a meaningful message that the PID placeholder is configured in the log file name but the FWD p2j library can't be found. What I mean here is to avoid 'why did it crash' questions for missconfigurations - we need to make it obvious that this is a log filename configuration issue which requires p2j library to be available at the FWD server.

Constantin Asofiei wrote:

Review for 5703a/14630:

• CentralLoggerServer.isLogicalTerminalInitialized and CentralLogger.invalidateLoggerTreeLevelCache - this is a question for #1848, but I think invalidateLoggerTreeLevelCache may need to go through all FWD client JVMs to push the new logging levels.

Yes, but since we're not supporting dynamic levels yet, this should be fine for the time being. Basically the levels from the configs will be all present at the time of initialization of the clients (LogicalTerminal.init), so we should not expect the invalidation to be needed.

• CentralLoggerServer.initialize - in processIdSupplier lambda, enclose the code in a try/catch(Throwable) and show a meaningful message that the PID placeholder is configured in the log file name but the FWD p2j library can't be found. What I mean here is to avoid 'why did it crash' questions for missconfigurations - we need to make it obvious that this is a log filename configuration issue which requires p2j library to be available at the FWD server.

Error log added in r14631.

Galya Bogdanova wrote:

• CentralLoggerServer.initialize - in processIdSupplier lambda, enclose the code in a try/catch(Throwable) and show a meaningful message that the PID placeholder is configured in the log file name but the FWD p2j library can't be found. What I mean here is to avoid 'why did it crash' questions for missconfigurations - we need to make it obvious that this is a log filename configuration issue which requires p2j library to be available at the FWD server.

Error log added in r14631.

Thanks, looks good.

Galya: Starting tomorrow morning, trunk will be frozen for the day (or until you merge whichever is shortest). If something becomes more difficult than expected, let us know and we will adjustr the plan. You may start your merge process tomorrow, first thing.

• SQLStatementLogger logging to System.out;
• com.goldencode.p2j.oo.logging that can be integrated with LegacyLogManager (for example the enum in LegacyLogManagerImpl has the same values as LogLevelEnum).

Question: uast was identified as conversion package, where ConversionStatus should be used, but there is also com.goldencode.ast. Does the same apply for it? Also is com.goldencode.trpl considered a conversion package as well?

Galya Bogdanova wrote:

Question: uast was identified as conversion package, where ConversionStatus should be used, but there is also com.goldencode.ast. Does the same apply for it? Also is com.goldencode.trpl considered a conversion package as well?

uast, ast are all used in conversion; this includes standalone application conversion and conversion done at runtime by the FWD server.

Greg: is com.goldencode.trpl obsolete? I don't see it anywhere being used.

Is com.goldencode.expr also a conversion package?

Galya Bogdanova wrote:

Is com.goldencode.expr also a conversion package?

Yes

Even if com.goldencode.trpl is not used, I guess ConversionStatus will be more appropriate, so changing it.

Note: Decide what to do with com.goldencode.trace, LoggingAspect and LogExecution.

Hotel Gui throws build.xml:538: Warning: Could not find file adm_windows.json to copy. on ant jar deploy.prepare. And the file is indeed not in the repo:

gbb@gbb:~/secure/code/p2j_repo/samples/hotel_gui$ bzr log adm_windows.json
bzr: ERROR: Path unknown at end or start of revision range: adm_windows.json

TODO: add TransformDriver cmd line arg parsing to set the level of logging. Ref #7180.

Constantin, here it is, I am finally able to reproduce it on the client's project:

23/05/12 15:00:22.123+0300 | SEVERE  | com.goldencode.p2j.util.TransactionManager | ThreadName:Conversation, Session:0000000F, Thread:00000037, User:... | Abnormal end; original error:
java.lang.RuntimeException: invoke() of program Progress.Json.Objectmodel.JsonConstruct failed
    at com.goldencode.p2j.util.ControlFlowOps.invokeError(ControlFlowOps.java:8174)
    at com.goldencode.p2j.util.ControlFlowOps.initializeLegacyClass(ControlFlowOps.java:4795)
    at com.goldencode.p2j.util.ObjectOps.loadClassInt(ObjectOps.java:2576)
    at com.goldencode.p2j.util.ObjectOps.loadClassInt(ObjectOps.java:2559)
    at com.goldencode.p2j.util.ObjectOps.loadClass(ObjectOps.java:2514)
    at com.goldencode.p2j.util.ObjectOps.newInstanceInternal(ObjectOps.java:1214)
    at com.goldencode.p2j.util.ObjectOps.newInstance(ObjectOps.java:1148)
    at com.goldencode.p2j.util.ObjectOps.newInstance(ObjectOps.java:1127)
    at CLIENT_PACKAGE.src.sys.apps.Httpsocketwithjwt.lambda$createNewJwt$8(Httpsocketwithjwt.java:254)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.topLevelBlock(BlockManager.java:8504)
    at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:766)
    at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:739)
    at CLIENT_PACKAGE.src.sys.apps.Httpsocketwithjwt.createNewJwt(Httpsocketwithjwt.java:247)
    at CLIENT_PACKAGE.src.sys.apps.Httpsocketwithjwt.lambda$post$10(Httpsocketwithjwt.java:339)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.topLevelBlock(BlockManager.java:8504)
    at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:766)
    at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:739)
    at CLIENT_PACKAGE.src.sys.apps.Httpsocketwithjwt.post(Httpsocketwithjwt.java:326)
    at CLIENT_PACKAGE.src.sys.apps.Usermgtbase.lambda$callService$13(Usermgtbase.java:214)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.functionBlock(BlockManager.java:9448)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:1045)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:1013)
    at CLIENT_PACKAGE.src.sys.apps.Usermgtbase.callService(Usermgtbase.java:176)
    at CLIENT_PACKAGE.src.sys.apps.Licenseservice.lambda$getVmaLic$6(Licenseservice.java:151)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.functionBlock(BlockManager.java:9448)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:1045)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:1013)
    at CLIENT_PACKAGE.src.sys.apps.Licenseservice.getVmaLic(Licenseservice.java:91)
    at CLIENT_PACKAGE.src.sys.apps.Licentiemanager.lambda$fetchLicensesFromLicenseservice$5(Licentiemanager.java:78)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.functionBlock(BlockManager.java:9448)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:1045)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:1013)
    at CLIENT_PACKAGE.src.sys.apps.Licentiemanager.fetchLicensesFromLicenseservice(Licentiemanager.java:71)
    at CLIENT_PACKAGE.src.sys.apps.Licentiemanager.lambda$__src_CLIENT_NAME_src_sys_apps_licentiemanager_constructor__$2(Licentiemanager.java:48)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.topLevelBlock(BlockManager.java:8504)
    at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:766)
    at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:739)
    at CLIENT_PACKAGE.src.sys.apps.Licentiemanager.__src_CLIENT_NAME_src_sys_apps_licentiemanager_constructor__(Licentiemanager.java:39)
    at CLIENT_PACKAGEe.src.sys.apps.LicentiemanagerMethodAccess.invoke(Unknown Source)
    at com.goldencode.p2j.util.ControlFlowOps$InternalEntryCaller.invokeImpl(ControlFlowOps.java:9378)
    at com.goldencode.p2j.util.ControlFlowOps$InternalEntryCaller.invoke(ControlFlowOps.java:9334)
    at com.goldencode.p2j.util.ControlFlowOps.initializeLegacyObject(ControlFlowOps.java:4905)
    at com.goldencode.p2j.util.ObjectOps.newInstanceInternal(ObjectOps.java:1308)
    at com.goldencode.p2j.util.ObjectOps.newInstanceInternal(ObjectOps.java:1221)
    at com.goldencode.p2j.util.ObjectOps.newInstance(ObjectOps.java:1148)
    at com.goldencode.p2j.util.ObjectOps.newInstance(ObjectOps.java:1127)
    at CLIENT_PACKAGE.src.sys.Licentie.lambda$getLicmanager$4(Licentie.java:73)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.functionBlock(BlockManager.java:9448)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:983)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:955)
    at CLIENT_PACKAGE.src.sys.Licentie.getLicmanager(Licentie.java:60)
    at CLIENT_PACKAGE.src.sys.Licentie.lambda$moduleAanwezig$6(Licentie.java:113)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.functionBlock(BlockManager.java:9448)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:983)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:955)
    at CLIENT_PACKAGE.src.sys.Licentie.moduleAanwezig(Licentie.java:111)
    at CLIENT_PACKAGE.src.dms.apps.Dmsdoc.lambda$execute$2(Dmsdoc.java:798)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.topLevelBlock(BlockManager.java:8504)
    at com.goldencode.p2j.util.BlockManager.externalProcedure(BlockManager.java:555)
    at com.goldencode.p2j.util.BlockManager.externalProcedure(BlockManager.java:528)
    at CLIENT_PACKAGE.src.dms.apps.Dmsdoc.execute(Dmsdoc.java:747)
    at CLIENT_PACKAGE.src.dms.apps.DmsdocMethodAccess.invoke(Unknown Source)
    at com.goldencode.p2j.util.ControlFlowOps$InternalEntryCaller.invokeImpl(ControlFlowOps.java:9378)
    at com.goldencode.p2j.util.ControlFlowOps$InternalEntryCaller.invoke(ControlFlowOps.java:9334)
    at com.goldencode.p2j.util.ControlFlowOps.invokeExternalProcedure(ControlFlowOps.java:6318)
    at com.goldencode.p2j.util.ControlFlowOps.invokeExternalProcedure(ControlFlowOps.java:6176)
    at com.goldencode.p2j.util.ControlFlowOps.invokePersistentImpl(ControlFlowOps.java:7588)
    at com.goldencode.p2j.util.ControlFlowOps.invokePersistentImpl(ControlFlowOps.java:7406)
    at com.goldencode.p2j.util.ControlFlowOps.invokePersistentSetWithMode(ControlFlowOps.java:2342)
    at com.goldencode.p2j.util.ControlFlowOps.invokePersistentSetWithMode(ControlFlowOps.java:2318)
    at com.goldencode.p2j.util.ControlFlowOps.invoke(ControlFlowOps.java:1262)
    at com.goldencode.p2j.util.InvokeConfig.run(InvokeConfig.java:425)
    at CLIENT_PACKAGE.src.dms.apps.Dmsapi.lambda$constructor$4(Dmsapi.java:281)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.topLevelBlock(BlockManager.java:8504)
    at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:715)
    at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:692)
    at CLIENT_PACKAGE.src.dms.apps.Dmsapi.constructor(Dmsapi.java:274)
    at CLIENT_PACKAGE.src.dms.apps.DmsapiMethodAccess.invoke(Unknown Source)
    at com.goldencode.p2j.util.ControlFlowOps$InternalEntryCaller.invokeImpl(ControlFlowOps.java:9378)
    at com.goldencode.p2j.util.ControlFlowOps$InternalEntryCaller.invoke(ControlFlowOps.java:9334)
    at com.goldencode.p2j.util.ControlFlowOps.lambda$invokeImpl$10(ControlFlowOps.java:7297)
    at com.goldencode.p2j.util.ControlFlowOps.invokeImpl(ControlFlowOps.java:7312)
    at com.goldencode.p2j.util.ControlFlowOps.invoke(ControlFlowOps.java:4448)
    at com.goldencode.p2j.util.ControlFlowOps.invokeImpl(ControlFlowOps.java:6878)
    at com.goldencode.p2j.util.ControlFlowOps.invokeImpl(ControlFlowOps.java:6781)
    at com.goldencode.p2j.util.ControlFlowOps.invokeInImpl(ControlFlowOps.java:6737)
    at com.goldencode.p2j.util.ControlFlowOps.invokeInWithMode(ControlFlowOps.java:1881)
    at com.goldencode.p2j.util.ControlFlowOps.invoke(ControlFlowOps.java:1307)
    at com.goldencode.p2j.util.InvokeConfig.run(InvokeConfig.java:425)
    at CLIENT_PACKAGE.src.sys.Ppm.lambda$null$10(Ppm.java:242)
    at com.goldencode.p2j.util.ErrorManager.silentWorker(ErrorManager.java:3893)
    at com.goldencode.p2j.util.ErrorManager.silent(ErrorManager.java:685)
    at CLIENT_PACKAGE.src.sys.Ppm.lambda$ppmGetMain$17(Ppm.java:242)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.functionBlock(BlockManager.java:9448)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:983)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:955)
    at CLIENT_PACKAGE.src.sys.Ppm.ppmGetMain(Ppm.java:200)
    at CLIENT_PACKAGE.src.sys.Ppm.lambda$ppmGet$18(Ppm.java:285)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.functionBlock(BlockManager.java:9448)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:983)
    at com.goldencode.p2j.util.BlockManager.function(BlockManager.java:955)
    at CLIENT_PACKAGE.src.sys.Ppm.ppmGet(Ppm.java:283)
    at CLIENT_PACKAGE.src.sys.PpmMethodAccess.invoke(Unknown Source)
    at com.goldencode.p2j.util.ControlFlowOps$InternalEntryCaller.invokeImpl(ControlFlowOps.java:9378)
    at com.goldencode.p2j.util.ControlFlowOps$InternalEntryCaller.invoke(ControlFlowOps.java:9334)
    at com.goldencode.p2j.util.ControlFlowOps.lambda$invokeImpl$10(ControlFlowOps.java:7297)
    at com.goldencode.p2j.util.ControlFlowOps.invokeImpl(ControlFlowOps.java:7312)
    at com.goldencode.p2j.util.ControlFlowOps.invoke(ControlFlowOps.java:4448)
    at com.goldencode.p2j.util.ControlFlowOps.invokeImpl(ControlFlowOps.java:6878)
    at com.goldencode.p2j.util.ControlFlowOps.invokeImpl(ControlFlowOps.java:6781)
    at com.goldencode.p2j.util.ControlFlowOps.invokeFunctionImpl(ControlFlowOps.java:6711)
    at com.goldencode.p2j.util.ControlFlowOps.invokeDynamicFunctionWithMode(ControlFlowOps.java:3360)
    at com.goldencode.p2j.util.ControlFlowOps.invoke(ControlFlowOps.java:1138)
    at com.goldencode.p2j.util.InvokeConfig.execute(InvokeConfig.java:438)
    at CLIENT_PACKAGE.src.root.Uitgesteldeverwerking.lambda$execute$7(Uitgesteldeverwerking.java:536)
    at com.goldencode.p2j.util.Block.body(Block.java:636)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8838)
    at com.goldencode.p2j.util.BlockManager.topLevelBlock(BlockManager.java:8504)
    at com.goldencode.p2j.util.BlockManager.externalProcedure(BlockManager.java:555)
    at com.goldencode.p2j.util.BlockManager.externalProcedure(BlockManager.java:528)
    at CLIENT_PACKAGE.src.root.Uitgesteldeverwerking.execute(Uitgesteldeverwerking.java:370)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at com.goldencode.p2j.util.Utils.invoke(Utils.java:1763)
    at com.goldencode.p2j.main.StandardServer$MainInvoker.execute(StandardServer.java:2341)
    at com.goldencode.p2j.main.StandardServer.invoke(StandardServer.java:1743)
    at com.goldencode.p2j.main.StandardServer.standardEntry(StandardServer.java:646)
    at com.goldencode.p2j.main.StandardServerMethodAccess.invoke(Unknown Source)
    at com.goldencode.p2j.util.MethodInvoker.invoke(MethodInvoker.java:156)
    at com.goldencode.p2j.net.Dispatcher.processInbound(Dispatcher.java:788)
    at com.goldencode.p2j.net.Conversation.block(Conversation.java:420)
    at com.goldencode.p2j.net.Conversation.run(Conversation.java:233)
    at java.lang.Thread.run(Thread.java:750)
Caused by: java.lang.IllegalStateException: Field private static final com.goldencode.p2j.util.logging.CentralLogger com.goldencode.p2j.oo.json.objectmodel.JsonConstruct.LOG in class class com.goldencode.p2j.oo.json.objectmodel.JsonConstruct is static, but not ContextLocal!
    at com.goldencode.p2j.util.ControlFlowOps.initializeLegacyClass(ControlFlowOps.java:4698)
    ... 157 more

The static CentralLogger fields in the Json* classes lead to java.lang.IllegalStateException: Field private static final com.goldencode.p2j.util.logging.CentralLogger com.goldencode.p2j.oo.json.objectmodel.JsonConstruct.LOG in class class com.goldencode.p2j.oo.json.objectmodel.JsonConstruct is static, but not ContextLocal!.

I reverted the fix in #5703-233, but now I want to bring it back. The fix is very simple and efficient. Static fields to instance fields. CentralLogger instances have only one String field as their state, so they are cheap and will be garbage collected.

Galya, no, do something else: in ControlFlowOps.initializeLegacyClass, there is this code:

            if (!ContextLocal.class.isAssignableFrom(ftype))
            {
               String msg = "Field " + f.toString() + " in class " + 
                            cls.toString() + " is static, but not ContextLocal!";
               String fpkg = ftype.getPackage().getName();
               if (fpkg.startsWith("com.goldencode") || fpkg.startsWith(pkgroot))
               {
                  throw new IllegalStateException(msg);
               }
               else if (LOG.isLoggable(Level.FINE))
               {
                  LOG.log(Level.FINE, msg);
               }

               continue;
            }

Previously the code worked because the field's type was outside of FWD or converted app's package. Change this code to avoid abending if the defined field is from com.goldencode.p2j.util.logging package.

is com.goldencode.trpl obsolete? I don't see it anywhere being used.

It is experimental and not in use yet. Yes, it definitely is in the conversion group.

Constantin Asofiei wrote:

Previously the code worked because the field's type was outside of FWD or converted app's package. Change this code to avoid abending if the defined field is from com.goldencode.p2j.util.logging package.

I fix it with:

               if (!fpkg.startsWith("com.goldencode.p2j.util.logging") &&
                  (fpkg.startsWith("com.goldencode") || fpkg.startsWith(pkgroot)))
               {
                  throw new IllegalStateException(msg);
               }

OK, thank you.

• Exceptions are either WARNING or SEVERE with a very few on INFO level.
• Important messages are mostly INFO. One or two messages are CONFIG.
• All trace and debug went to FINE/FINER/FINEST, a lot of them had a suggesting method involved with them.
• Some messages had the level inside, like "INFO: appserver has been spawned", so I just migrated them directly.

5703a has been merged to trunk, the branch is archived and an email is sent.

Is tilde (~) supported in the filename so that the configuration can cover all users?

Roger Borrello wrote:

Is tilde (~) supported in the filename so that the configuration can cover all users?

No. You will find we have a range of substitutions supported but home dir is not one of them. It probably should be added but we wouldn't do it with a tilde, we would add a printf-like % specifier.

DB import shows lots of INFO statements like:

  

    [java] Meta{...(...}

    [java] FWD ORM: com.mchange.v2.c3p0.impl.NewProxyPreparedStatement@5a5e3887 [wrapping: drop index if exists ... ]
    [java] FWD ORM: com.mchange.v2.c3p0.impl.NewProxyPreparedStatement@a76514c [wrapping: insert into ... ]
    [java] 20:57:23.808 [main] DEBUG com.mchange.v2.c3p0.impl.NewProxyPreparedStatement - com.mchange.v2.c3p0.impl.NewProxyPreparedStatement@373fb666 [wrapping:

These need to be lowered.

Galya,

Do you have any ideas how to resolve #7143-168, #7143-169 issues/regressions?

Regression: RemoteObject can be used from standalone JVMs (i.e. JavaOpenClient). The logging defaults to 'FINE' (for all loggers!) and abends with this:

    [junit] Caused by: java.lang.IllegalStateException: A custom result set must not be specified when calling this method!
    [junit]     at Source = SystemIdentity [name=xever] at 15/05/2023 18:15:03.164 on thread RMI TCP Connection(7)-127.0.0.1(42).(:0)
    [junit]     at com.goldencode.p2j.persist.TableWrapper.propertyIterator(TableWrapper.java:550)
    [junit]     at com.goldencode.p2j.persist.TableWrapper.toString(TableWrapper.java:1008)
    [junit]     at com.goldencode.p2j.util.TraceHelper.render(TraceHelper.java:241)
    [junit]     at com.goldencode.p2j.util.TraceHelper.expandParameters(TraceHelper.java:199)
    [junit]     at com.goldencode.p2j.util.TraceHelper.render(TraceHelper.java:230)
    [junit]     at com.goldencode.p2j.util.TraceHelper.expandParameters(TraceHelper.java:199)
    [junit]     at com.goldencode.p2j.util.TraceHelper.trace(TraceHelper.java:128)
    [junit]     at com.goldencode.p2j.net.RemoteObject$RemoteAccess.trace(RemoteObject.java:1498)
    [junit]     at com.goldencode.p2j.net.RemoteObject$RemoteAccess.invokeCore(RemoteObject.java:1467)
    [junit]     at com.goldencode.p2j.net.InvocationStub.invoke(InvocationStub.java:144)

Regression: add a bogus jar to the classpath (just at the beginning) and this is shown when starting the FWD server; this was found when starting an app which has p2j/build/lib/p2jadmin.jar (which does not exist) at the beginning of the classpath.

java.lang.ExceptionInInitializerError
        at com.goldencode.p2j.util.logging.CentralLogger.ultimateLog(CentralLogger.java:1359)
        at com.goldencode.p2j.util.logging.CentralLogger.log(CentralLogger.java:1090)
        at com.goldencode.p2j.classloader.MultiClassLoader.<clinit>(MultiClassLoader.java:136)
        at java.lang.Class.forName0(Native Method)
        at java.lang.Class.forName(Class.java:348)
        at java.lang.SystemClassLoaderAction.run(ClassLoader.java:2202)
        at java.lang.SystemClassLoaderAction.run(ClassLoader.java:2188)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.lang.ClassLoader.initSystemClassLoader(ClassLoader.java:1449)
        at java.lang.ClassLoader.getSystemClassLoader(ClassLoader.java:1429)
Caused by: java.lang.IllegalStateException: recursive invocation
        at java.lang.ClassLoader.initSystemClassLoader(ClassLoader.java:1443)
        at java.lang.ClassLoader.getSystemClassLoader(ClassLoader.java:1429)
        at java.util.ServiceLoader.loadInstalled(ServiceLoader.java:568)
        at sun.util.locale.provider.SPILocaleProviderAdapter$1.run(SPILocaleProviderAdapter.java:80)
        at sun.util.locale.provider.SPILocaleProviderAdapter$1.run(SPILocaleProviderAdapter.java:74)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.util.locale.provider.SPILocaleProviderAdapter.findInstalledProvider(SPILocaleProviderAdapter.java:74)
        at sun.util.locale.provider.AuxLocaleProviderAdapter.getLocaleServiceProvider(AuxLocaleProviderAdapter.java:70)
        at sun.util.locale.provider.LocaleServiceProviderPool.<init>(LocaleServiceProviderPool.java:133)
        at sun.util.locale.provider.LocaleServiceProviderPool.getPool(LocaleServiceProviderPool.java:111)
        at sun.util.locale.provider.CalendarDataUtility.retrieveFirstDayOfWeek(CalendarDataUtility.java:51)
        at java.util.Calendar.setWeekCountData(Calendar.java:3381)
        at java.util.Calendar.<init>(Calendar.java:1600)
        at java.util.GregorianCalendar.<init>(GregorianCalendar.java:737)
        at java.util.Calendar$Builder.build(Calendar.java:1482)
        at sun.util.locale.provider.CalendarProviderImpl.getInstance(CalendarProviderImpl.java:88)
        at java.util.Calendar.createCalendar(Calendar.java:1666)
        at java.util.Calendar.getInstance(Calendar.java:1655)
        at java.text.SimpleDateFormat.initializeCalendar(SimpleDateFormat.java:657)
        at java.text.SimpleDateFormat.<init>(SimpleDateFormat.java:601)
        at java.text.SimpleDateFormat.<init>(SimpleDateFormat.java:580)
        at com.goldencode.p2j.util.logging.CentralLogFormatter.<clinit>(CentralLogFormatter.java:87)
        at com.goldencode.p2j.util.logging.CentralLogger.ultimateLog(CentralLogger.java:1359)
        at com.goldencode.p2j.util.logging.CentralLogger.log(CentralLogger.java:1090)
        at com.goldencode.p2j.classloader.MultiClassLoader.<clinit>(MultiClassLoader.java:136)
        at java.lang.Class.forName0(Native Method)
        at java.lang.Class.forName(Class.java:348)
        at java.lang.SystemClassLoaderAction.run(ClassLoader.java:2202)
        at java.lang.SystemClassLoaderAction.run(ClassLoader.java:2188)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.lang.ClassLoader.initSystemClassLoader(ClassLoader.java:1449)
        at java.lang.ClassLoader.getSystemClassLoader(ClassLoader.java:1429)

Roger Borrello wrote:

Is tilde (~) supported in the filename so that the configuration can cover all users?

There is support for home provided by FileHandler (find Custom placeholders section in Logs wiki)

"%h" the value of the "user.home" system property

You can have the home folder + the default format like that:

              <node class="container" name="file">
                <node class="string" name="path">
                  <node-attribute name="value" value="%h/fwd_%m_%tY-%tm-%td_%tH-%tM-%tS_%uos_%pid_%uf_%as_%g.log"/>
                </node>
              </node>

Constantin Asofiei wrote:

DB import shows lots of INFO statements like:
[...]

These need to be lowered.

This is the CentralLoggerFallback that doesn't have a default logging level, since it's used for tools and tests. The com.mchange.v2 logs might be on a different slf4j level (not INFO, probably TRACE). Seems that before com.mchange.v2 logs were just missing due to the lack of proper slf4j support for tools.

How to deal with it now? We need to implement support for a logging level in the args of the tools. If I get it correctly it should be support for a new arg to com.goldencode.p2j.pattern.PatternEngine that will be added to build_db.xml import.db.pg and import.db.h2.

Do you want me to add it and test it?

Galya, for the standalone tools - this includes conversion, import, standalone JVMs (not FWD server/client) using FWD APIs -, the default logging level must not be 'log everything'. We can't make it mandatory to add some logging level at the tool's command line argument.

Please consider a default logging level of WARNING. You can make it globally - if even FWD directory.xml logging levels are not set, default to WARNING.

Also, regarding the #7143-178 - is OK for the message to appear as a WARNING, but the stacktrace let it show only for FINE/FINER.

Constantin Asofiei wrote:

Regression: RemoteObject can be used from standalone JVMs (i.e. JavaOpenClient). The logging defaults to 'FINE' (for all loggers!) and abends with this:
[...]

Java Loggers have the default level of INFO, which indeed is missing now, because we added more logs (System.err and some System.out) and thus all tools and test are supported in the same way now. All non-server / non-client processes run with CentralLoggerFallback which doesn't filter msgs based on level now.

Instead of adding a default INFO level, I would suggest to support level configs (startup arg) for each important entry class. Otherwise some tools might be missing important prints.

Constantin Asofiei wrote:

Please consider a default logging level of WARNING. You can make it globally - if even FWD directory.xml logging levels are not set, default to WARNING.

That will be problematic. If there is no mechanism to lower it, since tools don't read directory.xml.
Also as I mentioned in my last comment, previously the default level coming from Java loggers was INFO, so WARNING will remove some expected messages.

Galya Bogdanova wrote:

Constantin Asofiei wrote:

Please consider a default logging level of WARNING. You can make it globally - if even FWD directory.xml logging levels are not set, default to WARNING.

That will be problematic. If there is no mechanism to lower it, since tools don't read directory.xml.

I don't mean to not allow logging levels via some command line argument (or maybe a logging.properties file), for standalone tools - what I mean if no log level is specified, then use a good default.

Also as I mentioned in my last comment, previously the default level coming from Java loggers was INFO, so WARNING will remove some expected messages.

OK, lets try with INFO and see what gives us.

Constantin Asofiei wrote:

I don't mean to not allow logging levels via some command line argument (or maybe a logging.properties file), for standalone tools - what I mean if no log level is specified, then use a good default.

logging.properties won't do, since we're using a custom impl, although I can parse it still with a custom code. But it will be easier to just add startup args to the important tools classes. If we compile a list of these classes, I will be on it.

Also as I mentioned in my last comment, previously the default level coming from Java loggers was INFO, so WARNING will remove some expected messages.

I will hard-code INFO easily, but if I've added some System.err/outs to levels below INFO, they will not show. I'm worried for it especially for tools where all prints are part of the execution. :-/

• default any logger (including the ones initialized from directory.xml) to INFO; hopefully this fixes #5703-417 and some other cases (you already added this I see)
• #7143-178 message
• the sheet.war problem described in #7143-173, #7143-168, #7143-169
• #5703-418 problem

Once you have these, please let me know, so we can retest the apps.

Constantin Asofiei wrote:

Galya, we have some priorities to fix:

• default any logger (including the ones initialized from directory.xml) to INFO; hopefully this fixes #5703-417 and some other cases (you already added this I see)

Clients and server already had it. Now tools and tests also will have INFO as a default. 5703b r14572.

• #7143-178 message

Also up in 5703b r14572l.

• the sheet.war problem described in #7143-173, #7143-168, #7143-169

For #7143-173 and #7143-169 I'm waiting for Eugenie's response to #7143#note-176 and #7143#note-177.
Oddly #7143-168 doesn't look related. But I'll check it after everything else is sorted out.

• #5703-418 problem

I'm on it now.

Constantin Asofiei wrote:

Regression: add a bogus jar to the classpath (just at the beginning) and this is shown when starting the FWD server; this was found when starting an app which has p2j/build/lib/p2jadmin.jar (which does not exist) at the beginning of the classpath.
[...]

Well, the class loader still isn't completed initialization at this point (static initializer), so it can't properly use other classes. I'm reverting it to simple e.printStackTrace() as it was before. Up in 5703b r14573.

Galya, please use Hotel GUI and do a before and after comparison of the conversion log and db import logs. There are messages missing; please see how these can be enabled.

logging.properties won't do

I agree with this, we don't use props files. We use good defaults and allow optional override via command line.

Let's remove the pid from the default server log file name so that by default we are not trying to load the native library.

Greg Shah wrote:

Let's remove the pid from the default server log file name so that by default we are not trying to load the native library.

The default is one for both server and client files as we decided last. Is it ok to remove it from the client default as well?

The client side is better with it so let's consider options for not having a single cfg entry for both names.

The easiest is to simply not include pid ever in server log file name using a placeholder. Do you want to keep it as an option?

The easiest is to simply not include pid ever in server log file name using a placeholder.

No, allowing the pid on the server is useful. I just don't want it to be a default for the server, while the client in fact is better with the pid as a default.

I'll be debugging for a while the sheet project bug with loading slf4j. It is related to some dependencies using org.slf4j:jcl-over-slf4j:

23/05/16 14:46:26.504+0300 | WARNING | org.eclipse.jetty.webapp.WebAppContext | PID:216244, ThreadName:main, Server Session:00000075, User:bogus | Failed startup of context o.e.j.w.WebAppContext@6342d610{Spreadsheet,/sheet/432,file:///tmp/jetty-0_0_0_0-46875-fwd_sheet_war-_sheet_432-any-6176279366499463403.dir/webapp/,UNAVAILABLE}{/media/gbb/Disk2/<app>/deploy/lib/fwd_sheet.war}
java.lang.LinkageError: loader constraint violation: when resolving method "org.slf4j.impl.StaticLoggerBinder.getLoggerFactory()Lorg/slf4j/ILoggerFactory;" the class loader (instance of org/eclipse/jetty/webapp/WebAppClassLoader) of the current class, org/slf4j/LoggerFactory, and the class loader (instance of sun/misc/Launcher$AppClassLoader) for the method's defining class, org/slf4j/impl/StaticLoggerBinder, have different Class objects for the type org/slf4j/ILoggerFactory used in the signature
    at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:423)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:362)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:388)
    at org.zkoss.zk.ui.http.WebManager.<clinit>(WebManager.java:85)

According to JCL doc it's considered Type-II problem:

Type-II: Assignment incompatibility of two classes loaded by distinct class loaders, even in case where the two classes are bit-wise identical.

Type-II problems are a bit harder to grasp at first glance.

There are two classloaders, loading probably the same implementation of slf4j twice and considering it different. In SheetControllerImpl we have:

   public Object invokeCommand(SpreadsheetCommands command, Object... args)
   {
      ClassLoader originalClassLoader = Thread.currentThread().getContextClassLoader();
      try
      {
         Thread.currentThread().setContextClassLoader(getClass().getClassLoader());

So org.slf4j.impl.StaticLoggerBinder is originally loaded by org/eclipse/jetty/webapp/WebAppClassLoader and then by sun/misc/Launcher$AppClassLoader.

Do we always use fwd_sheet.war from a web process spawned by the server or as a separate tool as well?

Do we always use fwd_sheet.war from a web process spawned by the server or as a separate tool as well?

Neither. I would not say it is a spawned web process, nor a separate tool. As far as I know, it runs inside the FWD client's jetty web-server, always.

Greg Shah wrote:

Do we always use fwd_sheet.war from a web process spawned by the server or as a separate tool as well?

Neither. I would not say it is a spawned web process, nor a separate tool. As far as I know, it runs inside the FWD client's jetty web-server, always.

And to see the result, Spreadsheet for example you need to start Web client. Swing client will abend opening Spreadsheet and it is expected.

Eugenie Lyzenko wrote:

Greg Shah wrote:

Do we always use fwd_sheet.war from a web process spawned by the server or as a separate tool as well?

Neither. I would not say it is a spawned web process, nor a separate tool. As far as I know, it runs inside the FWD client's jetty web-server, always.

And to see the result, Spreadsheet for example you need to start Web client. Swing client will abend opening Spreadsheet and it is expected.

Yes

I can't debug SheetControllerImpl that is part of the war. Debugging doesn't hit the breakpoints.

It's deployed as org.eclipse.jetty.webapp.WebAppContext in SpreadsheetDriverWidget and the war is set to the context with webApp.setWar(getWARPath().getAbsolutePath()). I don't know how to debug this type of deployment (not that it's going to save the day anyways).

Galya Bogdanova wrote:

I can't debug SheetControllerImpl that is part of the war. Debugging doesn't hit the breakpoints.

Are you debugging the FWD client? You need to attach to it; add to jvmArgs in directory.xml, under clientConfig node. Make sure all processes in scheduler are disabled.

-Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,address=2998,server=y,suspend=n

After this, login with just 1 FWD web client.

I try to debug the sheet war. I have both the server and client debuggers connected, but the breakpoint in SheetControllerImpl is not hit with any of them. And this WebContext deployment of war seems a little odd indeed.

Galya Bogdanova wrote:

I try to debug the sheet war. I have both the server and client debuggers connected, but the breakpoint in SheetControllerImpl is not hit with any of them. And this WebContext deployment of war seems a little odd indeed.

I think you will not able to debug this because you have no source code:

23/05/12 23:43:01.549+0300 | WARNING | org.eclipse.jetty.webapp.WebAppContext | PID:12711, ThreadName:main, Server Session:00000075, User:bogus | Failed startup of context o.e.j.w.WebAppContext@7e64c1a9{Spreadsheet,/sheet/434,file:///tmp/jetty-0_0_0_0-37427-fwd_sheet_war-_sheet_434-any-7475110303428545033.dir/webapp/,UNAVAILABLE}{/home/evl/<app>_full/deploy/lib/fwd_sheet.war}
java.lang.LinkageError: loader constraint violation: when resolving method "org.slf4j.impl.StaticLoggerBinder.getLoggerFactory()Lorg/slf4j/ILoggerFactory;" the class loader (instance of org/eclipse/jetty/webapp/WebAppClassLoader) of the current class, org/slf4j/LoggerFactory, and the class loader (instance of sun/misc/Launcher$AppClassLoader) for the method's defining class, org/slf4j/impl/StaticLoggerBinder, have different Class objects for the type org/slf4j/ILoggerFactory used in the signature
    at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:423)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:362)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:388)
    at org.zkoss.zk.ui.http.WebManager.<clinit>(WebManager.java:85)
    at org.zkoss.zk.ui.http.HttpSessionListener23.contextInitialized(HttpSessionListener23.java:140)
    at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:929)
...

This is internal call from org.eclipse.jetty.server.handler.ContextHandler. So I think unfortunately this is coming from one of the external *.jar file we use. May be we need a version without embedded calls to slf4j.

The exact call is indeed part of jetty, but I was trying to debug the part around setting a context class loader in SheetControllerImpl, just to get more ... context.

I'm trying now to figure out a way to exclude the org.slf4j custom package from the war. It might work.

Roger Borrello wrote:

I made appropriate updates to directory.xml as directed for my application.

I believe there is a regression in that when I run ./server.sh -w for checking on status of the server process, and or ./server.sh -k for stopping it, there isn't any proper response. I get a crash log as noted. I can not longer run the server process detached without having to kill it via PID.

It looks like the call to configureLogging in CommonDriver.process() that now comes before the application is run via start(bc); is creating the DirectoryService without this check:

         if (bc.getString("security", "keystore", "filename", null) == null)
         {
            // if no keystore is specified, then we need to initialize as "server" and load it
            // from the directory.
            bc.setServer(true);
            bc.setConfigItem("directory", "xml", "must_exist", "true");
            DirectoryService ds = DirectoryService.createInstance(bc);
...

23/05/16 11:28:23.916-0400 | SEVERE  | com.goldencode.p2j.main.ServerDriver | ThreadName:main | CentralLoggerServer cannot be initialized with configs:
com.goldencode.p2j.cfg.ConfigurationException: Not a server configuration
    at com.goldencode.p2j.directory.DirectoryService.<init>(DirectoryService.java:302)
    at com.goldencode.p2j.directory.DirectoryService.createInstance(DirectoryService.java:338)
    at com.goldencode.p2j.main.ServerDriver.configureLogging(ServerDriver.java:577)
    at com.goldencode.p2j.main.CommonDriver.process(CommonDriver.java:534)
    at com.goldencode.p2j.main.ServerDriver.process(ServerDriver.java:224)
    at com.goldencode.p2j.main.ServerDriver.main(ServerDriver.java:995)

We can always add bc.setServer(true); without the if, since this code is in ServerDriver, but I've never seen that exception.

Galya Bogdanova wrote:

We can always add bc.setServer(true); without the if, since this code is in ServerDriver, but I've never seen that exception.

To duplicate in Hotel, you should be able to perform ./server.sh with -s option to perform a status check on the server. It will go through most of the initialization, but throw the error in DirectoryService as called from configureLogging instead of having the server flag set back to true.

As for whether or not to include the keystore condition, I would think it best to include it, but I am not the best at making that determination. Perhaps something like:

      try
      {
         // if no keystore is specified, then we need to initialize as "server" and load it
         // from the directory.
         bc.setServer(bc.getString("security", "keystore", "filename", null) == null);

         // instantiate the directory service with must_exist option
         bc.setConfigItem("directory", "xml", "must_exist", "true");
         DirectoryService ds = DirectoryService.createInstance(bc);

         ds.bind();
         CentralLoggerServer.Configs configs = CentralLoggerServer.Configs.fromDirectory(ds);
         ds.unbind();

         CentralLoggerServer.initialize(configs);
      }

• should fix all issues described by Eugenie - #7143-173, #7143-168, #7143-169;
• adds setServer to bc in ServerDriver.configureLogging;
• fixes the place of the spawner stderr redirect statement (changed with the rebase).

• comparing regression in db import tool output;
• splitting server / client path.

Galya Bogdanova wrote:

Eugenie, removing slf4j-api from all dependencies in sheet should be enough to fix the issue.

And then rebuild the war and replace it.

Hi Galya... I certainly do like the cleaner logging process, and will test my customers application on 5703b so as to provide feedback before you merge. I am trying to finish my changes to the directory.xml in my application, and I am having a couple of difficulties.

I have a helper script that wrappers the server.sh checking on status. Previously I relied upon the server.log file for monitoring output. Upon switching to the CentralLogging, I had to change that to server0.log since %m%g.log is the file specification. After a few retries, I see the most recent file is now server0.log.1, and the server0.log is an older version. How can I avoid that situation with a different extension on the filename, so I can utilize the same filename in my wrapper?

Also, I find some files from my appserver config are created in the directory where I start the server from: legacy_client_2023-05-16_14-38-14_rfb_38079_<appserver>.log (<appserver> obfuscated on purpose). I suspect there is a default somewhere that I need to change, I just cannot determine where from the Wiki.

The contents are similar to:

[23/05/16@14:38:14.332-0400] P-038079 T-000107 1 4GL -- Logging level set to = 2
[23/05/16@14:38:14.333-0400] P-038079 T-000107 1 4GL -- No entry types are activated

In general, I haven't been able to direct the log files for my app servers, and clients (web and chui).

For the appservers, I had tried the below:

    <node class="container" name="server">
      <node class="container" name="default">
        <node class="container" name="runtime">
          <node class="container" name="appserver">
            <node class="container" name="clientConfig">
              <node class="container" name="logging">
                <node class="container" name="file">
                  <node class="string" name="path">
                    <node-attribute name="value" value="/usr/<path>/%m_%tY-%tm-%td_%tH-%tM-%tS_%pid_%as_%uos_%g.log"/>
                  </node>
                </node>
              </node>

Also tried

    <node class="container" name="server">
      <node class="container" name="default">
        <node class="container" name="runtime">
          <node class="container" name="appserver">
            <node class="container" name="clientConfig">
              <node class="string" name="cfgOverrides">
                <node-attribute name="value" value="client:driver:background=true client:logging:path=/usr/<path>/%m_%tY-%tm-%td_%tH-%tM-%tS_%pid_%as_%uos_%g.log"/>

    <node class="container" name="server">
      <node class="container" name="standard">
        <node class="container" name="appservers">
          <node class="container" name="logging">
            <node class="boolean" name="serverSide">
              <node-attribute name="value" value="TRUE"/>
            </node>
            <node class="container" name="file">
              <node class="string" name="path">
                <node-attribute name="value" value="/usr/<path>/%m_%tY-%tm-%td_%tH-%tM-%tS_%pid_%as_%uos_%g.log"/>
              </node>
            </node>
          </node>

Any directions you can help with would be appreciated.

Constantin Asofiei wrote:

Galya, please use Hotel GUI and do a before and after comparison of the conversion log and db import logs. There are messages missing; please see how these can be enabled.

The steps of the import are not executed in the same order, but I was able to compare them and the output is the same now with Level.INFO. There were before some garbage logs like com.mchange.v2.log.slf4j.Slf4jMLog$Slf4jMLogger$InfoLogger log that now with proper slf4j support are removed. import.xml rules use two logging methods in CommonAstSupport. I set their levels to INFO, otherwise the msg from the rules will be missing. Up in 5703b r14575.

Roger Borrello wrote:

After a few retries, I see the most recent file is now server0.log.1, and the server0.log is an older version. How can I avoid that situation with a different extension on the filename, so I can utilize the same filename in my wrapper?

%g is adding a unique number for the rotation, but upon restart it's not unique any more, so adding datetime or pid to the pattern is the best way to avoid the auto added number as an extension.

Also, I find some files from my appserver config are created in the directory where I start the server from: legacy_client_2023-05-16_14-38-14_rfb_38079_<appserver>.log (<appserver> obfuscated on purpose). I suspect there is a default somewhere that I need to change, I just cannot determine where from the Wiki.

legacy_client is clientlog for LOG-MANAGER and it supports relative / absolute paths in the name itself. At the moment LOG-MANAGER writes server-side, but we'll jazz it up and add client-side soon as well, so I guess absolute paths will work best or something that works from any launch folders like ../client/legacy_client_%tY-%tm-%td_%tH-%tM-%tS_%uf_%pid_%uos_%as.log (I updated LOG-MANAGER section in Log wiki with the placeholders). clientlog should be configured for each client type (check LOG-MANAGER configs for web, appserver and gui clients), otherwise the default will go to the launch dir.

Galya Bogdanova wrote:

5703b r14574:

• should fix all issues described by Eugenie - #7143-173, #7143-168, #7143-169;
• adds setServer to bc in ServerDriver.configureLogging;
• fixes the place of the spawner stderr redirect statement (changed with the rebase).

Next:

• comparing regression in db import tool output;
• splitting server / client path.

Confirm fixed areas. Please consider to resolve #7143-174 issue. It is still active.

Eugenie Lyzenko wrote:

Confirm fixed areas. Please consider to resolve #7143-174 issue. It is still active.

This UnsatisfiedLinkError should be handled by the catch in:

         Supplier<Long> processIdSupplier = () -> {
            try 
            {
               System.loadLibrary("p2j");<---- EVL: Exception here
               return ClientCore.getPid();
            }
            catch (Throwable t)
            {
               LOG.severe("Server process id can't be determined at this time, which will lead to a corrupt" +
                             " log file name for the server process. The native library `p2j` loading method " +
                             "is likely the cause of the issue.", t);
               return 0L;
            }
         };

We've changed the level of the error to WARNING in 5703b, but even as SEVERE, it should not cause app crash. Can you check if there is anything else going on as well?

Roger, a clarification: LOG-MANAGER logs are configured with clientlog and don't support %g. There is default only for appservers and that is the legacy_client_* you see. For other types of clients, it's disabled by default so you don't need to add configs except if the clients are not dependent on LOG-MANAGER (that is the 4GL legacy logging method).

Galya Bogdanova wrote:

Eugenie Lyzenko wrote:

Confirm fixed areas. Please consider to resolve #7143-174 issue. It is still active.

This UnsatisfiedLinkError should be handled by the catch in:
[...]

We've changed the level of the error to WARNING in 5703b, but even as SEVERE, it should not cause app crash. Can you check if there is anything else going on as well?

Sorry, this is another issue I guess. Because location is different. Happen when I tried to start Swing client:

23/05/16 22:51:07.958+0300 | SEVERE  | com.goldencode.p2j.main.CommonDriver | ThreadName:main | System exits with code -13 caused by:
java.lang.UnsatisfiedLinkError: /home/evl/<app>_full/deploy/lib/libp2j.so: /home/evl/<app>_full/deploy/lib/libp2j.so: undefined symbol: curscr
    at java.lang.ClassLoader$NativeLibrary.load(Native Method)
    at java.lang.ClassLoader.loadLibrary0(ClassLoader.java:1937)
    at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1853)
    at java.lang.Runtime.loadLibrary0(Runtime.java:843)
    at java.lang.System.loadLibrary(System.java:1134)
    at com.goldencode.p2j.main.ClientCore.loadNativeLibrary(ClientCore.java:574)
    at com.goldencode.p2j.main.ClientCore.start(ClientCore.java:454)
    at com.goldencode.p2j.main.ClientDriver.start(ClientDriver.java:270)
    at com.goldencode.p2j.main.CommonDriver.process(CommonDriver.java:539)
    at com.goldencode.p2j.main.ClientDriver.process(ClientDriver.java:347)
    at com.goldencode.p2j.main.ClientDriver.main(ClientDriver.java:390)
...

There is no try {} catch {} protection there.

Eugenie Lyzenko wrote:

Sorry, this is another issue I guess. Because location is different. Happen when I tried to start Swing client:
[...]

There is no try {} catch {} protection there.

We had this code for a while there, but ClientCore has always been loading native with System.loadLibrary("p2j").

So is it expected that the deployment doesn't have libp2j.so and doesn't use native library?

Galya Bogdanova wrote:

Roger Borrello wrote:

After a few retries, I see the most recent file is now server0.log.1, and the server0.log is an older version. How can I avoid that situation with a different extension on the filename, so I can utilize the same filename in my wrapper?

%g is adding a unique number for the rotation, but upon restart it's not unique any more, so adding datetime or pid to the pattern is the best way to avoid the auto added number as an extension.

The wrapper needs to know what the server logfile name is, without having to make any logical determinations. If I am specifying /logs/%m%g.log as the log file name, I can't expect to know that .log.1 is now the extension of the file. I've specified .log and that's what I'd expect to have. If I do away with all the placeholders and specify /logs/server.log will I get the same log file each time, or will there be a /logs/server.log.1 upon restart?

Galya Bogdanova wrote:

Eugenie Lyzenko wrote:

Sorry, this is another issue I guess. Because location is different. Happen when I tried to start Swing client:
[...]

There is no try {} catch {} protection there.

We had this code for a while there, but ClientCore has always been loading native with System.loadLibrary("p2j").

So is it expected that the deployment doesn't have libp2j.so and doesn't use native library?

Please drop this note. The reason is my local changes for libp2j.so building. I tested on clean system and the server and clients are now working fine.

I will update replica today with recent <app>/FWD and your fix from #5703-454. Thanks for fast resolution and sorry for this additional false alarm.

Roger Borrello wrote:

The wrapper needs to know what the server logfile name is, without having to make any logical determinations. If I am specifying /logs/%m%g.log as the log file name, I can't expect to know that .log.1 is now the extension of the file. I've specified .log and that's what I'd expect to have. If I do away with all the placeholders and specify /logs/server.log will I get the same log file each time, or will there be a /logs/server.log.1 upon restart?

When rotation is enabled, this is the Java logging logic - attaching a unique rotation number to the file. It uses %g for it, but since the name is not unique after a restart, java FileHandler decides by itself to add the extension.

This is how java works with enabled rotation.

Roger Borrello wrote:

The wrapper needs to know what the server logfile name is, without having to make any logical determinations.

Does it mean the file should not be rotated and should be overwritten on restart?

What is the limitation in the wrapper of having no logic? Can it not find the last updated server*.log file and parse it until a more recent file of the same pattern appears in the folder?

• 5703b r14576 server and client default log file names separated. Server default without pid.

• Tested.

• Ready for review. 5703b is based on latest trunk r14571.

Galya Bogdanova wrote:

Roger Borrello wrote:

The wrapper needs to know what the server logfile name is, without having to make any logical determinations. If I am specifying /logs/%m%g.log as the log file name, I can't expect to know that .log.1 is now the extension of the file. I've specified .log and that's what I'd expect to have. If I do away with all the placeholders and specify /logs/server.log will I get the same log file each time, or will there be a /logs/server.log.1 upon restart?

When rotation is enabled, this is the Java logging logic - attaching a unique rotation number to the file. It uses %g for it, but since the name is not unique after a restart, java FileHandler decides by itself to add the extension.

This is how java works with enabled rotation.

I agree with Roger, that seems like a bug in the J2SE code. It is certainly not intuitive, when one specifies %g to come before the .log for there to be an arbitrary addition after.

Is there anything we can do about this other than not rotate the log files (not a good solution).

Greg Shah wrote:

I agree with Roger, that seems like a bug in the J2SE code. It is certainly not intuitive, when one specifies %g to come before the .log for there to be an arbitrary addition after.

I'm testing it right now. It seems odd indeed. I'll get back to you with the results.

Can someone approve 5703b, cause it has important fixes that need to be merged and then we can improve on rotation in another branch.

• src/com/goldencode/p2j/util/logging/CentralLoggerClientStandalone.java has just whitespace changes, please revert it
• history entries need to be added to all files
• Hynek: please review the ext/sheet/build.gradle change

I'll need to test some apps, if it works, you can merge it to trunk.

5703b r14577.

• src/com/goldencode/p2j/util/logging/CentralLoggerClientStandalone.java has just whitespace changes, please revert it

fixed

• history entries need to be added to all files

fixed

• Hynek: please review the ext/sheet/build.gradle change

It's still in the classpath, but not duplicated.

I'll need to test some apps, if it works, you can merge it to trunk.

I'll be waiting for the merge approval.

Hynek: please review the ext/sheet/build.gradle change

Hynek is not available until Friday. We need to make the call now without his review.

Greg Shah wrote:

Hynek: please review the ext/sheet/build.gradle change

Hynek is not available until Friday. We need to make the call now without his review.

It's not a difficult one. The libs are still present in the classpath. That was the issue actually. They were duplicated.