Skip to content

Commit

Permalink
Fix InternalEngineTests.testMergeThreadLogging (elastic#102640) (elas…
Browse files Browse the repository at this point in the history
…tic#102649)

The test has to wait for all merge thread log messages (include Lucene ones) 
to be seen before reset the log level and stop the appender.

Previous attempt wasn't enough: the test failure in elastic#90071 (comment) shows 
that Lucene's merge scheduler thread can log after the Elasticsearch one, and 
if the appender has been closed in the meanwhile it can fail the test.

This change ensure that the appender saw the Merge Scheduler end message 
before resetting the log level and close the engine.

Closes elastic#90071
  • Loading branch information
tlrx authored Nov 27, 2023
1 parent fcb4fd2 commit 7f23419
Showing 1 changed file with 34 additions and 19 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -2576,28 +2576,40 @@ public void testIndexWriterInfoStream() throws IllegalAccessException, IOExcepti
}
}

private static class MockMTAppender extends AbstractAppender {
private static class MockMergeThreadAppender extends AbstractAppender {

private final List<String> messages = Collections.synchronizedList(new ArrayList<>());
private final AtomicBoolean luceneMergeSchedulerEnded = new AtomicBoolean();

List<String> messages() {
return List.copyOf(messages);
}

MockMTAppender(final String name) throws IllegalAccessException {
public boolean mergeCompleted() {
return luceneMergeSchedulerEnded.get();
}

MockMergeThreadAppender(final String name) throws IllegalAccessException {
super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null, false, Property.EMPTY_ARRAY);
}

@Override
public void append(LogEvent event) {
final String formattedMessage = event.getMessage().getFormattedMessage();
if (event.getLevel() == Level.TRACE && formattedMessage.startsWith("merge thread")) {
messages.add(formattedMessage);
if (event.getLevel() == Level.TRACE && event.getMarker().getName().contains("[index][0]")) {
if (formattedMessage.startsWith("merge thread")) {
messages.add(formattedMessage);
} else if (event.getLoggerName().endsWith(".MS")
&& formattedMessage.contains("MS: merge thread")
&& formattedMessage.endsWith("end")) {
luceneMergeSchedulerEnded.set(true);
}
}
}
}

public void testMergeThreadLogging() throws Exception {
final MockMTAppender mockAppender = new MockMTAppender("testMergeThreadLogging");
final MockMergeThreadAppender mockAppender = new MockMergeThreadAppender("testMergeThreadLogging");
mockAppender.start();

Logger rootLogger = LogManager.getRootLogger();
Expand All @@ -2616,26 +2628,29 @@ public void testMergeThreadLogging() throws Exception {
engine.index(indexForDoc(testParsedDocument("3", null, testDocument(), B_1, null)));
engine.index(indexForDoc(testParsedDocument("4", null, testDocument(), B_1, null)));
engine.forceMerge(true, 1, false, UUIDs.randomBase64UUID());
engine.flushAndClose();

assertBusy(() -> {
assertThat(engine.getMergeStats().getTotal(), greaterThan(0L));
assertThat(engine.getMergeStats().getCurrent(), equalTo(0L));
});
}

assertBusy(() -> {
List<String> threadMsgs = mockAppender.messages().stream().filter(line -> line.startsWith("merge thread")).toList();
assertThat("messages:" + threadMsgs, threadMsgs.size(), greaterThanOrEqualTo(3));
assertThat(
threadMsgs,
containsInRelativeOrder(
matchesRegex("^merge thread .* start$"),
matchesRegex("^merge thread .* merge segment.*$"),
matchesRegex("^merge thread .* end$")
)
);
});
assertBusy(() -> {
List<String> threadMsgs = mockAppender.messages().stream().filter(line -> line.startsWith("merge thread")).toList();
assertThat("messages:" + threadMsgs, threadMsgs.size(), greaterThanOrEqualTo(3));
assertThat(
threadMsgs,
containsInRelativeOrder(
matchesRegex("^merge thread .* start$"),
matchesRegex("^merge thread .* merge segment.*$"),
matchesRegex("^merge thread .* end$")
)
);
assertThat(mockAppender.mergeCompleted(), is(true));
});

Loggers.setLevel(rootLogger, savedLevel);
engine.close();
}
} finally {
Loggers.setLevel(rootLogger, savedLevel);
Loggers.removeAppender(rootLogger, mockAppender);
Expand Down

0 comments on commit 7f23419

Please sign in to comment.