FWD » Core Development » Runtime Infrastructure

Implement more flexible formatter for log records, configurable in directory.xml.

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.

Be aware that the separate spawner process can be removed with the work related to enhancing authentication methods.

As requested in #4065-104 support optional (configurable) shorter versions of package names. Check how other logging libs provide it.

Full flexibility in log formats can be achieved by using a well-established slf4j implementation. Many customers already use such libraries in their own projects or as parts of their FWD deployments, for example the project affected by #7589 (using Spring logging), or #8248 (using log4j), or #8023 (using logback). Changing the logging provider is a matter of adding the library .jar file to the server and clients classpaths and the necessary formatting config file (usually parsed automatically from the launch dir), something customers are usually well familiar with, especially those requesting advanced customizations.

CentralLogger currently uses java.util.logging.FileHandler. A directory config can be added to make it switch writing to slf4-api instead. FWD's own slf4j impl CentralSlf4jProvider will have to be aborted on load, currently supported by the JVM arg disableCentralSlf4jProvider.

CentralLogger currently prepares for the logs some data flat (to survive serialization and ultimately comply to java.util.logging.LogRecord api). So this may pose an issue to the fully flexible formatting, if this flat data can't be easily transformed into separate fields, consumable by the logging provider. But that is an issue deriving from the complexity of the logging lifecycle in FWD in general and applies to any work on the formatting, it's not directly related to the use of an external lib.

This task does not include discussion on how to feed LOG-MANAGER logs to a new consumer.

It is possible that a customer's slf4j implementation will cause dependency conflicts with FWD. This will be an issue that the customer must handle. If a functional or performance bug in FWD can only be recreated with the customer's added logging customizations/dependencies, then this is not a real FWD bug to resolve.

Galya: Please ensure there is some documentation to this effect when you write the docs for this.

I found a partial solution to the problem of pre-init logs and crash files that have to be migrated to slf4j. The flag to enable slf4j is to be a jvm arg instead of a dir config to kick in right away. If FWD loggers are still not initialized with regular dir configs and the JVM exits, then instead to a crash log file, we can write to slf4j. All good. The remaining issue is with server-side filesystem and clients without slf4j impl and configuration. With server-side logs you can expect to have the slf4j setup only on the server, but if the client crashes early it won't send logs to the server. I'm not sure what's the solution.

Galya B wrote:

I found a partial solution to the problem of pre-init logs and crash files that have to be migrated to slf4j. The flag to enable slf4j is to be a jvm arg instead of a dir config to kick in right away. If FWD loggers are still not initialized with regular dir configs and the JVM exits, then instead to a crash log file, we can write to slf4j. All good. The remaining issue is with server-side filesystem and clients without slf4j impl and configuration. With server-side logs you can expect to have the slf4j setup only on the server, but if the client crashes early it won't send logs to the server. I'm not sure what's the solution.

Well, there is only one way out. Always make sure the clients have the slf4j impl in the classpath and configs, even with server-side filesystem. There is nothing else to be done. This would make slf4j + server-side client logs a bit unnecessary though, if clients can use the mechanism of sending the logs themselves.

Do we use CentralLogger logs for the tests run by FWDTestEngine?

The original OE tests themselves have the log-it custom logging functionality and I'm not sure how that's migrated, but I have the gut feeling the tests themselves still don't use CentralLogger. Maybe the engine itself uses it though, no idea. Kind of important though. I moved the logging initialization after SecurityManager is created and now FWDTestEngine complains, because it needs to execute a method available only in drivers (server/client).

So if someone can confirm if fwd logs are used or not, will be very helpful.

Actually the log-it thing is not related. I was thinking about the LOG-MANAGER that had to be used. Anyways, the question still stands.

4GL tests will not write directly to CentralLogger if that is what you are asking. They may write to LOG-MANAGER or not. Any runtime issues would certainly go to CentralLogger.

FWDTestEngine is our implementation of ABLUnit/OEUnit 4GL unit testing. The 4GL test code in such unit tests is just normal 4GL code. It can run in OE or in FWD, so there is nothing in it that knows anything about CentralLogger.

I forgot the engine itself might need to be debugged, so it makes sense to use the FWD logs. As for the progress tests, it's a different story. OK, I'll have to get creative again.

Any ideas what can cause DirectoryService.lockRO to return false? I got myself a stumbling block somehow, but I don't see any reasonable explanation how. Some directory configs (like clientConfig/gui/project_token and webClient/override) are not read. The same directory works with trunk and the branch is freshly rebased.

Normally it won't fail unless you're reading when not bound or you pass a null nodeid.

DirectoryService.clwa, that is used to check for bound, is ContextLocal, so I guess the directory service needs to be bound on each thread. It seems the jetty threads suddenly stopped being bound and resolving configs on them doesn't work in 7279a. It is strange, because there are no changes to web, only to the loggers, so I guess some implicit relationship got broken.

