Open timja opened 2 years ago
timja
commented
2 years ago I suppose it may be possible to use a different java.util.logging configuration when running under systemd(1). But we need to retain the existing configuration when running in a container (e.g., in Docker/Kubernetes) or from java -jar jenkins.war. Pull requests are welcome.
timja
commented
2 years ago basil, could you give me a hint about WHEREthe global logging is initialized (perhaps in the winstone or extras-executable-war repository?)
I also searched for sd_journal_print/sd_journal_send (the native structured logging calls for systemd's journal) but could not find those?!
Checking for systemd is easy: just compare the value of SYSTEMD_EXEC_PID against the current PID. If they are equal, we are running in systemd.
timja
commented
2 years ago It's initialized in Winstone's Launcher#initLogger. I just checked the environment variables for my running (under systemd(1)) Java process and I didn't see SYSTEMD_EXEC_PID listed, so I'm not sure how you were planning on reading it, but I do see NOTIFY_SOCKET=/run/systemd/notify, which is defined when Type=notify in the service unit (which is true for the service unit shipped by the Jenkins project and not expected to be customized by users), so I think it makes sense to key on that (and in fact that is what I am doing in core's SystemdLifecycle class). One caveat to keep in mind is that extras-executable-war/Winstone do support a --logfile argument to redirect output to a file, even when running under systemd(1). And implementing support for this might be non-trivial, since it appears extras-executable-war subverts Winstone by intercepting this argument and handling it separately (what appears to me to be long-standing technical debt). Ideally we would first move the logging-related code from extras-executable-war to Winstone, which would then make it easier to implement what you are describing in Winstone's Launcher#initLogger.
timja
commented
2 years ago Thanks for the hint.
How did you check for SYSTEMD_EXEC_PID? I can definitively see it here (on Fedora 34) using ps axe:
[root@fsun ~]# ps axe | grep java 3254064 ? Ssl 6:09 /usr/bin/java -Djava.awt.headless=true -Xmx2048m -jar /usr/share/java/jenkins.war --webroot=/var/cache/jenkins/war --httpPort=8080 SHELL=/bin/bash PWD=/var/lib/jenkins LOGNAME=jenkins SYSTEMD_EXEC_PID=3254064 HOME=/var/lib/jenkins LANG=en_US.UTF-8 INVOCATION_ID=185924a228ce463b94b58400b4d88f27 USER=jenkins NOTIFY_SOCKET=/run/systemd/notify SHLVL=0 JENKINS_HOME=/var/lib/jenkins JOURNAL_STREAM=8:24043757 PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin
Also, it is documented in systemd.exec(5)
Regarding the actual logging, I guess I will write a new LogHandler which uses sd_journal_send() to preserve the various fields instead of formatting them and then feeding the formatted text into syslog. Doing real structured logging is much more versatile. E.g. makes it possible to filter by any field using journalctl, also full qualified classnames could be stored as metadata and displayed on demand with journalctl
timja
commented
2 years ago The first reference to SYSTEMD_EXEC_PID I can find is in v248 of systemd(1), which is relatively recent. My Ubuntu 20.04 desktop is running v245 which doesn't seem to have this variable, but it does have NOTIFY_SOCKET. From a compatibility perspective we claim to support all the distributions listed in https://github.com/jenkinsci/packaging/blob/f2b64a7fd4bef80c30739794b03f7fb791b7723d/molecule/default/molecule.yml so unfortunately we have to support very old versions of systemd(1).
timja
commented
2 years ago Regarding the actual logging, I guess I will write a new LogHandler which uses sd_journal_send() to preserve the various fields instead of formatting them and then feeding the formatted text into syslog. Doing real structured logging is much more versatile. E.g. makes it possible to filter by any field using journalctl, also full qualified classnames could be stored as metadata and displayed on demand with journalctl
I think this is a great idea, and I would love to see this, but it will be tricky to implement because of the very convoluted execution path of extras-executable-war and Winstone. Basically, java -jar jenkins.war starts the Main class from extras-executable-war, which extracts winstone.jar from jenkins.war (which is placed there specially by the build in jenkinsci/jenkins/war/pom.xml) and then invokes Winstone's launcher via reflection. So because of this Winstone can't have any third-party dependencies, at least not in the conventional sense. And what you're describing would need a third-party dependency on JNA I think.
Now, obviously Winstone does have a third-party dependency on Jetty, but this is conveniently side-stepped by the fact that Winstone shades Jetty into its JAR with maven-shade-plugin. The same couldn't be done for JNA, since that would conflict with the non-shaded version in Jenkins core. So this all gets very tricky. I'm open to considering various workarounds, but really I think the long-term solution is to merge extras-executable-jar with Winstone and possibly to merge both with Jenkins core to avoid all of this convoluted execution. If you're serious about implementing sophisticated support for systemd(1) logging and need that cleanup work as a prerequisite, I could look into doing it myself, but I wouldn't be able to do it right away, and it would definitely need some more discussion on the developer mailing list.
After upgrading to 2.332.1 using the new journal logging, There are TWO time stamps in every line of the log. Example:
The first time stamp is from jounal logging and the second from jenkin's logging. I suggest to remove the second one. The various time-based filters of journalctl use the first one anyway so the second one is quite useless now. Note: the time difference in the above example is caused by the the difference of CEST (localtime, used in journalctl) vs. UTC (used by jenkins logging).
Originally reported by felfert, imported from: Superfluous timestams in new journal log