initLogging with log_stdout causes infinite loop

[markmac99]

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]

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]

yea just found the same. :(

[Cybis320]

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

[Cybis320]

Hi Mark, PR #504 was merged into prerelease. I never observed any propagation in practice with the new log. If you could test and let me know if you're still seeing propagation issues. Thank you.

[markmac99]

I#ll try to find an opportunity to test, sorry i have not done so already.