JDK loggers can initialize the JDK LogManager before GlassFishLogManager is set

[szarza]

Environment Details

• GlassFish Version (and build number): 7.0.17
• JDK version: 21
• OS: Red Hat

---

Problem Description

After "start-domain" and executing

$ASADMIN multimode --file calypso.config7.txt (attached)

Glassfish stops logging.

Notes:

• I've tried separated set-log-attributes with the same effect
• I've tried "only" set-log-attributes configuration with the same effect

calypso.config7.txt

Steps to reproduce

Execute attached configuration

Impact of Issue

Glassfish stops logging

[dmatej]

Just for sure, do you have write permissions to /var/log/cestel/calypso/server.log file?

[dmatej]

/app/appservers/glassfish7/glassfish/bin/asadmin set-log-attributes org.glassfish.main.jul.handler.GlassFishLogHandler.rotation.rollOnDateChange=true\:org.glassfish.main.jul.handler.GlassFishLogHandler.rotation.compress=true\:org.glassfish.main.jul.handler.GlassFishLogHandler.rotation.maxArchiveFiles=20\:org.glassfish.main.jul.handler.GlassFishLogHandler.file=/var/log/cestel/calypso/server.log

This really broke logging. If anything in your logging configuration breaks, the logging configuration is invalid. However enabling the configuration is not transactional. Maybe we could improve it.

The problem with logging is also that set-log-attributes cannot verify your file system because the target server can be on another computer. Maybe it could validate that for the "server" target which should be local from the domain admin point of view.

sudo mkdir -p /var/log/cestel/calypso/
sudo chown dmatej:dmatej /var/log/cestel/calypso
/app/appservers/glassfish7/glassfish/bin/asadmin set-log-attributes org.glassfish.main.jul.handler.GlassFishLogHandler.rotation.rollOnDateChange=true\:org.glassfish.main.jul.handler.GlassFishLogHandler.rotation.compress=true\:org.glassfish.main.jul.handler.GlassFishLogHandler.rotation.maxArchiveFiles=20\:org.glassfish.main.jul.handler.GlassFishLogHandler.file=/var/log/cestel/calypso/server2.log

The file now contains this (the log was not lost):

[2024-09-07T12:00:03.586750+02:00] [GF 7.0.18-SNAPSHOT] [SEVERE] [NCLS-LOGGING-00002] [com.sun.enterprise.server.logging.LogManagerService] [tid: _ThreadID=133 _ThreadName=pool-15-thread-1] [levelValue: 1000] [[
Could not apply the logging configuration changes.
java.lang.IllegalStateException: Failed to create the parent directory /var/log/cestel/calypso
at org.glassfish.main.jul.rotation.LogFileManager.enableOutput(LogFileManager.java:245)
at org.glassfish.main.jul.handler.GlassFishLogHandler.startLoggingIfPossible(GlassFishLogHandler.java:347)
at org.glassfish.main.jul.handler.GlassFishLogHandler.reconfigure(GlassFishLogHandler.java:209)
at com.sun.enterprise.server.logging.LogManagerService.reconfigureGlassFishLogHandler(LogManagerService.java:364)
at com.sun.enterprise.server.logging.LogManagerService$ReconfigurationAction.run(LogManagerService.java:398)
at org.glassfish.main.jul.GlassFishLogManager.reconfigure(GlassFishLogManager.java:458)
at com.sun.enterprise.server.logging.LogManagerService.reconfigure(LogManagerService.java:344)
at com.sun.enterprise.server.logging.LogManagerService$LoggingCfgFileChangeListener.changed(LogManagerService.java:457)
at org.glassfish.kernel.FileMonitoringImpl$3.run(FileMonitoringImpl.java:121)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)
]]

[2024-09-07T12:01:58.113232+02:00] [GF 7.0.18-SNAPSHOT] [INFO] [] [com.sun.enterprise.server.logging.LogManagerService] [tid: _ThreadID=134 _ThreadName=pool-16-thread-1] [levelValue: 800] [[
Detected change of file: /media/data-samsung/data/dmatej/work/app/appservers/glassfish7/glassfish/domains/domain1/config/logging.properties]]

[2024-09-07T12:01:58.113263+02:00] [GF 7.0.18-SNAPSHOT] [INFO] [] [com.sun.enterprise.server.logging.LogManagerService] [tid: _ThreadID=134 _ThreadName=pool-16-thread-1] [levelValue: 800] [[
Using property file: /media/data-samsung/data/dmatej/work/app/appservers/glassfish7/glassfish/domains/domain1/config/logging.properties]]

[dmatej]

I will close it for now, but if you would find another reason than missing permissions, please reopen the issue.

[szarza]

