#2896: Made the test more concrete

[levBagryansky]

Closes #2896
Now Logs get all messages, from other tests too. Thus, here we changed the test so now it filter messages by temp path too,

---

PR-Codex overview

This PR improves thread safety by making @CaptureLogs annotation specific to each test.

Detailed summary

• Made @CaptureLogs thread-safe to contain only test-related logs
• Added org.hamcrest imports for assertions
• Refactored error message handling in VerifyMojoTest

✨ Ask PR-Codex anything about this PR by commenting with /codex {your question}

[levBagryansky]

Pattern :
'.*Errors identified:\s{3}(/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/junit9699743741109071872/foo/x/main.eo, \d+: .*[\s]*)+\]'
Actual String to be matched:
"Optional[14:24:30 [ERROR] com.jcabi.xml.XSLDocument: net.sf.saxon.style.XSLMessage@21baa2ef: Errors identified:\n /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/junit6068276082387471053/foo/x/main.eo, 2: The alias is invalid: \"THIS-IS-WRONG org.eolang.io.stdout\";\n /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/junit6068276082387471053/foo/x/main.eo, 2: The alias \"org.eolang.io.stdout\" is not used;\n]"

Difference is in temp directory, in pattern and actual:
junit9699743741109071872, pattern
junit6068276082387471053 actual
Maybe capturing of logs is not thread safe?
@volodya-lombrozo WDYT?

[volodya-lombrozo]

@levBagryansky Apparently, It has a concurrency issue. I guess the key problem is in this peace of code, CaptureLogs.java:

/**
 * Initialize the appender.
 * Adds appender to the root logger.
 */
void init() {
    final Logger logger = LogManager.getRootLogger();
    final Enumeration<?> appenders = logger.getAllAppenders();
    if (appenders.hasMoreElements()) {
        final Object next = appenders.nextElement();
        if (next instanceof ConsoleAppender) {
            this.setLayout(((Appender) next).getLayout());
        }
    }
    logger.addAppender(this);
    this.logs.waitForInit();
}

As you can see, we have final Logger logger = LogManager.getRootLogger(); which is a shared state among all of the tests. To fix this we need to dig deeper. So, you can try to fix it, it might be interesting.

[volodya-lombrozo]

@levBagryansky Also note, that logging is actually an asynchronous process. So you might need to "wait" when the desired log will be captured.

[levBagryansky]

@volodya-lombrozo maybe we can use unique Loggers for these tests?

[volodya-lombrozo]

@levBagryansky In this case you might not see the results in your console. The idea is to append "unique" logger appender over the default console logger.

[levBagryansky]

@volodya-lombrozo We should make it the way that CaptureLogs gets only messages from it's test. Somehow.

[levBagryansky]

@volodya-lombrozo I have an Idea to do it this way

        @Override
        public void append(final LoggingEvent event) {
            if (event.getThreadName().equals(
                Thread.currentThread().getName()
            )) {
                this.logs.append(this.getLayout().format(event));
            }
        }

But a test can use different threads inside.

[volodya-lombrozo]

@volodya-lombrozo We should make it the way that CaptureLogs gets only messages from it's test. Somehow.

@levBagryansky Yes, it would be great.

As for:

But a test can use different threads inside.

I'm afraid it might be too dangerous and error-prone to count on thread names here. I guess we need to understand what we can do on the slf4j level instead.

[levBagryansky]

@volodya-lombrozo I don't see any option how to distinguish messages from different tests. They can be from different threads and we cannot "tag" them somehow.
I suggest to change the method private String waitForMessage(final String message, final Runnable action) to the private String waitForMessage(final Runnable action, final String ... messages) and to provide temp paths in tests. Only messages with temp paths are formed in the test.
final String message = this.getMessage(out, "Errors identified", temp.toString());
Looks like it it is enough in our cases.

[volodya-lombrozo]

@levBagryansky Actually it's a good idea, as for me! I mean this "tagging". However, maybe we can use something different, instead of creating temporary folders (I guess it might be rather slow to constantly touch a filesystem)? Maybe we can use
ExtensionContext in beforeEach and afterEach methods? This object has context.getUniqueId() method which we can use as a tag producer. What do you think?

[levBagryansky]

@volodya-lombrozo Idea with temps is based on the fact that messages with "Errors identified" have usually content like
"Optional[14:24:30 [ERROR] com.jcabi.xml.XSLDocument: net.sf.saxon.style.XSLMessage@21baa2ef: Errors identified:\n /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/junit6068276082387471053/foo/x/main.eo, 2: The alias is invalid: \"THIS-IS-WRONG org.eolang.io.stdout\";\n /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/junit6068276082387471053/foo/x/main.eo, 2: The alias \"org.eolang.io.stdout\" is not used;\n]"
So in such case we can filter messages via path

[volodya-lombrozo]

@levBagryansky I see. To be honest, I don't like this solution because:

1. We might loose some logs that don't have a file path in their log message
2. We should specify @TempDir for all the tests where we are interested in logs (which is strange, since we already mentioned @CaptureLogs)
3. Tests will create redundant folders all the time, which might lead to slow build time.

Hence, if we don't have any other option, we might try to implement it as you suggested, but I would suggest to dig a bit dipper and solve the original concurrency problem with log appenders.

[levBagryansky]

@volodya-lombrozo pls review

[volodya-lombrozo]

@levBagryansky Looks good to me. Thank you for your contribution!

[levBagryansky]

@yegor256 Please take a look

[levBagryansky]

@yegor256 please check

[levBagryansky]

@yegor256 please check

[levBagryansky]

@yegor256 please check. I filter the logs by temp path in order to avoid getting messages from other tests.

[levBagryansky]

@yegor256 please check

[levBagryansky]

@yegor256 please merge

[levBagryansky]

@yegor256 please merge

[levBagryansky]

@yegor256 please check

[yegor256]

@rultor merge

[rultor]

@rultor merge

@yegor256 OK, I'll try to merge now. You can check the progress of the merge here

[rultor]

@rultor merge

@yegor256 Done! FYI, the full log is here (took me 22min)