Ensure logging messages don't reach the root logger

[hugobuddel]

DEBUG should only be used when, well, debugging, and is thus not useful to have on by default.

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Comparison is base (2c7a0f0) 75.52% compared to head (42a9ed8) 75.53%.
Report is 2 commits behind head on dev_master.

Additional details and impacted files

@@             Coverage Diff             @@
##           dev_master     #345   +/-   ##
===========================================
  Coverage       75.52%   75.53%           
===========================================
  Files              59       59           
  Lines            7870     7871    +1     
===========================================
+ Hits             5944     5945    +1     
  Misses           1926     1926           

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[teutoburg]

There's a difference between the level of the logger and that of the handler. The console handler is set to INFO by default, so the DEBUG level messages should not get through! I'll investigate a bit more to understand why it's apparently still happening.

[teutoburg]

It seems the (outdated but not yet removed) root logging call in the @add_function_call_str decorator in scopesim_templates is somehow adding a handler to the root logger. Not sure if that's what happened in Gilles' case, but it's certainly a way to get this bug. I had another PR in the making that would mitigate that in a more robust way, by setting propagate=False for the astar logger. But I got distracted from finishing that.

Anyway, I do understand what the purpose of DEBUG is and it was never my intent to display DEBUG level messages to the user by default!

[teutoburg]

Interesting, now the tests fail on the Quantization effect which I introduced recently. The "captured output" shows that those warnings are there though...

[teutoburg]

Maybe because the logging configuration is not (correctly) applied in the tests? I can attempt to fix it and then push to this PR if that's ok with you

[hugobuddel]

Now test_logs_warning_for_float_dtype() fails:

>       assert "Setting quantized data to dtype" in caplog.text
E       AssertionError: assert 'Setting quantized data to dtype' in ''
E        +  where '' = <_pytest.logging.LogCaptureFixture object at 0x00000173002FEE10>.text

I think I don't understand how logging works... let me try to summarize:

• top_logger has loglevel Warning, this level is (apparently) tested in test_logs_warning_for_float_dtype()
  • child sim_logger is set to Debug, this (apparently) causes all debug info to be printed (at least in a notebook)
  • each module has its own child from top_logger, which somehow both gets the Warning level from top_logger (see failing test) as well as the Debug level from sim_logger, see output in notebooks

Then there are two handlers that are attached to the top_logger

• one for output to a file, which gets level Debug, I suppose this one is 'invisible' to the issue at hand
• one for output to stdout, which gets level Info, but not sure how this comes into play

I don't understand how the Debug info gets into the notebook before this PR, nor why the test fails for this PR.

By the way, I figured you understood what the levels are for; setting the Debug level was done long ago, not sure whether it was also visible in the past though.

[hugobuddel]

Maybe because the logging configuration is not (correctly) applied in the tests? I can attempt to fix it and then push to this PR if that's ok with you

Yeah that's fine. I didn't expect this to be so involved; I thought it was just an outdated loglevel setting that we never got to change

[hugobuddel]

Everything seems to work as intended now I think.

The notebooks etc do not show the debug information anymore.

[hugobuddel]

The output in the notebooks now looks identical to the output before #339 .

I also verified that it is still possible to set the loglevel to DEBUG through ~/.scopesim_rc.yaml. I was a bit afraid that disabling the propagation would prevent that.

Maybe when we setup nightly runs of the notebooks (and other tests, and bulk simulations), we could automatically generate diffs with the previous night, to catch unexpected problems.

Shall we merge this?

[teutoburg]

I thought it was just an outdated loglevel setting that we never got to change

It was something I introduced in the recent logging changes. The previous setting was WARNING by default, which was also what Oliver complained about in #257. It worked fine (i.e., no DEBUG by default) when I tested it, but I didn't test the case that there might be a plain logging.debug() call somewhere outside scopesim, which I should have. Had I had the time to continue with the dict config, we most likely would have never noticed, because that includes the same propagate: False. But this way, I at least learned even more about how logging works, which is a positive.

[teutoburg]

This was also useful in the scope of the tests, because 42a9ed8 now also fixes the huge log spam that was sometimes seen in the tests.

[teutoburg]

Changed the title to more closely reflect what's actually going on 🙃

[teutoburg]

Maybe when we setup nightly runs of the notebooks (and other tests, and bulk simulations), we could automatically generate diffs with the previous night, to catch unexpected problems.

The notebook plugin for pytest has a feature that does something like that, it's on my TODO to investigate this anyway...