Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

JDK loggers can initialize the JDK LogManager before GlassFishLogManager is set #25133

Open
szarza opened this issue Sep 6, 2024 · 12 comments · Fixed by #25172 · May be fixed by #25183
Open

JDK loggers can initialize the JDK LogManager before GlassFishLogManager is set #25133

szarza opened this issue Sep 6, 2024 · 12 comments · Fixed by #25172 · May be fixed by #25183
Assignees
@dmatej
Labels
bug Something isn't working In Progress
Milestone
7.1.0

Comments

@szarza
Copy link

szarza commented Sep 6, 2024

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
Copy link
Contributor

dmatej commented Sep 7, 2024

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

@dmatej
Copy link
Contributor

dmatej commented Sep 7, 2024 

/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
Copy link
Contributor

dmatej commented Sep 7, 2024

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

@dmatej dmatej closed this as completed Sep 7, 2024
@szarza
Copy link
Author

szarza commented Sep 9, 2024 •
edited
Loading

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?

@szarza szarza changed the title Glassfish 7.0.17 stops logging after configure a domain Glassfish 7.0.17 stops logging after configure a domain (logs only first log) Sep 9, 2024
@dmatej
Copy link
Contributor

dmatej commented Sep 9, 2024

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
Copy link
Contributor

dmatej commented Sep 9, 2024

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
Copy link
Author

szarza commented Sep 10, 2024

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

@szarza
Copy link
Author

szarza commented Sep 10, 2024 •
edited
Loading

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.

@szarza szarza changed the title Glassfish 7.0.17 stops logging after configure a domain (logs only first log) Glassfish 7.0.17 stops logging after configure a new domain (java.lang.ClassNotFoundException: org.glassfish.main.jul.handler.GlassFishLogHandler) Sep 11, 2024
@dmatej
Copy link
Contributor

dmatej commented Sep 11, 2024

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
Copy link
Author

szarza commented Sep 12, 2024

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
Copy link
Contributor

dmatej commented Sep 23, 2024

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 dmatej reopened this Sep 23, 2024
@dmatej dmatej changed the title Glassfish 7.0.17 stops logging after configure a new domain (java.lang.ClassNotFoundException: org.glassfish.main.jul.handler.GlassFishLogHandler) JDK loggers can initialize the JDK LogManager before GlassFishLogManager is set Sep 24, 2024
@dmatej dmatej added this to the 7.0.18 milestone Sep 24, 2024
@dmatej dmatej added the bug Something isn't working label Sep 24, 2024
@dmatej dmatej self-assigned this Sep 24, 2024
@dmatej dmatej modified the milestones: 7.0.18, 7.0.19 Sep 29, 2024
This was referenced Oct 3, 2024
Open
Merged
Merged
@dmatej dmatej reopened this Oct 12, 2024
@dmatej dmatej linked a pull request Oct 12, 2024 that will close this issue
Draft
@dmatej dmatej modified the milestones: 7.0.19, 7.1.0 Oct 31, 2024
@dmatej
Copy link
Contributor

dmatej commented Nov 24, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dmatej dmatej

Labels
bug Something isn't working In Progress
Projects
None yet
Milestone
7.1.0
Development

Successfully merging a pull request may close this issue.

Smaller cleanups dmatej/glassfish
Redesign of GlassFish bootstrap dmatej/glassfish
2 participants
@dmatej @szarza