Flaky GlassFishLogManagerLifeCycleTest.reconfigureWithoutResolvingLevelsWithincompleteconfiguration

[pzygielo]

glassfish/nucleus/glassfish-jul-extension/src/test/java/org/glassfish/main/jul/GlassFishLogManagerLifeCycleTest.java

Lines 194 to 221 in a56d44c

	/**
	* Yet another case, here we get into blocked state, and then we DISABLE resolving if the record
	* is loggable or not when we simply don't know. All records then go to the StartupQueue, which
	* means also some memory requirements.
	*/
	@Test
	@Order(100)
	@Timeout(5)
	public void reconfigureWithoutResolvingLevelsWithincompleteconfiguration() throws Exception {
	reconfigureToBlockingHandler();
	setResolveLevelWithIncompleteConfiguration(false);
	assertEquals(GlassFishLoggingStatus.CONFIGURING, MANAGER.getLoggingStatus(), "after reconfigureToBlockingHandler");
	doLog(Level.FINEST, "message0", 1);
	doLog(Level.INFO, "message1", 2);
	MANAGER.reconfigure(originalCfg, () -> LOG.setLevel(Level.FINEST), null);
	assertFalse(isResolveLevelWithIncompleteConfiguration(), "isResolveLevelWithIncompleteConfiguration");
	final List<GlassFishLogRecord> logRecords = COLLECTOR.getAll();
	assertAll("Both records must pass via startup queue",
	() -> assertEquals(GlassFishLoggingStatus.FULL_SERVICE, MANAGER.getLoggingStatus(),
	"status after all reconfiguration and flushing finished"),
	() -> assertThat(logRecords, hasSize(2)),
	() -> assertThat("record 0", logRecords.get(0).getLevel(), equalTo(Level.FINEST)),
	() -> assertThat("record 0", logRecords.get(0).getMessage(), equalTo("message0")),
	() -> assertThat("record 1", logRecords.get(1).getLevel(), equalTo(Level.INFO)),
	() -> assertThat("record 1", logRecords.get(1).getMessage(), equalTo("message1")));
	}

Have seen recently:

2025-01-26T08:21:39.9703043Z Both records must pass via startup queue (4 failures)
2025-01-26T08:21:39.9704392Z >--java.lang.AssertionError: record 0
2025-01-26T08:21:39.9704815Z Expected: <FINEST>
2025-01-26T08:21:39.9705101Z      but: was <INFO>
2025-01-26T08:21:39.9705451Z >--java.lang.AssertionError: record 0
2025-01-26T08:21:39.9705854Z Expected: "message0"
2025-01-26T08:21:39.9706155Z      but: was "message1"
2025-01-26T08:21:39.9706532Z >--java.lang.AssertionError: record 1
2025-01-26T08:21:39.9706915Z Expected: <INFO>
2025-01-26T08:21:39.9707189Z      but: was <FINEST>
2025-01-26T08:21:39.9707521Z >--java.lang.AssertionError: record 1
2025-01-26T08:21:39.9707903Z Expected: "message1"
2025-01-26T08:21:39.9708195Z      but: was "message0"

Timing issue?

Looks like records are collected in order different than expected by assertions.
From the message Both records must pass via startup queue I'd not suspect the order to be crucial. I believe that implementation is rather fine here and it's test that should follow.

Originally posted by @pzygielo in #24046 (comment)