Uploaded image for project: 'Data Management'
  1. Data Management
  2. DM-17741

pytest extra chatty on failed tests due to fonts and matplotlib

    Details

    • Type: Bug
    • Status: Done
    • Resolution: Done
    • Fix Version/s: None
    • Component/s: log
    • 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
      ...
      

        Attachments

          Activity

          Hide
          salnikov 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
          salnikov 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
          tjenness Tim Jenness added a comment -

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

          Show
          tjenness Tim Jenness added a comment - Great. I'm happy then. I had not realized that the -L options fixed up both root loggers.
          Hide
          salnikov 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
          salnikov 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
          tjenness Tim Jenness added a comment -

          Looks great!

          Show
          tjenness Tim Jenness added a comment - Looks great!
          Hide
          salnikov 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
          salnikov 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:
              salnikov Andy Salnikov
              Reporter:
              Parejkoj John Parejko
              Reviewers:
              Tim Jenness
              Watchers:
              Andy Salnikov, John Parejko, John Swinbank, Paul Price, Tim Jenness
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Summary Panel