I tried to bind directory before each request handling, but it didn't work too. DirectoryService is initialized, but not bound. I really have no more ideas how to fix this.

Galya B wrote:

DirectoryService.clwa, that is used to check for bound, is ContextLocal, so I guess the directory service needs to be bound on each thread.

Yes, this is true but it is not really the thread so much as the context. On the other hand, in most cases they are the same thing, but not in all cases (e.g. when we run using the Dispatcher instead of Conversation mode).

It seems the jetty threads suddenly stopped being bound and resolving configs on them doesn't work in 7279a. It is strange, because there are no changes to web, only to the loggers, so I guess some implicit relationship got broken.

I thought that generally, the jetty threads don't run with any FWD context.

I tried to bind directory before each request handling, but it didn't work too. DirectoryService is initialized, but not bound. I really have no more ideas how to fix this.

Do we need to read the directory for every request? I hope not, that seems like unnecessary overhead for something that we need to be high throughput. Anything related to initialization of logging should be done only one time per context creation. Anyway, I think we will need more details to help. For example, I'm not clear on what code (running on what context/thread) is modified to "bind directory before each request handling".

Constantin: Please review. Also, please post ideas about this directory reading issue.

Greg Shah wrote:

I tried to bind directory before each request handling, but it didn't work too. DirectoryService is initialized, but not bound. I really have no more ideas how to fix this.

Do we need to read the directory for every request? I hope not, that seems like unnecessary overhead for something that we need to be high throughput.

This is a good point. I haven't reworked all placed where configs are resolved with each request. It's a good time to do so.

Anything related to initialization of logging should be done only one time per context creation. Anyway, I think we will need more details to help.

Everything 'logging' is resolved on initialization (after SecurityManager is created), so this is not related.

For example, I'm not clear on what code (running on what context/thread) is modified to "bind directory before each request handling".

I added bind just for test locally, haven't committed the code, because it didn't fix anything. I first tried adding it to the jetty server thread factory in GenericWebServer constructor (overriding QueuedThreadPool.newThread), and then on each request in WebDriverHandler.handle.

I had to rework a few more places on top of the configs to remove all dependencies on directory. Now web works.

r15370 for review.

• The logging initialization has been moved after SecurityManager is created to allow the log record context for MDC vars to be read once for the thread and stored instead of being read from SecurityManager for each log. The caveat is that crash logs now can be generated with more content (pre-init period is longer).
• MDC vars are thread local.

Constantin, how is the review going?

• what happens with the spawner errors, if slf4j is enabled at the FWD server? I ask because there is no impl for slf4j at NativeSpawnerConnection classpath.
• existing customers which use their own spawner setup scripts need to be aware of this change, that slf4j-api.jar needs to be installed
• you mention that MDC vars are thread local; I can't 'see' this in the code: org.slf4j.MDC relies on a static mdcAdapter field, which gets resolved via the provider. So, is the provider's responsibility to have this thread-local?
• if you haven't already, please configure a large app with slf4j and test if the appservers and the GUI client starts properly.

Constantin Asofiei wrote:

• what happens with the spawner errors, if slf4j is enabled at the FWD server? I ask because there is no impl for slf4j at NativeSpawnerConnection classpath.

The default FWD slf4j implementation is already part of the p2j.jar itself, because in slf4j v2 the provider can be changed with jvm arguments. The NativeSpawnerConnection jvm doesn't need to use another slf4j impl, because it logs with the fallback CentralLogger and writes to stderr that is handled server-side, so the default slf4j provider serves it well. It still needs slf4j-api as a dependency in the classes.

• existing customers which use their own spawner setup scripts need to be aware of this change, that slf4j-api.jar needs to be installed

postbuild.sh copies slf4j-api.jar from the lib dir to the spawner location, but if customers rely on custom postbuild scripts or don't use the script at all, then yes, they will have to make the change.

• you mention that MDC vars are thread local; I can't 'see' this in the code: org.slf4j.MDC relies on a static mdcAdapter field, which gets resolved via the provider. So, is the provider's responsibility to have this thread-local?

The interface MDCAdapter says in the javadoc of put:

     * Put a context value (the val parameter) as identified with
     * the key parameter into the current thread's context map. 

• if you haven't already, please configure a large app with slf4j and test if the appservers and the GUI client starts properly.

Do you mean to enable a custom slf4j implementation for a random customer?

Galya B wrote:

• if you haven't already, please configure a large app with slf4j and test if the appservers and the GUI client starts properly.

Do you mean to enable a custom slf4j implementation for a random customer?

Yes, I'd like to have this tested with a real app (whatever you have setup).

Tested with customer app. When do I merge?

Galya B wrote:

Tested with customer app. When do I merge?

This can be merged to trunk now.

SsoAuthenticator.authenticate is called on Jetty threads and in hotel_gui that's where the db configs are read from directory. Now that Jetty threads no longer can read directory, an issue is reported in #7143-1126.

