Skip to content

Refactor logging for the whole library

Julien Michel requested to merge 1515-refactor-logging into develop

Summary

Closes #1515 (closed).

This merge requests provides the following:

  • A library wide, unified logging system based on singleton pattern that can be used from anywhere in the code :
#include "otbLogger.h"
otb::Logger::Instance()->Info("This is a log");
  • 5 increasing levels of logs: Debug, Info, Warning, Critical , Fatal
  • The level of logs that is displayed can be controlled by the new OTB_LOGGER_LEVEL environment variable. Only level greater than the level set in the variable will be displayed.
  • Default value for logging level if the environment variable is not set is Info.
  • All old macros (i.e., otbMsgDevMacro(), otbDebugMacro() and the like) have been factored to use a single macro, which in turn uses the otb::Logger class.
  • The most verbose messages have been reworked in various OTB classes to get a more compact, more informative output.

Example output with a default Release build (so log level is Warning) :

$ ./bin/otbcli_Convert -in ~/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif -out ~/tmp/out.tif uint8
Writing /home/michelj/tmp/out.tif...: 100% [**************************************************] (10 seconds)

Now, the same by setting log level to INFO with the environment variable :

$ OTB_LOGGER_LEVEL=INFO ./bin/otbcli_Convert -in ~/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif -out ~/tmp/out.tif uint8
2018-02-22 16:55:43 (INFO): Loading metadata from product files
2018-02-22 16:55:43 (INFO): Available memory: 128 Mb, estimated needed memory for full processing: 919.71 Mb, optimal number of stream divisions: 8
2018-02-22 16:55:43 (INFO): File /home/michelj/tmp/out.tif will be written in 9 blocks of 10979x1221 pixels
Writing /home/michelj/tmp/out.tif...: 100% [**************************************************] (10 seconds)

Even more verbose log using the DEBUG level :

