test: reducing logspam

[keturn]

I've never been happy with the setupLogging method I added to MTE. Now that it's a year later and we no longer have the engine-tests/MTE split to worry about, I might understand things well enough to do better.

Contains

• A logback configuration file to be used by default during module tests. Run groovyw module refresh to add this logback-test.xml to your workspace.

• A new syntax to exclude log messages using a regular expression.

[ example filter configuration, before and after ]

Before, using logback-classic matchers as documented:

    <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
      <evaluator>
        <matcher>
          <Name>reflectionsEmpty</Name>
          <regex>given scan urls are empty</regex>
        </matcher>
        <expression>reflectionsEmpty.matches(message)</expression>
      </evaluator>
      <OnMismatch>NEUTRAL</OnMismatch>
      <OnMatch>DENY</OnMatch>
    </filter>

After:

Terasology/engine/src/main/resources/org/terasology/engine/logback/filter-reflections.xml

Line 8 in de1c104

<denyRegex prefix="org.reflections" message="given scan urls are empty" />

• Refactorings to reduce the duplication of the fiddly bits of log configuration between engine tests, module tests, and production (the PC facade).

Implementation Goals:

• All test tasks should be able to filter logs with logback.
• Test frameworks like JUnit should be test* dependencies.
  • except code in engine-tests/src/main that builds on JUnit APIs for use by external module tests, then:
    • api if classes/interfaces from it show up on public method signatures.
    • otherwise implementation if it's needed to compile but not publicly visible.
• Only the edges (facade, test runners) should define a logging backend (logback).
  • except the code that uses specific logback classes. Which is multiple things in engine, and logback 1.2 isn't structured in a way that facilitates making complete logback extensions from logback-core alone; you often have to pull in logback-classic to do anything useful. This largely breaks the "let the edges pick their own logging backend" architecture I wanted, but the least we can do is not conflict with any logback.xml a downstream consumer wants to set up.

How to test

Run some engine tests, run some module tests, see if you can figure out how to include or exclude the log messages you want during your test output.

Outstanding before merging

• security: upgrade dependencies #5021. I moved dependencies around enough that git will find conflicts.
• log filter for module tests
• document how module maintainers can configure the filter: https://github.com/MovingBlocks/Terasology/wiki/Testing-Modules
• add archive of full test report to the jenkins build, in case you want to get the non-Jenkins-truncated output

Include with Merge

• feat: use default logback-test.xml if a module does not provide one ModuleJteConfig#25

[keturn]

In this branch's current state, things work fine for engine-tests. If you look at the console output for the integrationTest step, there's only the warnings from Java itself: https://jenkins.terasology.io/teraorg/job/Terasology/job/engine/view/change-requests/job/PR-5022/2/pipeline-console/

and when you look at the output for a specific test, you see it has some: https://jenkins.terasology.io/teraorg/job/Terasology/job/engine/view/change-requests/job/PR-5022/2/testReport/org.terasology.engine.integrationenvironment/MTEExtensionTestWithPerClassLifecycle/Integration_Tests___firstTestFindsThings__/

(The ...[truncated 19025 chars]... there is Jenkins, not the test execution. Its threshold for output on passing tests is very small. It keeps a bit more for failed tests.)

The thing I haven't checked yet, and I expect is not filtered, is the output of module tests.

[keturn]

Things to know about junit and logging: JUnit uses java.util.logging. We consolidate that with our own slf4j-based logging using jul-to-slf4j.