Default handler for loggers

[Zachary Marshall]

For some newer gridpacks, when running people encounter this error:

No handlers could be found for logger "madevent.cards"

That seems to come from madevent/bin/internal/banner.py . We've confirmed that adding

logging.basicConfig()

before the first call to logging.getLogger solves the problem, and the Python manual indeed says that it's a good idea to configure the loggers appropriately before using them.

Unfortunately, I've not found the magic trick -- it seems as though some users encounter this error and others do not, and I haven't identified a consistent issue for the ones that do encounter the error. The solution seems harmless enough, though, so I'd suggest adding such a configuration call somewhere in Madgraph (even in the top level scripts if you wish).

Thanks,
Zach

[Olivier Mattelaer (olivier-mattelaer)]

Hi,

I guess that the issue is that such user are using a way to access the code which is not one of the "official" entry for the code (i.e. the run is not executed via a script in ./bin)
So adding this in top level madgraph will not help (and putting it within banner.py is not a good idea).

So the real question is what is the python script that is really run at that time.
The typical reason why a script outside of ./bin is executed is to run something in multi-core mode.
So could this be related to link to re-weighting or to some other post-processing mode?

Cheers,

Olivier

[Zachary Marshall (zach-marshall)]

Hi Olivier,

In both cases I remember, the person was running ./bin/run.sh from a gridpack, which I think is an official way to run the code.

Best,
Zach

[Karolos Potamianos (karolos-potamianos)]

Hello,

