key4hep / k4FWCore

Core Components for the Gaudi-based Key4hep Framework
Apache License 2.0
10 stars 26 forks source link

Set only one handler for logging in k4run #192

Closed jmcarcell closed 4 months ago

jmcarcell commented 4 months ago

BEGINRELEASENOTES

ENDRELEASENOTES

I'm not sure how since I can't reproduce on main (well I only tried one or two steering files), but on https://github.com/key4hep/k4FWCore/pull/173 when running with k4run, sometimes the logging messages will be duplicated:

$ k4run ExampleFunctionalMemory.py

[k4run]
# Option name: Transformer.OutputLevel Transformer.OutputLevel 0
[k4run] Option name: Transformer.OutputLevel Transformer.OutputLevel 0
# Option name: Transformer.InputCollection Transformer.InputCollection ['MCParticles']
[k4run] Option name: Transformer.InputCollection Transformer.InputCollection ['MCParticles']
# Option name: Transformer.OutputCollection Transformer.OutputCollection ['NewMCParticles']
[k4run] Option name: Transformer.OutputCollection Transformer.OutputCollection ['NewMCParticles']
# Option name: Transformer.Offset Transformer.Offset 10
[k4run] Option name: Transformer.Offset Transformer.Offset 10
ApplicationMgr    SUCCESS

and this seems to be because there is the default handler and the new one that adds the [k4run] added. This PR sets the list to only be the one that adds [k4run].

One could think this is because of https://github.com/key4hep/k4FWCore/pull/173 but k4run there is the same as in main so nothing should change with respect to logging. Related: https://stackoverflow.com/questions/6729268/log-messages-appearing-twice-with-python-logging

andresailer commented 4 months ago

could it be caused by a change in #173 in the module imports, where one of the imports creates a handler? Or something directly calling logging.[info|error|warning...] which would call basicConfig if no handler exists?

jmcarcell commented 4 months ago

I tried reducing a steering file to the minimum: in the example I quote ExampleFunctionalMemory only loads ExampleFunctionalTransformer from Configurables and INFO and still happens (that means, without apparently importing any of the new python code). So it doesn't seem to be that. Then I checked there isn't any other code calling or importing logging and with pdb I checked addHandler in k4run is being called only once. So I still don't know where it comes from. In any case, this approach should be correct because right now have a single handler so it makes sure there is only one handler.

jmcarcell commented 4 months ago

I don't see any downsides to this; I don't know why that was happening but with the fix it should always be correct.