Is not a permissions issue. Have you restarted the domain after the changes? In my case, when the domain restarts, the server logs one and ony single line (the first one):

[2024-09-09T09:29:09.626929+02:00] [] [INFO] [NCLS-GFLAUNCHER-00005] [jakarta.enterprise.launcher] [tid: _ThreadID=1 _ThreadName=main] [levelValue: 800] [[
  JVM invocation command line:
/opt/cestel/jdk/current/bin/java
....

but stops logging. No more lines are written.

¿How can I reopen this ticket?

[dmatej]

Yes, changes were applied immediately and even after restart the server continued to work. The first log message is written by the asadmin start-domain command, we will probably change this confusing behavior in 8, it should not use the same file.

[dmatej]

Can you try to start the domain with --verbose? It should print some logs to your STDOUT so if the server is broken and cannot start, it should print at least something, reason why. Is it listening on port, can you visit the admin console? - Is it just logging or the server did not start for some reason? asadmin start-domain --verbose

[szarza]

log-verobse.log Attached log of requested output (--verbose)

[szarza]

It seems the problem is due to the commands "delete-domain domain1" / "create-domain calypso". Please, let me explain. I run the following commands before the configuration

asadmin delete-domain domain1
asadmin create-domain --portbase 8000 --checkports=true calypso

then I run

asadmin multimode --port 8048 --file calypso.config7.txt

And the issue occurs within the "calypso" domain. If I skip the domain deletion/creation phase and run "multimode" command directly in domain1, the log is working correctly.

I assumed the behavior was the same across all domains regarding this, and therefore, the fact that it was a different domain seemed irrelevant. I'm afraid I had not considered the implications of executing the configuration commands on a different domain, but it is now clear that it has an impact.

I hope these investigations will bring us closer to understanding the problem.

[dmatej]

Thanks, now I see the problem - missing dependency. Can you list this directory?

/home/szarza/proyectos/cestel/calypso/calypso.installer/glassfish/make/glassfish7/glassfish/lib/bootstrap/

It should contain two jar files:

ll glassfish7/glassfish/lib/bootstrap/
...
-rw-r-----  1 dmatej dmatej 158507 srp 29 22:21 glassfish-jul-extension.jar
-rw-r-----  1 dmatej dmatej   5606 srp 29 22:21 grizzly-npn-api.jar

[szarza]

Yes, it does.

❯ ls -hal /home/szarza/proyectos/cestel/calypso/calypso.installer/glassfish/make/glassfish7/glassfish/lib/bootstrap/
total 172K
drwxr-xr-x.  2 szarza usuarios del dominio 4,0K sep 12 08:48 .
drwxr-xr-x. 11 szarza usuarios del dominio 4,0K sep 12 08:48 ..
-rw-r-----.  1 szarza usuarios del dominio 155K ago 29 22:21 glassfish-jul-extension.jar
-rw-r-----.  1 szarza usuarios del dominio 5,5K ago 29 22:21 grizzly-npn-api.jar

[dmatej]

I was able to reproduce it - it is caused by two lines - when you remove/comment out both of them, GlassFish starts and logging works. I will try to do something about it, it seems that the GC is faster than our main and with these two options it initializes the JDK's LogManager. GlassFish then cannot change it.

#create-jvm-options '-Xlog\:gc*\:file=/var/log/cestel/calypso/calypso-gc-%t.log\:time\:filecount=10\:filesize=10M'
#create-jvm-options '-XX\:ErrorFile=/var/log/cestel/calypso/java_error%p.log'

[dmatej]

Just FYi, this hit much bigger issue I already knew for a long time and which basically led to creation of custom log manager in glassfish - now you proved that even this is not enough and it is required to move it yet the last step to the border of "standard usage" - using JVM options to define logging.properties and log manager.

So here we go with #25183 - it will take yet some time, because it affects a lot of things including TCK, but it should be a part of GlassFish 7.1.0.

[szarza]

Hi: I've tried with Glassfish 7.0.24 with those lines commented with the same result: there's no log after start domain "test" domain.

The process to create the domain is the following:

$ASADMIN delete-domain domain1
$ASADMIN create-domain --portbase 8000 --checkports=true $DOMAIN
cp -r $DOMAIN.lib/* $GLASSFISH_DIR/glassfish/domains/$DOMAIN/lib/
$ASADMIN start-domain $DOMAIN
$ASADMIN multimode --port 8048 --file $DOMAIN.config7.txt
mensaje
$ASADMIN --port 8048 change-admin-password --domain_name $DOMAIN
$ASADMIN --port 8048 enable-secure-admin
$ASADMIN --port 8048 stop-domain $DOMAIN

Attached $DOMAIN.config7.txt

test.config7.txt