[improve][broker] Bridge JUL to Log4j2 to unify third-party library logging under the project's Log4j2 configuration - #26330
Conversation
…ogging under the project's Log4j2 configuration
|
@lhotari |
|
Please merge origin/master and resolve merge conflicts since log4j has been upgraded to 2.26.1 version |
…LogAppender for validation
# Conflicts: # distribution/server/src/assemble/LICENSE.bin.txt # distribution/shell/src/assemble/LICENSE.bin.txt
|
checkstyle fails |
There was a problem hiding this comment.
Thanks for picking this up, @geniusjoe — bridging JUL is the right call and the wiring you did is sound.
I checked the parts that usually go wrong with this change and they hold up: every path you added the flag to does have log4j-jul on its classpath, in the distributions (lib/*) and in a dev checkout (bin/pulsar and bin/pulsar-perf fall back to distribution/server/build/classpath.txt, bin/pulsar-admin-common.sh to the shell one, and exportClasspath writes both from distLib). The flag and the testRuntimeOnly dependency both come from pulsar.java-conventions, so test JVMs can't get one without the other. I also ran log4j-jul 2.26.1 standalone to confirm the level mapping the new test asserts (SEVERE→ERROR, WARNING→WARN, INFO→INFO) and that message text passes through unmangled. Catalog entry and both LICENSE.bin.txt files are correct.
Requesting changes for a few completeness gaps, plus one semantics change that I think needs to be an explicit decision rather than something we inherit by default.
1. Function instance JVMs don't get the flag
RuntimeUtils.getCmd builds a fresh command — args.add("java") / args.add("-cp") at RuntimeUtils.java:334-335 — and adds the logging properties at :361-372, but never java.util.logging.manager. Child JVMs don't inherit the parent's -D flags, so process- and Kubernetes-runtime functions aren't bridged. gRPC is the functions control-plane transport and logs exclusively via JUL, so this is a meaningful gap rather than a corner case.
One subtlety for whoever fixes it: the child -cp is only the java-instance.jar fat jar, and pulsar-functions/runtime-all/build.gradle.kts:36-38 bundles log4j-slf4j2-impl, log4j-api and log4j-core but not log4j-jul. Adding the flag alone might still work by accident — the JDK's LogManager static init retries the class on the thread context classloader, and JavaInstanceMain builds a classloader from pulsar.functions.instance.classpath (lib/*, which does contain log4j-jul) that JavaInstanceStarter:177 installs as the TCCL. But that only holds if nothing touches JUL before that line; otherwise you get Could not load Logmanager plus a ClassNotFoundException dump and a silent fallback to the default manager. Please add log4j-jul to runtime-all so it's deterministic instead of ordering-dependent.
If you'd rather keep this PR focused, that's fine — but then please say in the description that function instances are out of scope, so we don't assume they're covered.
2. Several shipped launchers were left out
All of these ship in distributions whose lib/ now contains log4j-jul, so only activation is missing — one line each:
bin/bookkeeper— execs JVMs at:259,:261,:265,:267,:270,:274(bookie, autorecovery,LocalBookKeeper,FileSystemUpgrade,BookieShell, generic command). Right nowbin/pulsar bookieandbin/bookkeeper bookielog differently despite starting the sameorg.apache.bookkeeper.server.Main.bin/function-localrunner— execs at:201.- The Windows launchers —
pulsar-admin.cmd,pulsar-client.cmd,pulsar-shell.cmdandpulsar-perf.cmdallcallbin/pulsar-admin-common.cmd, which wasn't touched (rg logging.manager bin/*.cmdfinds nothing). The server distribution ships all ofbin/(distribution/server/build.gradle.kts:230) and the shell distribution shipspulsar-admin-common.cmdandpulsar-shell.cmdexplicitly (distribution/shell/build.gradle.kts:123,127), so the same CLI at the same version behaves differently on Windows than on Linux/macOS.
3. ApiLoggerAdapter is the default, and this silently breaks java.util.logging.config.file
This is the item I'd most like a deliberate decision on.
In log4j-jul 2.26.1 the LogManager constructor reads the log4j.jul.LoggerAdapter property and, when unset, falls back unconditionally to new ApiLoggerAdapter(). There's no log4j-core auto-detection any more: 2.23.1 did LoaderUtil.loadClass(CORE_LOGGER_CLASS_NAME) and picked CoreLoggerAdapter when it succeeded, and 2.24.0 replaced that with a plain // Use API by default / new ApiLoggerAdapter() (logging-log4j2#2353, cited in the source). So even though we ship log4j-core everywhere the bridge is enabled, we get the API adapter, whose isLoggable(...) consults only the Log4j2 level and whose log(LogRecord) never invokes JUL Handlers. Both mutators warn via StatusLogger, which conf/log4j2.yaml:22 suppresses at status: ERROR, so it all fails silently.
I measured this on JDK 21 with log4j 2.26.1, using a logging.properties containing io.grpc.level=SEVERE:
| stock JUL (today) | after this PR | + CoreLoggerAdapter |
|
|---|---|---|---|
java.util.logging.config.file level |
honoured — INFO suppressed | ignored | still ignored |
programmatic Logger.setLevel() |
works | warns, no effect | works |
addHandler(...) |
works | inert | inert |
So the operator-visible regression is real: anyone currently damping a chatty third-party logger through -Djava.util.logging.config.file loses that suppression on upgrade, and those records then flow at the Log4j2 root level (info by default). Note that switching to -Dlog4j.jul.LoggerAdapter=org.apache.logging.log4j.jul.CoreLoggerAdapter does not fix it — it only restores the programmatic API. The reason is structural: log4j-jul's LogManager.addLogger always returns false, so JUL never registers a logger to apply the file's .level entries to, under either adapter.
That means those levels have to move into conf/log4j2.yaml, and it needs a release note. Nothing in this PR compensates for it today.
There's a smaller build-side echo of the same root cause: the convention plugin applies the flag to every test JVM (pulsar.java-conventions.gradle.kts:262), and Gradle's test worker installs its own JUL capture — JavaUtilLoggingSystem.startCapture() does LogManager.reset(), SLF4JBridgeHandler.install() and a root setLevel(...) at the JUL level mapped from Gradle's log level (WARNING at the default LIFECYCLE) — all three of which become no-ops under ApiLogger. For most modules the net effect is nil, since they pick up buildtools/src/main/resources/log4j2.xml at root warn, the same threshold; but pulsar-broker, pulsar-proxy and pulsar-client-admin ship their own test config at root INFO, so those test JVMs will surface JUL records that were previously filtered.
4. The comment overstates what happens by default
The comment added to all three scripts says the records are "routed to pulsar.log instead of stdout". That isn't accurate in either direction:
- Console is the default, not a file.
bin/pulsar:331defaultsPULSAR_LOG_APPENDERtoRoutingAppenderand:334defaults the route toConsole, whichconf/log4j2.yaml:61targets atSYSTEM_OUT;bin/pulsar-admin-common.sh:152,158has the same defaults, andbin/pulsar-perf:147usesConsoleoutright. Onlybin/pulsar-daemon:81switches toRollingFile. So under a plainbin/pulsar broker, and in the container images, bridged records still go to stdout. - And it's never literally
pulsar.log.bin/pulsar:389-420defaultsPULSAR_LOG_FILEper command (pulsar-broker.log,bookkeeper.log,pulsar-proxy.log, …), andbin/pulsar-daemon:124usespulsar-$command-$HOSTNAME.log.pulsar.logis only the fallback inconf/log4j2.yaml:31-32, which applies to the CLI tools — and those default to Console anyway.
None of this undermines the change: the records now go through our Log4j2 config with our layout, levels and appender routing. Worth noting a real side benefit too — the JDK's default JUL ConsoleHandler writes two-line SimpleFormatter text to stderr, so with PULSAR_LOG_FORMAT=json those records used to break JSON parsing wherever the two descriptors get merged (the container images, and bin/pulsar-daemon:160's nohup … > "$out" 2>&1); after this change they're well-formed JSON on stdout. Please just reword the comment (and the motivation section) to say the records are routed through Log4j2 rather than specifically to pulsar.log.
5. No way to override the bridge
In all three scripts the new flag is appended after the user's extra options — bin/pulsar:326,328 (BOOKIE_EXTRA_OPTS / PULSAR_EXTRA_OPTS) versus :363, bin/pulsar-admin-common.sh:148 versus :172, bin/pulsar-perf:144 versus :171. Duplicate -D properties are last-wins, so an operator who sets PULSAR_EXTRA_OPTS=-Djava.util.logging.manager=... (an APM agent supplying its own LogManager, or simply wanting to revert) is silently overridden, even though bin/pulsar:88 documents PULSAR_EXTRA_OPTS as "Extra options to be passed to the jvm".
Every -Dpulsar.log.* flag in that block has the same ordering, but each is backed by a PULSAR_LOG_* env var; this one changes JVM-global JUL semantics with no escape hatch at all.
The good news is that these scripts already have the right idiom for exactly this case — -Djava.net.preferIPv4Stack=true is prepended early so that the later *_EXTRA_OPTS append wins on last-wins:
bin/pulsar:269—OPTS="-Djava.net.preferIPv4Stack=true $OPTS -Djute.maxbuffer=10485760", withPULSAR_EXTRA_OPTSappended at:328bin/pulsar-admin-common.sh:99—OPTS="-Djava.net.preferIPv4Stack=true $OPTS", withPULSAR_EXTRA_OPTSat:148bin/pulsar-perf:96—OPTS="-Djava.net.preferIPv4Stack=true $OPTS ...", withPULSAR_EXTRA_OPTSat:144
That's the closest analogue to this flag: another JVM-global -Djava.* platform default that we want to set but still let operators override. So the fix is the same one line in each of the three scripts:
OPTS="-Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager $OPTS"placed anywhere before the *_EXTRA_OPTS append — right next to the preferIPv4Stack line is the natural home. (bin/bookkeeper:198 sets preferIPv4Stack the same way, which is convenient for item 2.) No new environment variable needed; a PULSAR_JUL_BRIDGE_ENABLED switch would be a reasonable extra on top, but it isn't a substitute, since it wouldn't make PULSAR_EXTRA_OPTS itself win.
6. The description is stale
"Verifying this change" still describes PersistentTopicsTest.testGetMessageByIdLargePropertiesExceed16KB, but e83a7135d24 removed that method and replaced it with JulBridgeTest; no oversized-header test remains. Please update that section so the PR describes what it actually adds. Given items 3 and 4, "Anything that affects deployment" is worth ticking too.
One last practical note, not a change request: the bin/ scripts only regenerate distribution/*/build/classpath.txt when the file is missing, and nothing else depends on exportClasspath. So anyone with a checkout that already ran a bin/ script before this merges will have a cached classpath.txt without log4j-jul and will get the Could not load Logmanager stack trace until they delete it. Might be worth a line in the PR description so people aren't confused by it.
2 participants
Fixes #26229
Motivation
Third-party libraries used by Pulsar (Jersey/Jetty, gRPC, Guava, etc.) log via
java.util.logging(JUL). Without a JUL-to-Log4j2 bridge, these logs are written directly to stdout/stderr and never appear inpulsar.log. This makes it very difficult to diagnose issues in production — for example, when Jetty throws "Response Header Fields Too Large" due to oversized message properties in HTTP response headers, the error is only visible on stdout and lost from the structured log file.Modifications
Added
log4j-juldependency (org.apache.logging.log4j:log4j-jul) to the version catalog (gradle/libs.versions.toml) and to the server/shell distribution builds.Configured JUL bridge in startup scripts — Added
-Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManagertobin/pulsar,bin/pulsar-admin-common.sh, andbin/pulsar-perfso that all JUL logs are routed to Log4j2 at runtime.Configured JUL bridge for tests — Added the same JVM argument and
testRuntimeOnlydependency inpulsar.java-conventions.gradle.ktsso that all module tests also use the JUL bridge.Updated LICENSE files — Added the Apache-2.0 license entry for
log4j-julin both server and shell distribution LICENSE files.Added a test (
PersistentTopicsTest.testGetMessageByIdLargePropertiesExceed16KB) that verifies:org.apache.logging.log4j.jul.LogManager)maxResponseHeaderSize(16384 bytes), the admin API returns HTTP 500Verifying this change
This change added tests and can be verified as follows:
testGetMessageByIdLargePropertiesExceed16KBinPersistentTopicsTestthat validates JUL bridge activation and the expected HTTP 500 behavior when response headers overflow.pulsar-common,pulsar-broker-common,pulsar-broker,pulsar-metadata,pulsar-client-original,pulsar-proxy,managed-ledger,pulsar-transaction-coordinator) to confirm the global JVM argument change does not break existing tests.Current error format:
Does this pull request potentially affect one of the following parts:
Local Workflow
geniusjoe#2