I wanted to report that I also see this message when running MG 2.9.2 (with Python3, after applying the patched linked from https://bugs.launchpad.net/mg5amcnlo/+bug/1918129 and https://bugs.launchpad.net/mg5amcnlo/+bug/1918169) and using a gridpack that was produced for the following process

generate p p > w+{0} w+{0} j j QCD=0, w+ > e+ ve, w+ > mu+ vm @1

karolos@karoloss-macbook-pro testGridpack % tar xf ../PROC_ssWWjj_EW_LL/run_01_gridpack.tar.gz
karolos@karoloss-macbook-pro testGridpack % ./run.sh 1000 0
Now generating 1000 events with random seed 0 and granularity 1
WRITE GRIDCARD /Volumes/CERNbox/ssWWR2/MCgen/testGridpack/madevent
No handlers could be found for logger "madevent.cards"
P1_qq_wp0wp0qq_wp_lvl_wp_lvl
DONE
write ./events.lhe.gz
karolos@karoloss-macbook-pro testGridpack %

I also checked that it happens also when running ./madevent/bin/run.sh 1000 0; the script is then clearly is within the ./bin folder.

Best,
Karolos

[Olivier Mattelaer (olivier-mattelaer)]

Thanks Karolos,

I will take a look but this is obviously low priority since this is erverything but critical.

Cheers,

Olivier

> On 16 Mar 2021, at 23:07, Karolos Potamianos <email address hidden> wrote:
>
> Hello,
>
> I wanted to report that I also see this message when running MG 2.9.2
> (with Python3, after applying the patched linked from
> https://bugs.launchpad.net/mg5amcnlo/+bug/1918129 and
> https://bugs.launchpad.net/mg5amcnlo/+bug/1918169) and using a gridpack
> that was produced for the following process
>
> generate p p > w+{0} w+{0} j j QCD=0, w+ > e+ ve, w+ > mu+ vm @1
>
>
> karolos@karoloss-macbook-pro testGridpack % tar xf ../PROC_ssWWjj_EW_LL/run_01_gridpack.tar.gz
> karolos@karoloss-macbook-pro testGridpack % ./run.sh 1000 0
> Now generating 1000 events with random seed 0 and granularity 1
> WRITE GRIDCARD /Volumes/CERNbox/ssWWR2/MCgen/testGridpack/madevent
> No handlers could be found for logger "madevent.cards"
> P1_qq_wp0wp0qq_wp_lvl_wp_lvl
> DONE
> write ./events.lhe.gz
> karolos@karoloss-macbook-pro testGridpack %
>
> I also checked that it happens also when running ./madevent/bin/run.sh
> 1000 0; the script is then clearly is within the ./bin folder.
>
> Best,
> Karolos
>
> --
> You received this bug notification because you are subscribed to
> MadGraph5_aMC@NLO.
> https://bugs.launchpad.net/bugs/1897721
>
> Title:
> Default handler for loggers
>
> Status in MadGraph5_aMC@NLO:
> New
>
> Bug description:
> For some newer gridpacks, when running people encounter this error:
>
> No handlers could be found for logger "madevent.cards"
>
> That seems to come from madevent/bin/internal/banner.py . We've
> confirmed that adding
>
> logging.basicConfig()
>
> before the first call to logging.getLogger solves the problem, and the
> Python manual indeed says that it's a good idea to configure the
> loggers appropriately before using them.
>
> Unfortunately, I've not found the magic trick -- it seems as though
> some users encounter this error and others do not, and I haven't
> identified a consistent issue for the ones that do encounter the
> error. The solution seems harmless enough, though, so I'd suggest
> adding such a configuration call somewhere in Madgraph (even in the
> top level scripts if you wish).
>
> Thanks,
> Zach
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/mg5amcnlo/+bug/1897721/+subscriptions

[Karolos Potamianos (karolos-potamianos)]

Dear Olivier,

Thank you.

Cheers,
Karolos

[Karolos Potamianos (karolos-potamianos)]

FYI, my current workaround is to do the following:

sed -i '/logging.basicConfig/s/^#//' madevent/bin/gridrun
sed -i '/def set_configuration/a\ \ \ \ logging.basicConfig()' madevent/bin/generate_events

in the gridpack produced my MG2.9.2

Cheers,
Karolos

[Olivier Mattelaer (olivier-mattelaer)]

Why do you need a workaround?

As far as I know this is just printout not creating a crash.
Or am I wrong?

Olivier

> On 26 Mar 2021, at 14:42, Karolos Potamianos <email address hidden> wrote:
>
> FYI, my current workaround is to do the following:
>
> sed -i '/logging.basicConfig/s/^#//' madevent/bin/gridrun
> sed -i '/def set_configuration/a\ \ \ \ logging.basicConfig()' madevent/bin/generate_events
>
> in the gridpack produced my MG2.9.2
>
> Cheers,
> Karolos
>
> --
> You received this bug notification because you are subscribed to
> MadGraph5_aMC@NLO.
> https://bugs.launchpad.net/bugs/1897721
>
> Title:
> Default handler for loggers
>
> Status in MadGraph5_aMC@NLO:
> Confirmed
>
> Bug description:
> For some newer gridpacks, when running people encounter this error:
>
> No handlers could be found for logger "madevent.cards"
>
> That seems to come from madevent/bin/internal/banner.py . We've
> confirmed that adding
>
> logging.basicConfig()
>
> before the first call to logging.getLogger solves the problem, and the
> Python manual indeed says that it's a good idea to configure the
> loggers appropriately before using them.
>
> Unfortunately, I've not found the magic trick -- it seems as though
> some users encounter this error and others do not, and I haven't
> identified a consistent issue for the ones that do encounter the
> error. The solution seems harmless enough, though, so I'd suggest
> adding such a configuration call somewhere in Madgraph (even in the
> top level scripts if you wish).
>
> Thanks,
> Zach
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/mg5amcnlo/+bug/1897721/+subscriptions

[Olivier Mattelaer (olivier-mattelaer)]

Ok I do not reproduce that issue for that gridpack, I guess that this might be related to some environment variable (in particular what is your PYTHONPATH?)

So looking at you sed command is instructive. Do you need both sed command to remove that printout?

The second one seems fully irrelevant for me.

The first one might indicate what the issue is:
try:
    if __debug__ and options.logging == 'INFO':
        options.logging = 'DEBUG'
    logging.config.fileConfig(os.path.join(root_path, 'internal', 'me5_logging.conf'))
    logging.root.setLevel(eval('logging.' + options.logging))
    logging.getLogger('madgraph').setLevel(eval('logging.' + options.logging))
except:
    pass

You can see that all the setting are done in a way to avoid any crash on the logging in case something happens, so the situation is likely that one of those command are crashing replacing those lines with
try:
    if __debug__ and options.logging == 'INFO':
        options.logging = 'DEBUG'
    logging.config.fileConfig(os.path.join(root_path, 'internal', 'me5_logging.conf'))
    logging.root.setLevel(eval('logging.' + options.logging))
    logging.getLogger('madgraph').setLevel(eval('logging.' + options.logging))
except:
    raise

Should allow to identify which of those three lines have issue and allow to have the proper fix and keeping the correct functionality of the logging behavior.

Thanks for the help,

Olivier

[Karolos Potamianos (karolos-potamianos)]

Hello Olivier,

(Apologies, this message wasn't sent last week; meanwhile I saw you responded so I will look at your response -- happy to help if can, and thanks for looking into this. But I wanted to post this anyway, in case it helps to give some context.)

You are right: it doesn't prevent generating the events. But it's also technically improper to use a logger without having configured a handler for it.

As part of our ATLAS infrastructure we check the error stream to confirm there are no ignored warnings/errors. This message (No handlers could be found for logger "madevent.cards") appearing in stderr is therefore a problem to us.

BTW, the patch I have above still causes some issue: so the proper fix (for our case) would be

sed -i '/^import logging/alogging.basicConfig()' madevent/bin/gridrun madevent/bin/generate_events

and generally for any file in bin/ (which are entrypoints) would make sense.

This works for most cases though there are some race conditinos (I think) causing this output to the stderr in some cases when running on a batch system (HTCondor), but not always, in line with what was reported by Zach.

Karolos

Note that this wouldn't go away with Python 3.2+ as according to https://github.com/python/cpython/blob/master/Doc/howto/logging.rst#what-happens-if-no-configuration-is-provided there will be a lastResort logger that by default logs anything to stderr (including stuff meant for stdout) until the handler is properly configured.

[Karolos Potamianos (karolos-potamianos)]

Hello Olivier,

Thanks for your feedback and suggestion. I will modify the code to raise the exception and get back to you. Indeed, I agree the second sed is irrelevant, also in my follow-up, as I mistakenly though that generate_events was being used. My bad.

Note that with the uncommmenting on the line, I still obtain (in some cases) the output to stderr (I guess it depends on how options.logging is configued, which is why I just went with a plain logging.basicConfig(), which works. However, I agree that this should be understood better as it's not good to ignore logging options when they are provided.

I'll keep you posted.

Thanks,
Karolos

[Karolos Potamianos (karolos-potamianos)]

Hello Olivier,

Apologies for the delay in getting back to this. After changing the exception (from pass to raise), I get the following output:

Traceback (most recent call last):
  File "madevent/bin/gridrun", line 82, in <module>
    logging.config.fileConfig(os.path.join(root_path, 'internal', 'me5_logging.conf'))
  File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/logging/config.py", line 77, in fileConfig
    formatters = _create_formatters(cp)
  File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/logging/config.py", line 113, in _create_formatters
    flist = cp.get("formatters", "keys")
  File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/ConfigParser.py", line 607, in get
    raise NoSectionError(section)
ConfigParser.NoSectionError: No section: 'formatters'

Cheers,
Karolos

[Olivier Mattelaer (olivier-mattelaer)]

Thanks,

now it makes sense. Here is the patch that is going to be release very soon in our long term stable release and our latest release as well:
https://bazaar.launchpad.net/~maddevelopers/mg5amcnlo/2.9.4/revision/312

Cheers,

Olivier

[Karolos Potamianos (karolos-potamianos)]

Thanks a lot, Olivier!

Cheers,
Karolos

[Karolos Potamianos (karolos-potamianos)]

Hello Olivier,

I applied the patch to my gridpack (adding the 'bin' to the path) and it didn't work. I then re-rasied the exception and obtain the following trace:

Traceback (most recent call last):
  File "madevent/bin/gridrun", line 82, in <module>
    logging.config.fileConfig(os.path.join(root_path, 'bin', 'internal', 'me5_logging.conf'))
  File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/logging/config.py", line 77, in fileConfig
    formatters = _create_formatters(cp)
  File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/logging/config.py", line 134, in _create_formatters
    c = _resolve(class_name)
  File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/logging/config.py", line 101, in _resolve
    __import__(used)
ImportError: No module named ColorFormatter

I saw there is a class ColorFormatter in madgraph/interface/coloring_logging.py but for some reason it's not autmatically included.

Is this something that you understand on your end, or does the patch need to be applied in other places (than gridrun) to work ?

Cheers,
Karolos

[Olivier Mattelaer (olivier-mattelaer)]

This should fix that issue:

https://bazaar.launchpad.net/~maddevelopers/mg5amcnlo/LTS_dev/revision/316

Cheers,

Olivier

> On 31 May 2021, at 16:44, Karolos Potamianos <email address hidden> wrote:
>
> Hello Olivier,
>
> I applied the patch to my gridpack (adding the 'bin' to the path) and it
> didn't work. I then re-rasied the exception and obtain the following
> trace:
>
> Traceback (most recent call last):
> File "madevent/bin/gridrun", line 82, in <module>
> logging.config.fileConfig(os.path.join(root_path, 'bin', 'internal', 'me5_logging.conf'))
> File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/logging/config.py", line 77, in fileConfig
> formatters = _create_formatters(cp)
> File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/logging/config.py", line 134, in _create_formatters
> c = _resolve(class_name)
> File "/cvmfs/atlas.cern.ch/repo/sw/software/21.6/sw/lcg/releases/LCG_88b/Python/2.7.13/x86_64-centos7-gcc62-opt/lib/python2.7/logging/config.py", line 101, in _resolve
> __import__(used)
> ImportError: No module named ColorFormatter
>
> I saw there is a class ColorFormatter in
> madgraph/interface/coloring_logging.py but for some reason it's not
> autmatically included.
>
> Is this something that you understand on your end, or does the patch
> need to be applied in other places (than gridrun) to work ?
>
> Cheers,
> Karolos
>
> --
> You received this bug notification because you are subscribed to
> MadGraph5_aMC@NLO.
> https://bugs.launchpad.net/bugs/1897721
>
> Title:
> Default handler for loggers
>
> Status in MadGraph5_aMC@NLO:
> Confirmed
>
> Bug description:
> For some newer gridpacks, when running people encounter this error:
>
> No handlers could be found for logger "madevent.cards"
>
> That seems to come from madevent/bin/internal/banner.py . We've
> confirmed that adding
>
> logging.basicConfig()
>
> before the first call to logging.getLogger solves the problem, and the
> Python manual indeed says that it's a good idea to configure the
> loggers appropriately before using them.
>
> Unfortunately, I've not found the magic trick -- it seems as though
> some users encounter this error and others do not, and I haven't
> identified a consistent issue for the ones that do encounter the
> error. The solution seems harmless enough, though, so I'd suggest
> adding such a configuration call somewhere in Madgraph (even in the
> top level scripts if you wish).
>
> Thanks,
> Zach
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/mg5amcnlo/+bug/1897721/+subscriptions