search

CroatianMeteorNetwork / RMS

RPi Meteor Station
https://globalmeteornetwork.org/
GNU General Public License v3.0
181 stars 50 forks source link

initLogging with log_stdout causes infinite loop #468

Open markmac99 opened 1 day ago

markmac99 commented 1 day ago

There's a relatively new config parameter log_stdout. When this is set, the RMS initLogging() function redirects all standard output to the logger. So far so good. However, the logger is also configured to send to stdout. So the logger is sending to stdout but also monitoring it. There's therefore a risk that it will read its own messges, re-echo them to stdout, re-read them and so on infinitely. Example shown below from UK003X.

Within RMS this is generally masked by the order in which logging and stdout redirection is set up. However, if initLogging is called a second time, for example by a child process such as an external script or by another RMS script, then infinite recursion is triggered. It can also be demonstrated with a simple python script (shown below).

I'm not sure yet how to fix this, but in the meantime i think the config parameter needs to be heavily commented to explain the risk.

from time import sleep
from RMS.Logger import initLogging
import RMS.ConfigReader as cr

config = cr.loadConfigFromDirectory('.config', 'e:/dev/meteorhunting/rms/')
config.data_dir = 'c:/temp'
config.log_stdout = True
initLogging(config)
sleep(10)
initLogging(config)
2024/11/15 07:11:38-INFO-Logger-line:155 - GStreamer logging successfully initialized
2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:155 - GStreamer logging successfully initialized
2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:155 - GStreamer logging successfully initialized
2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:155 - GStreamer logging successfully initialized
2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:44 - 2024/11/15 07:11:38-INFO-Logger-line:155 - GStreamer logging successfully initialized
Cybis320 commented 23 hours ago

Hi Mark. Indeed, I ran into this issue when working on prerelease and added this line in BufferedCapture.py in prerelease: https://github.com/CroatianMeteorNetwork/RMS/blob/1b37a7e3f6b1c3249619298d1603df60bd55dbdc/RMS/BufferedCapture.py#L46-L49

However, I now think I should have put that line in the Logger.py instead. Any chance you could test your script with that line added at line 23 in Logger.py? Edit: that won't work in Logger... might have to add each to each script starting a log...

markmac99 commented 21 hours ago

yea just found the same. :(

Cybis320 commented 21 hours ago

With PR#468, no change? How about with the current prerelease?