test: add coverage for individual logger levels overriding global set…

[kaya-david]

• add new test to validate that per-logger log levels correctly override the global log level in LoggerConfig

[kaya-david]

Many thanks for the proposed changes!

It took me a moment to realize that LoggerConfig actually modifies its loggers attribute during post-init, which makes this test useful (otherwise we would only test set-and-get).

However the mileage under test is still rather short. We basically check wether set, post-process, get produces the right results. What would interest me is if the config is actually properly applied to the logging framework. One way would be to call setup_logging and catch what is being passed to dictConfig. Or we let dictConfig run through in a temporary environment and then check if the changes were properly applied there (not sure if this is feasible though). Additionally, at least a few acceptance tests would be great which ensure that setup_logging is actually applied when logprep is run and that the logs are actually produced in the way we think they do. I think we already have a basic structure for this kind of testcase, meaning it would be relatively straight-foward. What do you think?

In any case, please add another testcase which only sets an explicit individual log level for a subset of components. This way we can see that individual log levels successfully override the global one while also the global one is properly applied to the others.

My bad - I initially misunderstood LoggerConfig. The {"level": ... argument only affects the root logger’s level ("root": {"level": ...}) and does not propagate to the other loggers.

{
   "level": "INFO:,
   "loggers": {
       "root": ...
   }
}

In relation to DEFAULT_LOG_CONFIG in utils/defaults.py, there’s no single global level applied across all components. Each logger keeps its own expected default unless explicitly overridden. The other tests already cover this behavior - verifying that setting level only updates the root logger while other loggers retain their defaults.

I’ve updated the test to reflect the defaults, which should be sufficient at the unit-test level.

The next step would be to add acceptance tests on a more integration-like level to verify that logs actually end up in the configured channels.

[mhoff]

Thank you for the added test which checks how our own class interacts with the logging framework. That definitely makes sense and is an improvement.

Regarding the discussion we had this morning: I am wondering if we have some test (probably rather an acceptance test) which ensures that running logprep actually also runs setup_logging() at all / at the right time. Imagine we accidentally don't call setup_logging in run_logprep.py, what would happen? I actually tried it out just now and the result is that all acceptance tests pass except for two:

FAILED tests/acceptance/test_error_output.py::test_error_output_flushes_if_timeout_is_reached - TimeoutError: STREAM ioctl timeout
FAILED tests/acceptance/test_wineventlog_pseudonymization.py::test_events_pseudonymized_correctly - IndexError: list index out of range

We are lucky as there are at least some tests which fail. But that is quite circumstantial and if we wrote those tests in a different way, I suppose everything might work just fine (like the other acceptance tests). So I still think it would be a great idea to test that the logger configuration we supply in the pipeline.yml is actually applied during running logprep.

One could use a test like this:

def test_two_times_config_refresh_after_5_seconds(tmp_path, config):
    config_path = tmp_path / "generated_config.yml"
    config_path.write_text(config.as_json())
    config = Configuration.from_sources([str(config_path)])
    with run_logprep(config_path) as proc:
        wait_for_output(proc, "Config refresh interval is set to: 5 seconds", test_timeout=5)
        config.version = "2"
        config_path.write_text(config.as_json())
        wait_for_output(proc, "Successfully reloaded configuration", test_timeout=12)
        config.version = "other version"
        config_path.write_text(config.as_json())
        wait_for_output(proc, "Successfully reloaded configuration", test_timeout=20) 

and check two outputs:

• "Configuration loaded" in run_logprep.py
• "Startup complete" in runner.py

By overriding the logger levels we can always make one log disappear while we still see the other (in both combinations). So even if the default config would already produce one of both scenarios, the other would require an overwritten logger config to work.

I hope this makes sense

[kaya-david]

Thank you for the added test which checks how our own class interacts with the logging framework. That definitely makes sense and is an improvement.

Regarding the discussion we had this morning: I am wondering if we have some test (probably rather an acceptance test) which ensures that running logprep actually also runs setup_logging() at all / at the right time. Imagine we accidentally don't call setup_logging in run_logprep.py, what would happen? I actually tried it out just now and the result is that all acceptance tests pass except for two:

FAILED tests/acceptance/test_error_output.py::test_error_output_flushes_if_timeout_is_reached - TimeoutError: STREAM ioctl timeout
FAILED tests/acceptance/test_wineventlog_pseudonymization.py::test_events_pseudonymized_correctly - IndexError: list index out of range

We are lucky as there are at least some tests which fail. But that is quite circumstantial and if we wrote those tests in a different way, I suppose everything might work just fine (like the other acceptance tests). So I still think it would be a great idea to test that the logger configuration we supply in the pipeline.yml is actually applied during running logprep.

One could use a test like this:

def test_two_times_config_refresh_after_5_seconds(tmp_path, config):
    config_path = tmp_path / "generated_config.yml"
    config_path.write_text(config.as_json())
    config = Configuration.from_sources([str(config_path)])
    with run_logprep(config_path) as proc:
        wait_for_output(proc, "Config refresh interval is set to: 5 seconds", test_timeout=5)
        config.version = "2"
        config_path.write_text(config.as_json())
        wait_for_output(proc, "Successfully reloaded configuration", test_timeout=12)
        config.version = "other version"
        config_path.write_text(config.as_json())
        wait_for_output(proc, "Successfully reloaded configuration", test_timeout=20) 

and check two outputs:

* ["Configuration loaded" in run_logprep.py](https://github.com/fkie-cad/Logprep/blob/main/logprep/run_logprep.py#L90)

* ["Startup complete" in runner.py](https://github.com/fkie-cad/Logprep/blob/main/logprep/runner.py#L100)

By overriding the logger levels we can always make one log disappear while we still see the other (in both combinations). So even if the default config would already produce one of both scenarios, the other would require an overwritten logger config to work.

I hope this makes sense

I see your point, and I get the line of thought. Personally, I would have taken the idea a bit further: we could make LoggerConfig emit explicit log messages indicating which loggers were configured and with which levels. That would allow us to write targeted acceptance tests that validate exactly this behavior.

In other words: “Was the logger actually set to the level I specified in the config?” If we make that part observable through dedicated log output, we can test it reliably without depending on side effects or indirect behavior elsewhere in the system.

[mhoff]

I see your point, and I get the line of thought. Personally, I would have taken the idea a bit further: we could make LoggerConfig emit explicit log messages indicating which loggers were configured and with which levels. That would allow us to write targeted acceptance tests that validate exactly this behavior.

In other words: “Was the logger actually set to the level I specified in the config?” If we make that part observable through dedicated log output, we can test it reliably without depending on side effects or indirect behavior elsewhere in the system.

It's not straight-forward to me how you would emit log messages from LoggerConfig which can be used to test if the individual loggers are configured correctly. Would that be something like getLogger("Runner").debug("Runner configured with level: XX") inside of LoggerConfig? If so, I think it is rather an anti-pattern to have a module emit log messages using the logger from another module. And it would also feel like shipping test code to production, as these lines would get executed in our deployments as well. Assuming there is no condition like "if TESTING", which would be a topic for itself. These are at least my first thoughts, but maybe I am missing something or there are other significant advantages to this approach. Feel free to further explain your idea; I just jumped to the first implementation approach I saw.

In the end, I don't really see how we can avoid an acceptance test for this kind of thing. Right now we are only talking about the runner/manager process, but what about the processor processes? They have the extra complication that logs are shipped through ipc to the runner/manager and then logged there using the logger configuration (at least that is my current understanding without checking the code once again). This is certainly something with more moving gears, meaning it is even more likely to fail in some subtle manner. Using an acceptance test, you could simply spin up logprep, configure a component which is only meant to run in the child process to log on debug and see if you actually get the log message. That seems relatively straight-forward to me and I can hardly see another way to easily verify & safeguard this overall behavior.

[kaya-david]

I see your point, and I get the line of thought. Personally, I would have taken the idea a bit further: we could make LoggerConfig emit explicit log messages indicating which loggers were configured and with which levels. That would allow us to write targeted acceptance tests that validate exactly this behavior. In other words: “Was the logger actually set to the level I specified in the config?” If we make that part observable through dedicated log output, we can test it reliably without depending on side effects or indirect behavior elsewhere in the system.

It's not straight-forward to me how you would emit log messages from LoggerConfig which can be used to test if the individual loggers are configured correctly. Would that be something like getLogger("Runner").debug("Runner configured with level: XX") inside of LoggerConfig? If so, I think it is rather an anti-pattern to have a module emit log messages using the logger from another module. And it would also feel like shipping test code to production, as these lines would get executed in our deployments as well. Assuming there is no condition like "if TESTING", which would be a topic for itself. These are at least my first thoughts, but maybe I am missing something or there are other significant advantages to this approach. Feel free to further explain your idea; I just jumped to the first implementation approach I saw.

In the end, I don't really see how we can avoid an acceptance test for this kind of thing. Right now we are only talking about the runner/manager process, but what about the processor processes? They have the extra complication that logs are shipped through ipc to the runner/manager and then logged there using the logger configuration (at least that is my current understanding without checking the code once again). This is certainly something with more moving gears, meaning it is even more likely to fail in some subtle manner. Using an acceptance test, you could simply spin up logprep, configure a component which is only meant to run in the child process to log on debug and see if you actually get the log message. That seems relatively straight-forward to me and I can hardly see another way to easily verify & safeguard this overall behavior.

My idea with adding explicit LoggerConfig log messages wasn’t meant as a replacement for acceptance tests. It was just a thought about improving observability and making integration tests easier.

But I understand your point: for acceptance tests it doesn’t really make sense to add extra LoggerConfig logs, because that would mix test-related code into production and still wouldn’t check the real end-to-end behavior. Your approach focuses on what actually happens at runtime, and that’s exactly what we want to verify there.

[codecov-commenter]

Codecov Report

:white_check_mark: All modified and coverable lines are covered by tests. :white_check_mark: Project coverage is 96.21%. Comparing base (5d57113) to head (0b32657).

Additional details and impacted files

@@            Coverage Diff             @@
##             main     #894      +/-   ##
==========================================
+ Coverage   96.20%   96.21%   +0.01%     
==========================================
  Files         211      211              
  Lines       13803    13807       +4     
==========================================
+ Hits        13279    13285       +6     
+ Misses        524      522       -2     

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

:rocket: New features to boost your workflow:

• :snowflake: Test Analytics: Detect flaky tests, report on failures, and find test suite problems.