Logging in python wrapper

Summary

Redirect the logs produced by OTB to Python

Rationale

Today, logs from the applications are not printed when using the Python API, and other logs from OTB are printed to stdout using std::cout. It would be convenient to redirect these logs to Python. See related Issue #1831 (closed).

In this Merge Request we consider three types of logs :

1. Logs from OTB : the logs created outside OTB applications using a log macro (e.g. otbDebugMacro(msg), otbLogMacro(lvl,msg) ...). These logs are issued using the singleton otbLogger.Instance() which is by default connected to a itkStdStreamLogOutput (i.e. to stdout)

2. Logs from OTB applications : The logs created inside OTB applications, for instance with otbAppLogINFO(msg). Each application uses its own instance of otbLogger. When using the commandLineLauncher, the logger is connected to a itkStdStreamLogOutput and the log are redirected to the terminal, when using Qt the logs are redirected to a window, but in Python the logger is not connected to anything and the logs are not redirected.

3. Progress Reporting : the progess bar logs. Progress reporting should be added every time the AddProcess method of Application is called. In command line and Qt this is done by using an observer on the AddProcessToWatchEvent method (called by AddProcess), but nothing is done in Python

Implementation Details

LogOutputCallback

The new LogOutputCallback class is what is used in this Merge Request to redirect OTB C++ logs to Python. It relies on Swig Directors to allow cross language polymorphism. It has the methods Call(string) and Flush() which are not doing anything, but which are overridden in Python using directors in the PythonLogOutputCallback class. In Python the Call method is a proxy to sys.stdout.write and Flush is a proxy to sys.stdout.flush.

The PythonLogOutput (C++) class is a itk::LogOutput using a LogOutputCallback to print and flush. It is wrapped in Python with Swig, and we can set its callback to be a PythonLogOutputCallback object using Python.

The objects _libraryLogOutput and _libraryLogCallback are created and stored when importing the otbApplication module, so we can use them to log without having to create new objects.

Logs from OTB

The otb::logger class has been wrapped in Python with Swig, so we can access the Singleton logger in Python. We need to remove the itkStdStreamLogOutput from the outputs of this logger (unless other output have been added by the user, this is the only output of logger.Instance()) and replace it by _libraryLogOutput. As we cannot manipulate the set of LogOutput used by a logger (the object containing these outputs is a itk::MultipleLogOutput, and we can only add LogOutput to it, not remove them), I added a method to reset all outputs of a otb::logger. This method is used before adding the PythonLogOutput

Logs from Applications

We need to connect the application's logger to the _libraryLogOutput.

This is done automatically when calling otb.Registry.CreateApplication(name)

Progress Reporting

The new CallbackProgressReporter C++ class is used to do progress reporting using a PythonLogOutputCallback. Like StandardOneLineFilterWatcher it generates the progress line, but instead of printing it to stdout with cout, it uses the callback.

the class ProgressReporterManager stores a vector of CallbackProgressReporter. It also stores a itk::MemberCommand that can be used to add CallbackProgressReporter to the vector. This command can be used on an application with :

appli.AddObserver(AddProcessToWatchEvent(), _libraryProgressReportManager.GetAddProcessCommand())

Then, there will be progress reporting for every process added with the AddProcess() method

Limitations

In the same fashion as in !364 (merged), I added in CallbackProgressReporter a test to determine if the output (sys.stdout) is redirected, using sys.stdout.isatty(), and if so, the progress line is only printed at the end. This avoid having huge logs when the output is redirected to a file.

The problem is that sometime in Python, the output is redirected but should still be interactive. This is the case is some Python IDE like Spyder where sys.stdout is redirected to another window (and this might also be the case with Jupyter notebooks, I have not tested). In these cases the progress reporting is not interactive and the output is printed at the end.

Example

the code :

import otbApplication as otb

appli = otb.Registry.CreateApplication("EdgeExtraction")
appli.SetParameterString("in","otb-data/Examples/qb_RoadExtract.tif")
appli.SetParameterString("out","/tmp/out.tif")

appli.ExecuteAndWriteOutput()

outputs :

cedric@PO16089LX:/Datas/Code/OTB/scripts$ ipython3 testAppli.py 
2019-03-05 18:49:39  :  EdgeExtraction  (INFO) Default RAM limit for OTB is 256 MB
2019-03-05 18:49:39  :  EdgeExtraction  (INFO) GDAL maximum cache size is 794 MB
2019-03-05 18:49:39  :  EdgeExtraction  (INFO) OTB will use at most 12 threads
2019-03-05 18:49:39  :    (INFO) No kwl metadata found in file /home/cedric/Documents/OTBData/otb-data/Examples/qb_RoadExtract.tif
2019-03-05 18:49:39  :    (INFO) Estimated memory for full processing: 31.25MB (avail.: 256 MB), optimal image partitioning: 1 blocks
2019-03-05 18:49:39  :    (INFO) File /tmp/out.tif will be written in 1 blocks of 1000x1000 pixels
Writing /tmp/out.tif...: 100% [**************************************************] (0s)

Note that the output can be redirected to a file with:

import sys
sys.stdout = open('/tmp/log.txt', 'w')

Copyright

The copyright owner is CNES and has signed the ORFEO ToolBox Contributor License Agreement.

---

Check before merging:

• All discussions are resolved
• At least 2 votes from core developers, no vote.
• The feature branch is (reasonably) up-to-date with the base branch
• Dashboard is green
• Copyright owner has signed the ORFEO ToolBox Contributor License Agreement