Log file handler rotation maximum size is exceeded when process name is long

[michalvavrik]

Describe the bug

I am using Quarkus Log File Handler rotation and set maximum file size to 5K, quarkus.log.handler.file.access-log.rotation.max-file-size=5K, however when my process name is long (like in native, or when my JDK is installed in quite nested directory), maximum file size is exceeded.

Expected behavior

Regardless of a process name value, maximum file size should be respected.

Actual behavior

When the process name is long, log file size is longer (5335 or 5336 bytes). When I add Runtime.getRuntime().halt(1) after failing test assertion, I can see that log file is too big.

mvavrik@fedora:/tmp/aaaaaaaaaaaaaaaaaaaaaaaa/bbbbbbbbbbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccccccc/ddddddddddddddddddddddddddd/eeeeeeeeeeeeeeeeeeeeeeeeeee/fffffffffffffffffffff/guesswhat/ggggggggggggggggggggggg/quarkus-test-suite/logging/jboss$ ls -la target/AccessLoggingIT/app/appAccess.log
-rw-r--r--. 1 mvavrik mvavrik 5336 Nov  6 14:02 target/AccessLoggingIT/app/appAccess.log

How to Reproduce?

Steps to reproduce the behavior:

cd /tmp
mkdir -p aaaaaaaaaaaaaaaaaaaaaaaa/bbbbbbbbbbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccccccc/ddddddddddddddddddddddddddd/eeeeeeeeeeeeeeeeeeeeeeeeeee/fffffffffffffffffffff/guesswhat/ggggggggggggggggggggggg
cd aaaaaaaaaaaaaaaaaaaaaaaa/bbbbbbbbbbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccccccc/ddddddddddddddddddddddddddd/eeeeeeeeeeeeeeeeeeeeeeeeeee/fffffffffffffffffffff/guesswhat/ggggggggggggggggggggggg
git clone git@github.com:michalvavrik/quarkus-test-suite.git -b feature/jboss-logging-max-size-reproducer
cd quarkus-test-suite/logging/jboss

NATIVE:
mvn clean verify -Dit.test=AccessLoggingIT#logRotationTest -Dnative -Dreruns=0

JVM:
# download and unzip OpenJDK from https://access.redhat.com/jbossnetwork/restricted/listSoftware.html?product=core.service.openjdk&downloadType=distributions
export JAVA_HOME="/tmp/aaaaaaaaaaaaaaaaaaaaaaaa/bbbbbbbbbbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccccccc/ddddddddddddddddddddddddddd/eeeeeeeeeeeeeeeeeeeeeeeeeee/fffffffffffffffffffff/guesswhat/ggggggggggggggggggggggg/quarkus-test-suite/long-java-home/java-21-openjdk-21.0.5.0.11-1.portable.jdk.x86_64"
export PATH="$JAVA_HOME/bin:$PATH"
mvn clean verify -Dit.test=AccessLoggingIT#logRotationTest -Dreruns=0

Output of uname -a or ver

Fedora 41, RHEL8

Output of java -version

OpenJDK Runtime Environment (Red_Hat-21.0.5.0.11-1) (build 21.0.5+11-LTS)

Quarkus version or git rev

3.15.1, 999-SNAPSHOT

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.9.9 (8e8579a9e76f7d015ee5ec7bfcdc97d260186937)

Additional information

No response

[gsmet]

I will defer to @jamezp and @dmlloyd but I'm not convinced it's worth fixing.

[dmlloyd]

This is not really fixable. The user could create a directory that only allows for one-character log file names for example. There's not much we can do about it at our end.

To work around the specific problem, change the output directory of the log handler using the quarkus.log.file.path property to put the log files in a less-nested directory. Otherwise my recommendation is: don't do that!

[michalvavrik]

Alright, thank you. Can you please document scenarios under which quarkus.log.handler.file."file-handlers".rotation.max-file-size works? I just spend 2 days to figure why this test is failing and I can assure you I wouldn't if it was documented, which is my motivation to have this documented. Thank you

[michalvavrik]

For context, it only failed in FIPS-enabled environment in native mode when run in Jenkins, so it can be quite a fun to try to figure why this log is bigger. Small docs note would be enough.

[michalvavrik]

To work around the specific problem, change the output directory of the log handler using the quarkus.log.file.path property to put the log files in a less-nested directory.

Change output directory of the log handler? You mean quarkus.log.handler.file.access-log.path=path-to-log to some short path? That doesn't work, I have tried it.

