# pytest extra chatty on failed tests due to fonts and matplotlib

XMLWordPrintable

## Details

• Type: Bug
• Status: Done
• Resolution: Done
• Fix Version/s: None
• Component/s:
• Labels:
• Story Points:
1
• Sprint:
DB_S19_02
• Team:
Data Access and Database

## Description

The new changes that forward python log messages to lsst.log have resulted in pytest dumping a giant list of DEBUG messages related to matplotlib and/or font_manager after failed tests. This can require scrolling up through several pages of useless messages before you get to the actual pytest output.

Tim Jenness suggests either changing the default logging level we use when running pytest, or to configure our logger to ignore debug matplotlib messages.

Portion of an example "Captured log call" from a failed fgcm test:

 ------------------------------ Captured log call ------------------------------- font_manager.py 1343 DEBUG findfont: Matching :family=sans-serif:style=normal:variant=normal:weight=normal:stretch=normal:size=14.0 to DejaVu Sans ('/home/parejkoj/lsst/lsstsw/miniconda/envs/lsst-scipipe/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSans.ttf') with score of 0.050000 font_manager.py 1343 DEBUG findfont: Matching :family=sans-serif:style=normal:variant=normal:weight=normal:stretch=normal:size=16.0 to DejaVu Sans ('/home/parejkoj/lsst/lsstsw/miniconda/envs/lsst-scipipe/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSans.ttf') with score of 0.050000 font_manager.py 1343 DEBUG findfont: Matching :family=STIXGeneral:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXGeneral ('/home/parejkoj/lsst/lsstsw/miniconda/envs/lsst-scipipe/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXGeneral.ttf') with score of 0.050000 font_manager.py 1343 DEBUG findfont: Matching :family=STIXGeneral:style=italic:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXGeneral ('/home/parejkoj/lsst/lsstsw/miniconda/envs/lsst-scipipe/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXGeneralItalic.ttf') with score of 0.050000 ... and more ... 

## Activity

Hide
Andy Salnikov added a comment -

Well, if user configures logging through supported interface, that is providing a bunch of -L options to CmdLineTask (or pipetask), then both lsst.log loggers and their matching logging loggers will be set to the same level. If one says -L DEBUG then root loggers will be set to DEBUG so all debug messages will be seen (forwarded to lsst.log). If a child logger is configured (-L matplotlib=debug) then things will work too, debug messages sent to logging matplotlib logger will be accepted (because it is configured with DEBUG) and propagated to root logger (parent logger level does not matter when propagating) which will send them to handler(s). So I think with the mechanism implemented in this patch things will work as expected, potential trouble is when log4cxx is configured separately using some external mechanism (but this should not apply to CmdLineTask/pipetask because we always re-initialize log4cxx)

Show
Andy Salnikov added a comment - Well, if user configures logging through supported interface, that is providing a bunch of -L options to CmdLineTask (or pipetask), then both lsst.log loggers and their matching logging loggers will be set to the same level. If one says -L DEBUG then root loggers will be set to DEBUG so all debug messages will be seen (forwarded to lsst.log ). If a child logger is configured ( -L matplotlib=debug ) then things will work too, debug messages sent to logging matplotlib logger will be accepted (because it is configured with DEBUG) and propagated to root logger (parent logger level does not matter when propagating) which will send them to handler(s). So I think with the mechanism implemented in this patch things will work as expected, potential trouble is when log4cxx is configured separately using some external mechanism (but this should not apply to CmdLineTask/pipetask because we always re-initialize log4cxx)
Hide
Tim Jenness added a comment -

Great. I'm happy then. I had not realized that the -L options fixed up both root loggers.

Show
Tim Jenness added a comment - Great. I'm happy then. I had not realized that the -L options fixed up both root loggers.
Hide
Andy Salnikov added a comment -

Tim Jenness, thanks to K-T there is now more changes and one more PR (for log), could you look at it once again?

Show
Andy Salnikov added a comment - Tim Jenness , thanks to K-T there is now more changes and one more PR (for log ), could you look at it once again?
Hide
Tim Jenness added a comment -

Looks great!

Show
Tim Jenness added a comment - Looks great!
Hide
Andy Salnikov added a comment - - edited

Updated docstrings for new class and merged all three PRs.
After messing around with all those pointless transformations I really wish we used Python logging everywhere on Python side and only used forwarding feature of lsst.log. I guess we'll be moving slowly in that direction during the next 10 years or so

Show
Andy Salnikov added a comment - - edited Updated docstrings for new class and merged all three PRs. After messing around with all those pointless transformations I really wish we used Python logging everywhere on Python side and only used forwarding feature of lsst.log . I guess we'll be moving slowly in that direction during the next 10 years or so

## People

• Assignee:
Andy Salnikov
Reporter:
John Parejko
Reviewers:
Tim Jenness
Watchers:
Andy Salnikov, John Parejko, John Swinbank, Paul Price, Tim Jenness