add logging.basicConfig to avoid errors when testing Python27...KalmanFilter

[mwetter]

This is to test a work-around for https://github.com/lbl-srg/modelica-buildings/issues/1587

The proposed patch is in buildingspy/development/jmodelica_run.template the addition

...
import pymodelica

###############################################################
# PATCH using `logging`
###############################################################
#
# The call to `simulate` function of `pyfmi.load_fmu` instance
# might segfault (erratic behavior) when the instance is
# handled by a child process (using `multiprocessing.Process`)
# or a child thread (using `threading.Thread`).
#     * No segfault has been observed when the instance is
#       handled by the main process as in
#       `docker-ubuntu-jmodelica/jmodelica.py`.
#     * Using `threading.Thread` shows that JModelica
#       simulation actually succeeds and that the segfault
#       happens when exiting the thread.
#       (This is also visible using `multiprocessing.Process`
#       and looking at `cpu_time` in the JSON log file.)
#     * The STDOUT redirection mechanism is not the cause:
#       tests have been done with no redirection.
#     * No proper debugging of the C function calls has been
#       done yet.
#     * When switching to Python 3 it might be worth testing
#       multiprocessing with `set_start_method('spawn')`.
# Inexplicably the segfault is resolved by simply setting
# `logging.basicConfig` as below (whatever the level).
# Looking at the source code of `logging` does not bring any
# explanation...
#
###############################################################

logging.basicConfig(
    level=0,
    format='\n[%(levelname)s] (%(processName)-10s) %(message)s\n',
)

###############################################################
# Capture stdout of a Python function
###############################################################
# From https://stackoverflow.com/questions/24277488/in-python-how-to-capture-the-stdout-from-a-c-shared-library-to-a-variable/29834357

class OutputGrabber(object):
...

[mwetter]

These changes still lead to the same error when run from BuildingsPy. Running

$ jm_ipython.sh Buildings_Utilities_IO_Python27_Examples_KalmanFilter.py

from the console worked in about 100 test runs.

[AntoineGautier]

@mwetter From my last tests: no segfault is observed when simulating with a local installation of JModelica instead of docker (even without the logging.basicConfig patch).

[AntoineGautier]

So it is indeed a segfault of the Python interpreter that seems related to the use of pickle module in Buildings/Resources/Python-Sources/KalmanFilter.py. Using json instead (same API but need to change rb and wb into standard read and write) seems the solve the issue for both JModelica execution with Docker and BuildingsPy. (Nota: no need for logging.basicConfig patch any more.) A side issue I also noticed (and did not solve) is that Modelica.Utilities.Files.removeFile("tmp-kalman.pkl") in Buildings/Utilities/IO/Python27/Examples/KalmanFilter.mo does not seem effective (that temporary file persists).

[AntoineGautier]

For future reference the segfault was tracked with faulthandler from inside the Docker container (origin not explicit from outside the container).

root@4aa0ebfbade1:~/tmp/modelica-buildings# ipython
Python 2.7.15+ (default, Oct  7 2019, 17:39:04)
Type "copyright", "credits" or "license" for more information.

IPython 5.5.0 -- An enhanced Interactive Python.
?         -> Introduction and overview of IPython's features.
%quickref -> Quick reference.
help      -> Python's own help system.
object?   -> Details about 'object', use 'object??' for extra details.

In [1]: import faulthandler

In [2]: faulthandler.enable()

In [3]: %run Buildings_Utilities_IO_Python27_Examples_KalmanFilter.py
Exception in thread Thread-79:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/local/JModelica/Python/pymodelica/compiler_logging.py", line 218, in run
    xml.sax.parse(self.stream, LogErrorParser(self.result))
  File "/usr/lib/python2.7/xml/sax/__init__.py", line 33, in parse
    parser.parse(source)
  File "/usr/lib/python2.7/xml/sax/expatreader.py", line 116, in parse
    self._close_source()
  File "/usr/lib/python2.7/xml/sax/expatreader.py", line 235, in _close_source
    file.close()
AttributeError: KeepLastStream instance has no attribute 'close'

Fatal Python error: Segmentation fault

Thread 0x00007f09f0734700 <python> (most recent call first):
  File "/usr/lib/python2.7/threading.py", line 340 in wait
  File "/usr/lib/python2.7/threading.py", line 614 in wait
  File "/usr/lib/python2.7/dist-packages/IPython/core/history.py", line 835 in run
  File "/usr/lib/python2.7/dist-packages/IPython/core/history.py", line 60 in needs_sqlite
  File "<decorator-gen-24>", line 2 in run
  File "/usr/lib/python2.7/threading.py", line 801 in __bootstrap_inner
  File "/usr/lib/python2.7/threading.py", line 774 in __bootstrap

Current thread 0x00007f09f4917740 <python> (most recent call first):
  File "/usr/lib/python2.7/pickle.py", line 1037 in load_dict
  File "/usr/lib/python2.7/pickle.py", line 864 in load
  File "/usr/lib/python2.7/pickle.py", line 1384 in load
  File "/home/developer/tmp/modelica-buildings/Buildings/Resources/Python-Sources/KalmanFilter.py", line 35 in filter
  File "/usr/local/JModelica/Python/pyfmi/simulation/assimulo_interface.py", line 869 in handle_event

[mwetter]

@AntoineGautier : Nice find... Can you please update KalmanFilter.py to use json instead of pickle.

[AntoineGautier]

@mwetter Sure, will do. Should we fix the bug with Modelica.Utilities.Files.removeFile("tmp-kalman.pkl") at the same time? Any idea where it might come from? EDIT That is a strange bug: Modelica.Utilities.Files.exist returns true before and false after the call to removeFile despite the file still being in the file system.