qa: parametrize logger usages #5173

jdrueckert · 2023-11-14T11:53:21Z

PMD Rule Docs: https://docs.pmd-code.org/pmd-doc-6.55.0/pmd_rules_java_bestpractices.html#guardlogstatement

Theoretically fixes rule findings by using substituting parameters (parametrized logs).
Practically, false-positive findings still show up due to PMD bug: pmd/pmd#4703

jdrueckert · 2023-11-14T11:54:03Z

Addresses the remaining findings that were not part of #5170

engine/src/main/java/org/terasology/engine/config/RenderingDebugConfig.java

engine/src/main/java/org/terasology/engine/core/TerasologyEngine.java

skaldarnar · 2023-11-14T13:21:10Z

engine/src/main/java/org/terasology/engine/core/modes/StateLoading.java

@@ -234,7 +234,7 @@ private void popStep() {
        current = null;
        if (!loadProcesses.isEmpty()) {
            current = loadProcesses.remove();
-            logger.debug(current.getMessage());
+            logger.debug("{}", current.getMessage());


This looks weird 🙄 Is this necessary because of some quirk in the rules?

The only this might do is defer the call to toString on whatever type getMessage() returns. If that is already string, we don't gain anything from this...

My understanding was that the parametrization is what avoids the call in case log level is not debug, so with
logger.debug(current.getMessage()) the call to getMessage() is done even if log level is "info"
while with
logger.debug("{}", current.getMessage()) the call to getMessage() is only done if log level is "debug" but not if it's "info"

Is my understanding incorrect?

Admittedly, in this particular case the call might not be particularly impactful.

Is my understanding incorrect?

I think it indeed is. The only thing that is defered is the final call to toString I think.

Maybe this gets clearer if we write this part of the code like this:

// executed regardless of the log-level Message message = current.getMessage(); // message.toString() is only called if DEBUG logs are enabled (happens inside) logger.debug("{}", message);

The parameterization can only help as far as Java itself allows it. Here, we are passing the value of current.getMessage() to the method, that is, we evaluate that part already when calling it.

To make it a truly lazy evaluation we'd need a supplier, either for the whole message or for the inidividual parameters (see #5173 (comment)). I don't think the following code works, but that's how it would look like:

logger.debug(() -> current.getMessage());

Here, we pass a function that, if evaluated, will make the lookup on how to get the message from current.

skaldarnar · 2023-11-14T13:24:09Z

engine/src/main/java/org/terasology/engine/logic/characters/CharacterSystem.java

+                logger.info("Denied activation attempt by {} since the used entity does not exist on the authority",
+                        getPlayerNameFromCharacter(character));


Does our logging framework allow for passing a Supplier<String> for the log message? Here, it would be nice to avoid the computation of getPlayerNameFromCharacter(character) until we actually have to log it. Maybe that's guarded sufficiently, though, and INFO logs are enabled by default currently 🤷

My understanding was that the parametrization does exactly that - avoid the computation until we actually have to log it. But I don't know for sure, so I could be misunderstanding how this works.

it is so @jdrueckert :
https://dennis-xlc.gitbooks.io/the-logback-manual/content/en/chapter-2-architecture/logger-appenders-and-layouts/parameterized-logging.html

@soloturn the parts mentioned in that manual I understood. It doesn't speak to method calls in the parameters, though.
But @skaldarnar's comment above explains it nicely 👍

ha, with you guys one learns something new all the time. there is indeed a fluent API to slf4j-2.0, @skaldarnar , which allows to pass suppliers. we are at slf4j-1.7 at the moment:
https://www.slf4j.org/manual.html#fluent

soloturn · 2023-11-15T04:23:07Z

engine/src/main/java/org/terasology/engine/rendering/dag/RenderTaskListGenerator.java

@@ -183,7 +183,7 @@ public List<RenderPipelineTask> generateFrom(List<Node> orderedNodes) {

    private void logList(List<?> list) {
        for (Object object : list) {
-            logger.debug(object.toString());
+            logger.debug("{}", object.toString());


see above @skaldarnar "weird" comment.

…valuation) (#5174) permit use of slf4j fluent api: https://www.slf4j.org/manual.html#fluent tried to upgrade to logback 1.3.x or logback 1.4.x, but code contains code depending on ch.qos.logback.core.joran.spi.InterpretationContext: engine/src/main/java/org/terasology/logback/RegexFilterAction.java for engine tests though, an upgrade was necessary as the code uses logback-classic directly.

engine/src/main/java/org/terasology/engine/rendering/dag/RenderTaskListGenerator.java

engine/src/main/java/org/terasology/engine/rendering/nui/editor/layers/NUIEditorScreen.java

engine/src/main/java/org/terasology/engine/rendering/nui/editor/layers/NUISkinEditorScreen.java

Co-authored-by: Tobias Nett <[email protected]>

skaldarnar · 2023-11-19T20:41:50Z

build-logic/src/main/kotlin/terasology-metrics.gradle.kts

        because("runtime: to configure logging during tests with logback.xml")
    }
    testRuntimeOnly("org.codehaus.janino:janino:3.1.7") {
        because("allows use of EvaluatorFilter in logback.xml")
    }
-    testRuntimeOnly("org.slf4j:jul-to-slf4j:1.7.36") {
+    testRuntimeOnly("org.slf4j:jul-to-slf4j:2.0.9") {


Does that major version upgrade just work?

looked like it, yes

This reverts commit c56c4dd.

This reverts commit 4f42a8f.

* Revert "revert: "qa: parametrize logger usages (#5173)" (#5180)" This reverts commit 4f42a8f. * revert upgrade slf4j-2.0 * micrometer 1.9.8 --> 1.9.12 * qa, still use old slf4j, feedback jdrueckert. gradle does not care about the logger definition in engine-tests, it uses the one from engine also for the tests. remove it to not confuse. --------- Co-authored-by: soloturn <[email protected]>

This reverts commit 4f42a8f.

qa: parametrize logger usages

f70b5d7

jdrueckert added Type: Improvement Request for or addition/enhancement of a feature Topic: Stabilization Requests, Issues and Changes related to improving stablity and reducing flakyness Category: Test/QA Requests, Issues and Changes targeting tests and quality assurance labels Nov 14, 2023

jdrueckert added this to the 2023 Revive - Milestone 2 milestone Nov 14, 2023

jdrueckert self-assigned this Nov 14, 2023

skaldarnar previously approved these changes Nov 14, 2023

View reviewed changes

soloturn reviewed Nov 15, 2023

View reviewed changes

jdrueckert mentioned this pull request Nov 17, 2023

upgrade slf4j-2.0, permit passing suppliers to loggers, and thus lazy… #5174

Merged

jdrueckert dismissed skaldarnar’s stale review via 39da317 November 17, 2023 13:21

jdrueckert commented Nov 17, 2023

View reviewed changes

jdrueckert and others added 12 commits November 17, 2023 14:27

chore: remove superfluous toString() calls

9076613

Co-authored-by: Tobias Nett <[email protected]>

chore: remove superfluous toString calls

f6f1ad5

chore: reuse existing local variables in log

d1e3677

refactor: introduce new local variable to use in logic and logs

2d02c21

refactor: parametrize log

75c9521

chore: fix minor typos in comment

9202869

chore: log full exception instead of only exception message

e2fa44e

Merge branch 'develop' into qa/logger

e76f9d5

Merge branch 'develop' into qa/logger

28b87ac

ci: retrigger

26cd0ea

fix: variable scope

f9b8e44

Merge branch 'develop' into qa/logger

b168c19

skaldarnar approved these changes Nov 19, 2023

View reviewed changes

jdrueckert merged commit c56c4dd into develop Nov 19, 2023
8 checks passed

jdrueckert deleted the qa/logger branch November 19, 2023 20:48

jdrueckert added a commit that referenced this pull request Nov 19, 2023

Revert "qa: parametrize logger usages (#5173)"

73d8848

This reverts commit c56c4dd.

jdrueckert mentioned this pull request Nov 19, 2023

revert: "qa: parametrize logger usages" #5180

Merged

jdrueckert added a commit that referenced this pull request Nov 19, 2023

revert: "qa: parametrize logger usages (#5173)" (#5180)

4f42a8f

This reverts commit c56c4dd.

jdrueckert restored the qa/logger branch November 19, 2023 21:16

jdrueckert added a commit that referenced this pull request Nov 19, 2023

Revert "revert: "qa: parametrize logger usages (#5173)" (#5180)"

6c5faa2

This reverts commit 4f42a8f.

jdrueckert mentioned this pull request Nov 19, 2023

qa: parametrize logger usages #5181

Merged

soloturn pushed a commit that referenced this pull request Nov 25, 2023

Revert "revert: "qa: parametrize logger usages (#5173)" (#5180)"

a98755b

This reverts commit 4f42a8f.

soloturn pushed a commit that referenced this pull request Dec 3, 2023

Revert "revert: "qa: parametrize logger usages (#5173)" (#5180)"

437006c

This reverts commit 4f42a8f.

jdrueckert deleted the qa/logger branch December 5, 2023 16:45

soloturn pushed a commit that referenced this pull request Dec 9, 2023

Revert "revert: "qa: parametrize logger usages (#5173)" (#5180)"

ef1a0fe

This reverts commit 4f42a8f.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

qa: parametrize logger usages #5173

qa: parametrize logger usages #5173

jdrueckert commented Nov 14, 2023

jdrueckert commented Nov 14, 2023

skaldarnar Nov 14, 2023

jdrueckert Nov 14, 2023

skaldarnar Nov 14, 2023

skaldarnar Nov 14, 2023

jdrueckert Nov 14, 2023

soloturn Nov 14, 2023

jdrueckert Nov 14, 2023

soloturn Nov 15, 2023 •

edited

Loading

soloturn Nov 15, 2023

skaldarnar Nov 19, 2023

jdrueckert Nov 19, 2023

		logger.info("Denied activation attempt by {} since the used entity does not exist on the authority",
		getPlayerNameFromCharacter(character));

qa: parametrize logger usages #5173

qa: parametrize logger usages #5173

Conversation

jdrueckert commented Nov 14, 2023

jdrueckert commented Nov 14, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

soloturn Nov 15, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

soloturn Nov 15, 2023 •

edited

Loading