$ OTB_LOGGER_LEVEL=DEBUG ./bin/otbcli_Convert -in ~/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif -out ~/tmp/out.tif uint8
2018-02-22 16:56:14 (INFO): Loading metadata from product files
2018-02-22 16:56:14 (DEBUG): Recursive evaluation of memory print for ProcessObjectExtractImageFilter (0xa4a940)
2018-02-22 16:56:14 (DEBUG): Recursive evaluation of memory print for ProcessObjectClampImageFilter (0xa4a230)
2018-02-22 16:56:14 (DEBUG): Recursive evaluation of memory print for ProcessObjectImageListToVectorImageFilter (0x971770)
2018-02-22 16:56:14 (DEBUG): Evaluation of memory print for DataObject ImageList (0x971a90)
2018-02-22 16:56:14 (DEBUG): Recursive evaluation of memory print for ProcessObjectMultiToMonoChannelExtractROI (0xa4cbb0)
2018-02-22 16:56:14 (DEBUG): Recursive evaluation of memory print for ProcessObjectImageFileReader (0x971d20)
2018-02-22 16:56:14 (DEBUG): Evaluation of memory print for DataObject VectorImage (0x9784a0)
2018-02-22 16:56:14 (DEBUG): Evaluation of memory print for DataObject Image (0xa4ce00)
2018-02-22 16:56:14 (DEBUG): Evaluation of memory print for DataObject VectorImage (0xa4c7f0)
2018-02-22 16:56:14 (DEBUG): Evaluation of memory print for DataObject VectorImage (0xa4a4c0)
2018-02-22 16:56:14 (DEBUG): Evaluation of memory print for DataObject VectorImage (0xa4ab80)
2018-02-22 16:56:14 (DEBUG): Evaluation of memory print for DataObject VectorImage (0xa4ab80)
2018-02-22 16:56:14 (INFO): Available memory: 128 Mb, estimated needed memory for full processing: 919.71 Mb, optimal number of stream divisions: 8
2018-02-22 16:56:14 (INFO): File /home/michelj/tmp/out.tif will be written in 9 blocks of 10979x1221 pixels
Writing /home/michelj/tmp/out.tif...: 0% [                                                  ]2018-02-22 16:56:14 (DEBUG): GDAL reads [0, 10978]x[0, 1220] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:14 (DEBUG): GDAL read took 72 ms
Writing /home/michelj/tmp/out.tif...: 10% [*****                                             ]2018-02-22 16:56:15 (DEBUG): GDAL writes [0, 10978]x[0, 1220] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:16 (DEBUG): GDAL write took 9 ms
2018-02-22 16:56:16 (DEBUG): GDAL reads [0, 10978]x[1221, 2441] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:16 (DEBUG): GDAL read took 47 ms
Writing /home/michelj/tmp/out.tif...: 22% [***********                                       ]2018-02-22 16:56:17 (DEBUG): GDAL writes [0, 10978]x[1221, 2441] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:17 (DEBUG): GDAL write took 9 ms
2018-02-22 16:56:17 (DEBUG): GDAL reads [0, 10978]x[2442, 3662] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:17 (DEBUG): GDAL read took 52 ms
Writing /home/michelj/tmp/out.tif...: 32% [****************                                  ]2018-02-22 16:56:18 (DEBUG): GDAL writes [0, 10978]x[2442, 3662] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:18 (DEBUG): GDAL write took 9 ms
2018-02-22 16:56:18 (DEBUG): GDAL reads [0, 10978]x[3663, 4883] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:18 (DEBUG): GDAL read took 48 ms
Writing /home/michelj/tmp/out.tif...: 44% [**********************                            ]2018-02-22 16:56:19 (DEBUG): GDAL writes [0, 10978]x[3663, 4883] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:19 (DEBUG): GDAL write took 5 ms
2018-02-22 16:56:19 (DEBUG): GDAL reads [0, 10978]x[4884, 6104] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:19 (DEBUG): GDAL read took 34 ms
Writing /home/michelj/tmp/out.tif...: 54% [***************************                       ]2018-02-22 16:56:20 (DEBUG): GDAL writes [0, 10978]x[4884, 6104] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:20 (DEBUG): GDAL write took 5 ms
2018-02-22 16:56:20 (DEBUG): GDAL reads [0, 10978]x[6105, 7325] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:20 (DEBUG): GDAL read took 35 ms
Writing /home/michelj/tmp/out.tif...: 66% [*********************************                 ]2018-02-22 16:56:21 (DEBUG): GDAL writes [0, 10978]x[6105, 7325] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:21 (DEBUG): GDAL write took 6 ms
2018-02-22 16:56:21 (DEBUG): GDAL reads [0, 10978]x[7326, 8546] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:22 (DEBUG): GDAL read took 36 ms
Writing /home/michelj/tmp/out.tif...: 76% [**************************************            ]2018-02-22 16:56:23 (DEBUG): GDAL writes [0, 10978]x[7326, 8546] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:23 (DEBUG): GDAL write took 6 ms
2018-02-22 16:56:23 (DEBUG): GDAL reads [0, 10978]x[8547, 9767] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:23 (DEBUG): GDAL read took 35 ms
Writing /home/michelj/tmp/out.tif...: 88% [********************************************      ]2018-02-22 16:56:24 (DEBUG): GDAL writes [0, 10978]x[8547, 9767] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:24 (DEBUG): GDAL write took 6 ms
2018-02-22 16:56:24 (DEBUG): GDAL reads [0, 10978]x[9768, 10979] x 1 bands of type Float32 from file /home/michelj/tmp/peps_ortho_s1/s1a_32TNR_vh_DES_20170814t052658.tif
2018-02-22 16:56:24 (DEBUG): GDAL read took 35 ms
Writing /home/michelj/tmp/out.tif...: 100% [**************************************************]2018-02-22 16:56:25 (DEBUG): GDAL writes [0, 10978]x[9768, 10979] x 1 bands of type Byte to file /home/michelj/tmp/out.tif
2018-02-22 16:56:25 (DEBUG): GDAL write took 6 ms
 (10 seconds)

Rationale

see #1515 (closed) for rationale. Short summary is :

  • Logs can be activated without rebuilding
  • They are less verbose and informative
  • All logs are displayed in the application log tab when using Qt Gui,
  • The logging system is unified.

Implementation Details

Classes and files

Main changes are:

  • the otb::Logger class has been moved from Wrappers/ApplicationEngine to Core/Common and made a singleton
  • the otb::ConfigurationManager has a new method to parse the logger level from the environment variable. It returns a default value if the variable is not found
  • At instanciation (First call to ::Instance()), otb::Logger calls the otb::ConfigurationManager to retrieve the logger level.
  • Macros have been refactored in otbMacros.h to be more compact and avoid code duplication (note that all former Macros still work).
  • The most verbose calls to the old macros have been refactored to be more compact and more informative (there are still other calls to those macros that need to be adressed, but they are not flooding the logs).

Note that logging of applications have been kept separate to avoid mixing information from the library and outputs of the applications.

Applications

No changes made to applications.

Tests

No changes made to tests.

Documentation

This ought to be documented somewhere, but where ?

Additional notes

  • Impact on performances is not known, probably minor (but instead of empty macro now we always do something)
  • Mixes of logs from the applications and logs from OTB might be difficult to read. Maybe we can create a new logging level and reserve it for application
  • Default level values and what trace goes to what level can of course be discussed
  • It would be nice to be able to change the log level on the fly in Monteverdi or the application GUI.
Edited by Laurențiu Nicola

Merge request reports