Logger refactoring

[hannaeko]

Purpose

This PR aims to provide an interface to manually set the module and test case name in the Logger.

This is to avoid unnecessary calls to callers and decouple the module / test case name from the file name / method name.

This PR also addresses the letter case of test cases and module to fit the updated specification.

Context

zonemaster/zonemaster#1200

Changes

• In test modules, the local method _emit_log is used instead of info
• A somewhat global variable $Zonemaster::Engine::Logger::TEST_CASE_NAME is used to set the test case name
• Test case and module name have now the letter case defined in change letter case for test case identifier zonemaster#1200 (including Syestem and Unspecified).
• Avoid building the caller trace and iterating through it for each log entry this may marginally improve performance.

How to test this PR

Run a test using the CLI,

zonemaster-cli --level info --show-module --show-testcase afnic.fr

check that

• the module and test case are no longer full uppercase
• the log messages are correctly displayed and translated

[hannaeko]

Some tests are failing due to circular dependency, I need to rethink some stuff around the logger. Changing this PR to draft for the time being.

[hannaeko]

The circular dependency has been fixed, I still need to fix the unit tests but this should not impact anything else than the unit tests themselves.

[tgreenx]

Tested and it works as advertised. Note that even with this PR profile options (such as test_levels or logfilter) are still expected to use capitalized Test module names.

I have one suggestion: since module names in share/modules.txt are already in the format suggested by zonemaster/zonemaster#1200, for simplicity purposes we could already remove the forced upper-case module names in Engine where applicable. See the proposed change below to Zonemaster::Engine::Translator:

$ git log -1 --oneline
b96d62ea (HEAD -> test-PR1302) fix log filter

$ git diff
diff --git a/lib/Zonemaster/Engine/Translator.pm b/lib/Zonemaster/Engine/Translator.pm
index 42fef57f..23bdc726 100644
--- a/lib/Zonemaster/Engine/Translator.pm
+++ b/lib/Zonemaster/Engine/Translator.pm
@@ -174,10 +174,10 @@ sub _load_data {
 sub _build_all_tag_descriptions {
     my %all_tag_descriptions;

-    $all_tag_descriptions{SYSTEM} = \%TAG_DESCRIPTIONS;
+    $all_tag_descriptions{System} = \%TAG_DESCRIPTIONS;
     foreach my $mod ( 'Basic', Zonemaster::Engine->modules ) {
         my $module = 'Zonemaster::Engine::Test::' . $mod;
-        $all_tag_descriptions{ uc( $mod ) } = $module->tag_descriptions;
+        $all_tag_descriptions{ $mod } = $module->tag_descriptions;
     }

     return \%all_tag_descriptions;
@@ -231,7 +231,7 @@ sub to_string {
 sub translate_tag {
     my ( $self, $entry ) = @_;

-    return $self->_translate_tag( uc $entry->module, $entry->tag, $entry->printable_args ) // $entry->string;
+    return $self->_translate_tag( $entry->module, $entry->tag, $entry->printable_args ) // $entry->string;
 }

[marc-vanderwal]

So far, so good. I wanted to see if there was any improvement in performance but it seems that the time to test a zone has too high of a variance to allow me to arrive at a conclusive result.

[marc-vanderwal]

However, when I run the unit tests for the test modules (i.e. prove -rl t/Test-*.t), I notice they run much faster. On the current develop branch, I timed it at 4:13 minutes, and with your branch checked out, it drops to about 2:43 minutes. Nice!

[hannaeko]

However, when I run the unit tests for the test modules (i.e. prove -rl t/Test-*.t), I notice they run much faster. On the current develop branch, I timed it at 4:13 minutes, and with your branch checked out, it drops to about 2:43 minutes. Nice!

Thanks for the measurements that's really good to know!
EDIT : Although I wonder how much was because of the crashing tests ^^

[hannaeko]

Please re-review, the tests are now passing.

[hannaeko]

However, when I run the unit tests for the test modules (i.e. prove -rl t/Test-*.t), I notice they run much faster. On the current develop branch, I timed it at 4:13 minutes, and with your branch checked out, it drops to about 2:43 minutes. Nice!

I redid some measurements now that the tests are passing, the gain is only marginal.
Before : Files=79, Tests=1711, 92 wallclock secs ( 0.57 usr 0.20 sys + 87.43 cusr 4.56 csys = 92.76 CPU)
After: Files=79, Tests=1711, 86 wallclock secs ( 0.54 usr 0.21 sys + 80.24 cusr 4.53 csys = 85.52 CPU)

[matsduf]

Purpose

Provide interface to manually set the module and test case name.

Is this a correct description of this PR?

[mattias-p]

Super nice to get rid of the call stack walking! I added comments for a few minor things but all in all I like it a lot.

[matsduf]

Please provide a better text under "Purpose" so that you easily can see what this PR is about.

[hannaeko]

Please provide a better text under "Purpose" so that you easily can see what this PR is about.

I tried to improve it.

@mattias-p please can you re-review?

[matsduf]

Please provide a better text under "Purpose" so that you easily can see what this PR is about.

I tried to improve it.

Is the new presentation of the module and test case names in mostly lower case part of the purpose? Or is that just a side effect?

[hannaeko]

Is the new presentation of the module and test case names in mostly lower case part of the purpose? Or is that just a side effect?

It was the main motivation but has become a side effect, I updated the description to mention it in the purpose section.

[mattias-p]

I really like this.

[ghost]

v2023.2 release testing

Tested based on the "How to test" section and woks as expected.