[Twisted-Python] Twisted.logger on windows max recursion depth exceeded
John Aherne
johnaherne at rocs.co.uk
Sat Jan 6 05:38:40 MST 2018
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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: </pipermail/twisted-python/attachments/20180106/7c03e034/attachment-0001.html>
More information about the Twisted-Python
mailing list