The fix requires adding a new method to SsoAuthenticator that is called on the server main thread, as early as persistence is initialized.

7279b r15373 for review. Related hotel_gui fix will be committed after 7279b is merged.

• please rename readDirectory to initialize
• please move this code to another serverHooks.add(new AbstractInitTermListener() block, after persistence and add a comment that it needs to be after it. All server hooks are executed in order.

Constantin Asofiei wrote:

Review for 7279b 15373:

• please rename readDirectory to initialize

I'm not sure. Why do we need initialize, it doesn't say anything about the need of this method.

• please move this code to another serverHooks.add(new AbstractInitTermListener() block, after persistence and add a comment that it needs to be after it. All server hooks are executed in order.

If it's not in the same hook after time the order can be shuffled and hotel_gui will be broken again.

What about initializeOnServerMain? \* Edited \*

Or initializeWithServerContext.

I'm not sure. Why do we need initialize, it doesn't say anything about the need of this method.

No, the javadoc for initialize can explain that this method can contain code to execute (like reading directory configs) on server startup, after the FWD server has initialized other components, like database connections.

And while we are talking about initialization at FWD server startup, the InitTermListener also has a terminate method, which will be executed on the FWD server shutdown - so we may want to add this also to the SSO interface, in case the plugin wants to cleanup at FWD server shutdown (but I don't think is needed for now).

If it's not in the same hook after time the order can be shuffled and hotel_gui will be broken again.

I understand, but lets have this added last (just before the if (isSecure) check). Comments can explain why it can't be moved. More, the current change initializes the SSO only if persistence is active, which is not necessarily the case.

7279b r15374.

Galya B wrote:

7279b r15374.

Thanks, I'm OK with the changes.

A customer detected that the Testcases project seems broken by this change.
After manually copying and restart of the server, it worked again:

cd testcases/deploy/spawner
sudo cp -p ../lib/slf4j-api-2.0.13.jar .

Do other GCD devs have this issue?
If it's due to some specific process at the customer, I'll handle that.
But if testcases deploy isn't up to date yet, please inform/address.

Galya, note that the customer didn't pinpoint this task to be the cause. This was an assumption.
The problem is present in rev 15383.
The problem is not present in rev 15364.

Tijs Wickardt wrote:

A customer detected that the Testcases project seems broken by this change.
After manually copying and restart of the server, it worked again:
[...]

Do other GCD devs have this issue?
If it's due to some specific process at the customer, I'll handle that.
But if testcases deploy isn't up to date yet, please inform/address.

Galya B wrote:

• existing customers which use their own spawner setup scripts need to be aware of this change, that slf4j-api.jar needs to be installed

postbuild.sh copies slf4j-api.jar from the lib dir to the spawner location, but if customers rely on custom postbuild scripts or don't use the script at all, then yes, they will have to make the change.

This is mentioned in the merge notification in #8828-113.

Galya B wrote:

This is mentioned in the merge notification in #8828-113.

1. Do other GCD devs have this issue?
2. If testcases deploy isn't up to date yet, please inform/address.

Tijs Wickardt wrote:

Galya B wrote:

This is mentioned in the merge notification in #8828-113.

Thanks.
That leaves:

1. Do other GCD devs have this issue?
2. If testcases deploy isn't up to date yet, please inform/address.

Noone who uses an up-to-date testcases is having an issue, if using install_spawner.sh on deployment.

If someone has modified the included p2j postbuild.sh they will have an issue and they need to fix it, but with vanilla FWD trunk revision of postbuild.sh the library is copied as expected.

Edited: postbuild.sh

Thank you Galya, it must be a customer thing then. I'll look into it.
Roger: I presume no changes to existing install_spawner.sh in testcases is needed (because there is no overriding postbuild.sh in testcases AFAICS ).

dev@ubuntu-desktop:/v1/<appname>-dev.local/workspace/eclipse/xfer_testcases$ bzr log -l1 -S ./install_spawner.sh
 1554 Roger F Borrello    2024-02-28
      Updated files for standardization and added docker capabilities.

dev@ubuntu-desktop:/v1/<appname>-dev.local/workspace/eclipse/xfer_testcases$ bzr log -l2 -S
 1622 es    2024-08-14
      added some tests to validation and flushing testcases

 1621 Bursuc Serban    2024-08-14
      Ported /testcases/uast/combo_box/screen_value to /abl_unit/combobox/screenvalue

 bzr log -l1 -S ./p2j/src/native/postbuild.sh
15368 Galya Bogdanova    2024-08-05 [merge]
      CentralLogger support for writing to slf4j-api (refs #7279)

Yes, if not customized the default install_spawner.sh calls postbuild.sh from the trunk branch that is already modified to copy the file.

Tijs Wickardt wrote:

Roger: I presume no changes to existing install_spawner.sh in testcases is needed (because there is no overriding postbuild.sh in testcases AFAICS ).

There were some minor changes I just checked in so that it would match up with the standard version in hotel_gui.