Also, it doesn't surprise me. Both issue title and description speaks about "process name" and not output directory of the log handler. More specifically, I tested it and it matters what how long this part is:

"processName":"/home/hudson/hudson_workspace/workspace/rhbq-3.15-baremetal-ts-native/420ae479/quarkus-test-suite/logging/jboss/target/logging-jboss-1.0.0-SNAPSHOT-runner"

here is "full" log (not the access log):

19:05:41,379 INFO  ## Running test AccessLoggingIT.logRotationTest()
19:05:43,391 INFO  [app] Service stopped (Quarkus NATIVE mode)
19:05:43,392 INFO  Running command: /home/hudson/hudson_workspace/workspace/rhbq-3.15-baremetal-ts-native/420ae479/quarkus-test-suite/logging/jboss/target/logging-jboss-1.0.0-SNAPSHOT-runner -Dquarkus.log.handler.file.access-log.format=%d{yyyy-MM-dd HH:mm:ss} -Dquarkus.http.access-log.enabled=true -Dquarkus.http.access-log.log-to-file=false -Dquarkus.log.handler.file.access-log.path=/tmp/AccessLoggingIT2298614165834377554/appAccess.log -Dquarkus.log.handler.file.access-log.rotation.max-backup-index=2 -Dquarkus.log.handler.file.access-log.enable=true -Dquarkus.log.handler.file.access-log.rotation.max-file-size=5K -Dquarkus.log.category."io.quarkus.http.access-log".use-parent-handlers=false -Dquarkus.log.handler.file.access-log.rotation.file-suffix=yyyy-MM-dd.zip -Dquarkus.log.console.format=%d{HH:mm:ss,SSS} %s%e%n -Dquarkus.log.category."io.quarkus.http.access-log".handlers=access-log -Dquarkus.http.port=1105
19:05:46,397 INFO  [app] {"timestamp":"2024-11-06T19:05:43.469657Z","sequence":516,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus","level":"INFO","message":"logging-jboss 1.0.0-SNAPSHOT native (powered by Quarkus 3.15.1.redhat-00005) started in 0.073s. Listening on: http://0.0.0.0:1105","threadName":"main","threadId":1,"mdc":{},"ndc":"","hostName":"rhel8-fips-xlarge-431","processName":"/home/hudson/hudson_workspace/workspace/rhbq-3.15-baremetal-ts-native/420ae479/quarkus-test-suite/logging/jboss/target/logging-jboss-1.0.0-SNAPSHOT-runner","processId":27608}
19:05:46,398 INFO  [app] {"timestamp":"2024-11-06T19:05:43.469727Z","sequence":517,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus","level":"INFO","message":"Profile prod activated. ","threadName":"main","threadId":1,"mdc":{},"ndc":"","hostName":"rhel8-fips-xlarge-431","processName":"/home/hudson/hudson_workspace/workspace/rhbq-3.15-baremetal-ts-native/420ae479/quarkus-test-suite/logging/jboss/target/logging-jboss-1.0.0-SNAPSHOT-runner","processId":27608}
19:05:46,398 INFO  [app] {"timestamp":"2024-11-06T19:05:43.469742Z","sequence":518,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus","level":"INFO","message":"Installed features: [cdi, resteasy, smallrye-context-propagation, vertx]","threadName":"main","threadId":1,"mdc":{},"ndc":"","hostName":"rhel8-fips-xlarge-431","processName":"/home/hudson/hudson_workspace/workspace/rhbq-3.15-baremetal-ts-native/420ae479/quarkus-test-suite/logging/jboss/target/logging-jboss-1.0.0-SNAPSHOT-runner","processId":27608}
19:05:46,399 INFO  [app] Service started (Quarkus NATIVE mode)
19:05:48,746 INFO  [app] Service stopped (Quarkus NATIVE mode)

Otherwise my recommendation is: don't do that!

Issue as I understand it naively is long path to native executable (AKA process name) is included into log but is not included into max-file-size. So I think "don't do that" means "use short paths only". I don't agree this is reasonable request.

[michalvavrik]

FYI @dmlloyd my colleague created this test based on your suggestion in https://issues.redhat.com/browse/QUARKUS-4663.

[michalvavrik]

Hope I don't overwhelm you with information, but here is how access log looks like on my local machine with short paths in JVM (just FYI):

{"timestamp":"2024-11-06T20:54:13.67287682+01:00","sequence":228,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}
{"timestamp":"2024-11-06T20:54:13.679976273+01:00","sequence":229,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}
{"timestamp":"2024-11-06T20:54:13.685111704+01:00","sequence":230,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}
{"timestamp":"2024-11-06T20:54:13.690072301+01:00","sequence":231,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}
{"timestamp":"2024-11-06T20:54:13.696166336+01:00","sequence":232,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}
{"timestamp":"2024-11-06T20:54:13.702358258+01:00","sequence":233,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}
{"timestamp":"2024-11-06T20:54:13.707562972+01:00","sequence":234,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}
{"timestamp":"2024-11-06T20:54:13.714684917+01:00","sequence":235,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}

[dmlloyd]

OK I misread the error, I thought you were saying "the file name is too long when the process name is long". Let me look at the code before I answer to make sure I don't give wrong information (again).

[michalvavrik]

OK I misread the error, I thought you were saying "the file name is too long when the process name is long". Let me look at the code before I answer to make sure I don't give wrong information (again).

no worry, and yes, I think it is "operation name" because that was the only difference I could see from my machine to Jenkins run. And only way I could reproduce it, but I can easily be wrong.

What makes this weird for me is that I would expect this line

{"timestamp":"2024-11-06T20:54:13.714684917+01:00","sequence":235,"loggerClassName":"org.jboss.logging.Logger","loggerName":"io.quarkus.http.access-log","level":"INFO","message":"127.0.0.1 - - [06/Nov/2024:20:54:13 +0100] \"GET /access HTTP/1.1\" 200 12","threadName":"executor-thread-1","threadId":34,"mdc":{},"ndc":"","hostName":"fedora","processName":"/home/mvavrik/.sdkman/candidates/java/21.0.5-tem/bin/java","processId":21426}

to be treated as any other log message, in which case I don't know why max size doesn't work.

[dmlloyd]

OK the way the logic works, the file size check is performed after the log record is written. So, if your rotation limit is a hard limit on the file size, and particularly when that limit is quite small, it's going to cause a problem because it's quite possible to (for example) fabricate e.g. a GET URI which itself already exceeds the size.

So, I'm not quite sure how to proceed here. What is the use case which requires such a limited file size?

[michalvavrik]

OK the way the logic works, the file size check is performed after the log record is written. So, if your rotation limit is a hard limit on the file size, and particularly when that limit is quite small, it's going to cause a problem because it's quite possible to (for example) fabricate e.g. a GET URI which itself already exceeds the size.

got it

So, I'm not quite sure how to proceed here. What is the use case which requires such a limited file size?

QUARKUS-4663 spoke about max-file-size, so we (Quarkus QE) tried to check this property works. I think that small extra size is not an issue, but I will appreciate if you document it. Thank you

[geoand]

@michalvavrik are you trying to stress the logging rotation subsystem or is there an actual use case for the 5k size limit?
If it's the former, I think we should just document that having a very low limit can be problematic

[michalvavrik]

@michalvavrik are you trying to stress the logging rotation subsystem or is there an actual use case for the 5k size limit? If it's the former, I think we should just document that having a very low limit can be problematic

Just to be clear, I can think of loads of better things to do than finding unimportant bugs :-D Here is why I opened this issue #44346 (comment).

[geoand]

Sure yeah, I didn't mean that you were mindlessly looking to break things :)

[michalvavrik]

Yeah, I can see the other side. But usually when a test is failing in very rare circumstances, I cannot just say "give it up". Now that @dmlloyd explained the issue to me, I'll fix the test for us (allow bigger size). From user POV, note to docs would be good.

[dmlloyd]

OK, here's what the documentation states:

[quarkus.log.file.rotation.max-file-size](https://quarkus.io/guides/logging#quarkus-core_quarkus-log-file-rotation-max-file-size)

The maximum log file size, after which a rotation is executed.

Environment variable: QUARKUS_LOG_FILE_ROTATION_MAX_FILE_SIZE

The key word here is "after". But it's subtle so maybe we need to expand on that a little bit?

[geoand]

The key word here is "after". But it's subtle so maybe we need to expand on that a little bit?

Makes sense

[michalvavrik]

OK, here's what the documentation states:

[quarkus.log.file.rotation.max-file-size](https://quarkus.io/guides/logging#quarkus-core_quarkus-log-file-rotation-max-file-size)

The maximum log file size, after which a rotation is executed.

Environment variable: QUARKUS_LOG_FILE_ROTATION_MAX_FILE_SIZE

The key word here is "after". But it's subtle so maybe we need to expand on that a little bit?

+1 for little more, I do interpret docs statement differently.