[Twisted-Python] Twisted.logger on windows max recursion depth exceeded
I've started to look at Python3 and klein I am using python3.6.3 32bit and twisted 17.9.0 on windows10 klein is downloaded from pypi. I got to the point of needing to do some logging and thought I now should use the new logger system. Below I have posted the python code I am using and the traceback for when it crashes. The last part is the log output for when the program works as expected. *First Setup* With the first setup all seems to work as expected. I can log to stdio and to a FileLogObserver without error. This works with or without the print statements enabled in the event formatter (jahlog) *Second Setup* The second setup causes python to crash with the print statements enabled in the event formatter. With the for loop print enabled the system will crash. With just printing the keys from the event dict it will produce the recursion depth error but won't crash python. If I comment out the print statements all seems to work correctly. I assume I am doing something wrong or something I should not be trying to do. But I can't work out what causes the 2 setups to behave so differently. The traceback I have posted below shows the result when using the for loop to print out the items in the event dict. As you can see there are a whole lot of empty items it iterates over. The last section below shows the log output when all is working as expected. Here we see the expected result from iterating the event dict. About 8 items to print. The question is What am I doing wrong if at all. Or why is there such a difference between the 2 setups. Any pointers gratefully accepted. import os import sys import traceback from klein import Klein from twisted.web import static #from twisted.internet import reactor from twisted.web.resource import NoResource from twisted.internet.defer import succeed #from twisted.python import log from twisted.logger import Logger, formatEvent, formatTime from twisted.logger import FileLogObserver, globalLogPublisher, globalLogBeginner from twisted.python.logfile import DailyLogFile from pprint import pprint def jahlog(event): #print('EVENT DIR', event.keys()) for item in event: print('ITEM', event[item]) my_tb = '' eventText = 'NONE' if 'log_failure' in event: print('TRACEBACVK22 failure', event['log_failure']) my_tb = event['log_failure'] event['log_format'] = str(event['log_format']) eventText = formatEvent(event) time = formatTime(event["log_time"]) my_space = event["log_namespace"] my_level = event["log_level"] my_logger = event["log_logger"] if 'log_logger' in event else 'JAHlog' system_log = event["log_system"] if 'log_system' in event else '-' eventString = "{[time]} {[namespace]} {[loglevel]} {[my_logger]} {[system_log]} {[text]}\r\n {[my_tb]}".format(dict(time=time), dict(namespace=my_space), dict(loglevel=my_level), dict(my_logger=my_logger), dict(system_log=system_log), dict(text=eventText), dict(my_tb=my_tb) ) return eventString log = Logger(namespace="jah_test5") globalLogPublisher.addObserver(FileLogObserver(DailyLogFile.fromFullPath('c:\\logs\\my_log9.log'), jahlog)) #Replace the above 2 lines with the following 2 lines and all is well #f = FileLogObserver(DailyLogFile.fromFullPath('c:\\logs\\my_log6.log'), jahlog) #log = Logger(observer=f, namespace="klein_test") app = Klein() @app.route('/') def jah(request): logdata = 'some log data' print('DO JAH', logdata) log.debug('DO JAH LOGGGGG {data!r}\r\n', data=logdata) return b"GOT RESULT" #my_html app.run('localhost', 9000) Do run with following logger log = Logger(namespace="jah_test5") globalLogPublisher.addObserver(FileLogObserver(DailyLogFile.fromFullPath('c:\\logs\\my_log9.log'), jahlog)) Total Inability To Support Usual Programming PS C:\jahtest> ./klein_static_test5.py 2018-01-06 11:48:37+0000 [-] ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM ITEM - 2018-01-06 11:48:37+0000 [-] Temporarily disabling observer <twisted.logger._file.FileLogObserver object at 0x00000287D6E597B8> due to exception: [Failure instance: Traceback: <class 'RecursionError'>: maximum recursion depth exceeded C:\Program Files\Python36\lib\site-packages\twisted\logger\_file.py:50:__call__ C:\jahtest\klein_static_test5.py:18:jahlog C:\Program Files\Python36\lib\site-packages\twisted\logger\_io.py:170:write C:\Program Files\Python36\lib\site-packages\twisted\logger\_logger.py:135:emit --- <exception caught here> --- C:\Program Files\Python36\lib\site-packages\twisted\logger\_observer.py:131:__call__ C:\Program Files\Python36\lib\site-packages\twisted\logger\_file.py:50:__call__ C:\jahtest\klein_static_test5.py:18:jahlog C:\Program Files\Python36\lib\site-packages\twisted\logger\_io.py:170:write C:\Program Files\Python36\lib\site-packages\twisted\logger\_logger.py:117:emit C:\Program Files\Python36\lib\site-packages\constantly\_constants.py:273:iterconstants ] Traceback (most recent call last): File "C:\Program Files\Python36\lib\site-packages\twisted\logger\_file.py", line 50, in __call__ text = self.formatEvent(event) File "C:\jahtest\klein_static_test5.py", line 18, in jahlog print('ITEM', event[item]) File "C:\Program Files\Python36\lib\site-packages\twisted\logger\_io.py", line 170, in write self.log.emit(self.level, format=u"{log_io}", log_io=line) File "C:\Program Files\Python36\lib\site-packages\twisted\logger\_logger.py", line 135, in emit self.observer(event) --- <exception caught here> --- File "C:\Program Files\Python36\lib\site-packages\twisted\logger\_observer.py", line 131, in __call__ observer(event) File "C:\Program Files\Python36\lib\site-packages\twisted\logger\_file.py", line 50, in __call__ text = self.formatEvent(event) File "C:\jahtest\klein_static_test5.py", line 18, in jahlog print('ITEM', event[item]) File "C:\Program Files\Python36\lib\site-packages\twisted\logger\_io.py", line 170, in write self.log.emit(self.level, format=u"{log_io}", log_io=line) File "C:\Program Files\Python36\lib\site-packages\twisted\logger\_logger.py", line 117, in emit if level not in LogLevel.iterconstants(): File "C:\Program Files\Python36\lib\site-packages\constantly\_constants.py", line 273, in iterconstants sorted(constants, key=lambda descriptor: descriptor._index)) builtins.RecursionError: maximum recursion depth exceeded Fatal Python error: Cannot recover from stack overflow. Do run with following logger f = FileLogObserver(DailyLogFile.fromFullPath('c:\\logs\\my_log6.log'), jahlog) log = Logger(observer=f, namespace="klein_test") PS C:\jahtest> ^C PS C:\jahtest> ^C PS C:\jahtest> ./klein_static_test5.py 2018-01-06 11:54:29+0000 [-] Log opened. 2018-01-06 11:54:29+0000 [-] Site starting on 9000 2018-01-06 11:54:29+0000 [-] Starting factory <twisted.web.server.Site object at 0x000001A886F11588> 2018-01-06 11:54:40+0000 [-] DO JAH some log data 2018-01-06 11:54:40+0000 [-] ITEM some log data 2018-01-06 11:54:40+0000 [-] ITEM <Logger 'klein_test'> 2018-01-06 11:54:40+0000 [-] ITEM <LogLevel=debug> 2018-01-06 11:54:40+0000 [-] ITEM klein_test 2018-01-06 11:54:40+0000 [-] ITEM None 2018-01-06 11:54:40+0000 [-] ITEM DO JAH LOGGGGG {data!r} 2018-01-06 11:54:40+0000 [-] 2018-01-06 11:54:40+0000 [-] ITEM 1515239680.6134038 2018-01-06 11:54:40+0000 [-] "127.0.0.1" - - [06/Jan/2018:11:54:40 +0000] "GET / HTTP/1.1" 200 10 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36" 2018-01-06 11:54:46+0000 [-] DO JAH some log data 2018-01-06 11:54:46+0000 [-] ITEM some log data 2018-01-06 11:54:46+0000 [-] ITEM <Logger 'klein_test'> 2018-01-06 11:54:46+0000 [-] ITEM <LogLevel=debug> 2018-01-06 11:54:46+0000 [-] ITEM klein_test 2018-01-06 11:54:46+0000 [-] ITEM None 2018-01-06 11:54:46+0000 [-] ITEM DO JAH LOGGGGG {data!r} 2018-01-06 11:54:46+0000 [-] 2018-01-06 11:54:46+0000 [-] ITEM 1515239686.295032 2018-01-06 11:54:46+0000 [-] "127.0.0.1" - - [06/Jan/2018:11:54:45 +0000] "GET / HTTP/1.1" 200 10 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36" -- *John Aherne* *www.rocs.co.uk <http://www.rocs.co.uk>* 020 7223 7567
Hi John, Lots of interest in logging this week for some reason :-).
The issue here is that klein.run() is initializing the (old-style) logging system; that initialization, among other things, includes replacing sys.stdout and sys.stderr with files that will emit log messages rather than write directly. `print` debugging of log observers is therefore always somewhat risky since many ways of initializing the logging system will do this. Perhaps the logging system should be a bit more defensive about observers emitting messages; however, for the time being, if you want to do `print` debugging of a log observer, at the top of your file do something like from sys import stderr as DEBUG and then everywhere you have a call to the 'print' function, use the 'file' kwarg: print('ITEM', event[item], file=DEBUG) I hope this is helpful, -g
Lots of interest in logging this week for some reason :-). Yes. Must be the weather :-). But very helpful from my point of view as I've just started to look at it. Well I guessed that printing inside the observer was not a good idea. But I could not see why this one showed the problem log = Logger(namespace="jah_test5") globalLogPublisher.addObserver(FileLogObserver( DailyLogFile.fromFullPath('c:\\logs\\my_log9.log'), jahlog)) But this one did not f = FileLogObserver(DailyLogFile.fromFullPath('c:\\logs\\my_log6.log'), jahlog) log = Logger(observer=f, namespace="klein_test") I was assuming they would both add an observer to globalLogObserver at some point. And if klein was the culprit it would have the same problem with both. Anyway I only needed the print statements while I checked out what was turning up in the event. Thanks. John On Sun, Jan 7, 2018 at 7:27 AM, Glyph <glyph@twistedmatrix.com> wrote:
-- *John Aherne* *www.rocs.co.uk <http://www.rocs.co.uk>* 020 7223 7567
Hi John, Lots of interest in logging this week for some reason :-).
The issue here is that klein.run() is initializing the (old-style) logging system; that initialization, among other things, includes replacing sys.stdout and sys.stderr with files that will emit log messages rather than write directly. `print` debugging of log observers is therefore always somewhat risky since many ways of initializing the logging system will do this. Perhaps the logging system should be a bit more defensive about observers emitting messages; however, for the time being, if you want to do `print` debugging of a log observer, at the top of your file do something like from sys import stderr as DEBUG and then everywhere you have a call to the 'print' function, use the 'file' kwarg: print('ITEM', event[item], file=DEBUG) I hope this is helpful, -g
Lots of interest in logging this week for some reason :-). Yes. Must be the weather :-). But very helpful from my point of view as I've just started to look at it. Well I guessed that printing inside the observer was not a good idea. But I could not see why this one showed the problem log = Logger(namespace="jah_test5") globalLogPublisher.addObserver(FileLogObserver( DailyLogFile.fromFullPath('c:\\logs\\my_log9.log'), jahlog)) But this one did not f = FileLogObserver(DailyLogFile.fromFullPath('c:\\logs\\my_log6.log'), jahlog) log = Logger(observer=f, namespace="klein_test") I was assuming they would both add an observer to globalLogObserver at some point. And if klein was the culprit it would have the same problem with both. Anyway I only needed the print statements while I checked out what was turning up in the event. Thanks. John On Sun, Jan 7, 2018 at 7:27 AM, Glyph <glyph@twistedmatrix.com> wrote:
-- *John Aherne* *www.rocs.co.uk <http://www.rocs.co.uk>* 020 7223 7567
participants (2)
-
Glyph -
John Aherne