Ensure order of logged messages, fix a few flaky tests #25365
Conversation
| @@ -133,6 +136,7 @@ public void startReconfiguration() throws Exception { | |||
| () -> assertEquals(GlassFishLoggingStatus.CONFIGURING, MANAGER.getLoggingStatus()), | |||
| () -> assertNull(COLLECTOR.pop(), "COLLECTOR should be empty after reconfiguration started")); | |||
| doLog(Level.INFO, "Log after reconfiguration started", 0); | |||
| Thread.sleep(10L); | |||
There was a problem hiding this comment.
In all these tests should not be any sleeps, they make these tests ineffective. Also the line before has 0 sleep time, while the thread started before the sleep (but still could be executed before or after it).
I have to think what kind of error I intended to catch by this.
There was a problem hiding this comment.
I added this sleep to ensure that the logging actually happens before the assertion on the next line. Otherwise the assertion doesn't have any value - it could be asserted before the log happens and then the test passes.
Should I remove the sleep here?
There was a problem hiding this comment.
Could doLog return something that the code here could check if it's safe to proceed?
There was a problem hiding this comment.
I have no idea. Now it looks to me that @dmatej intended to do the check immediately. It’s supposed to test locking, so maybe all should run as soon as possible. Although it would be good to clarify what the tests intends to verify.
There was a problem hiding this comment.
Obviously I did something wrong, I just need to remember, document it somehow and fix it.
But I think I know how to resolve it better ... the point is that you cannot write into a file while it is renamed. The idea I implemented in #24980 was that if I have just a single log message, I can log it asynchronously. The problem is that there can be more threads which want to log something and we are a bit out of the control with threads here.
Creating static executor with any thread waiting whole day or month is ugly, but maybe it can be "transactional". When rolling starts create the thread, send logs to its buffer and destroy it when the operation finished (after it consumes the queue). Then you even don't need the executor.
However, the original idea was that log handler will accept log records, it just will not process them while the file manager does roll. So even the idea with threads was bad workaround. Or I missed yet something.... mhm ... (eh, there is yet another situation - startup, which is another stateful machine ... that is related to #25183 , because logging system can be used even also by the garbage collector which ten can break everything, as it is initialized too early).
There was a problem hiding this comment.
Do you mean the executor I created here in rhe LogFileManager? It creates a thread only when it’s needed and disposes it after 100ms if it’s inactive. The only thing that is kept all the time is the executor itself, with no threads most of the time.
A better approach would be as you suggest - it would be enough to create a single threaded executor in the scope of roll method and use it for all async logging and then shut it down at the end of the roll method.
This comment was marked as resolved.
This comment was marked as resolved.
OndroMih
force-pushed
the
ondromih-flaky-tests
branch
from
a162bb8 to
d0a0c4c
Compare
This comment was marked as resolved.
This comment was marked as resolved.
dmatej
changed the title
| @@ -164,10 +168,11 @@ public void roll() throws Exception { | |||
| ); | |||
| handler.publish(new GlassFishLogRecord(Level.SEVERE, "File two, line two", false)); | |||
| Thread.sleep(MILLIS_FOR_PUMP); | |||
| final List<String> fileLines3 = Files.readAllLines(logFile.toPath()); | |||
There was a problem hiding this comment.
If the file doesn't exist, this will cause IOException, so the assertion will not make sense.
| () -> assertTrue(handler.getConfiguration().getLogFile().exists(), "file exists"), | ||
| () -> assertThat("file content", Files.readAllLines(handler.getConfiguration().getLogFile().toPath()), | ||
| () -> assertTrue(logFile.exists(), "file exists"), | ||
| () -> assertThat("file content, filename=" + logFile + ", content=" + fileLines2 , fileLines2, |
There was a problem hiding this comment.
Putting whole content to "reason" argument is bit too much ... the assertion would provide quite good explanation, ie:
java.lang.AssertionError: file content
Expected: iterable containing [a string containing "INFO", "Rolling the file ", ".log", "output was originally enabled: true" in order, a string containing "INFO", "Araaachiving file ", ".log", " to ", ".log_" in order, a string containing "SEVERE", "main", "File two, line two" in order]
but: item 1: was "21:56:32.278209 INFO er-Async-Info-Logger . Archiving file /tmp/org.glassfish.main.jul.handler.GlassFishLogHandlerTest11276075090100096775.log to /tmp/org.glassfish.main.jul.handler.GlassFishLogHandlerTest11276075090100096775.log_2025-02-05T21-56-32"
but maybe adding the file to the message is a good idea, perhaps directly to assertAll.
Fixes #25349
Fixes an issue that caused the
GlassFishLogHandlerTest.rolltest to fail sometimes - the messages produced when rolling log files could be logged in reversed order.Fixes flaky
GlassFishLogManagerLifeCycleTest.reconfigureWithoutResolvingLevelsWithincompleteconfigurationtest, which produced log messages in undeterministic order but expected them in order. The fix is similar, but this time in the test, not in production code.