When using native Python logging, a Kivy app will go into an infinite loop on exit #825

Closed
supercheetah opened this Issue Nov 28, 2012 · 9 comments

Comments

Projects
None yet
8 participants
Contributor

supercheetah commented Nov 28, 2012

When an application is using the native Python logging, upon closing, it will fail to exit, and seems to get stuck in an infinite loop somewhere, and it only happens when a logging function call is being made. Simply importing the logging module won't trigger this bug.

Here's some sample code that demonstrates the problem: https://gist.github.com/4157249

Here's a bit of a sample of some of the warnings that come out of it (and it gets repeated a lot):

WARNING:kivy:stderr: WARNING:kivy:stderr: WARNING:kivy:stderr: Traceback (most recent call last):

After doing a bit of debugging with IPython, it seems the best place to start with this is in kivy/base.py:452. It looked like the problem is with one of the handlers. At some point within the Python code base while trying to debug it, it seems to blow up on the data object given to it by Kivy with just the above being repeated over and over again without ever getting back to the debugger. I'd have to go back into it again to figure out where that is, but that is as much as I could figure out about it.

The only way to exit the application is with a kill or ^C.

I encountered the same problem in a slight variant, trying to log warning messages.
The symptoms were worse, as the infinite loop arose as soon as a warning was to be logged, which would crash the program eventually.
I did not have time to investigate it and assumed I might have missed something in Kivy's documentation, so I just disabled native logging to avoid the issue.

Thanks supercheetah to raise this bug properly !

Contributor

supercheetah commented Dec 9, 2012

I think I've figured out where the infinite loop begins on this issue. I seemed to have tracked it down to logging/init.py:1269 in the function handle(). It goes into logging/init.py:1316 callHandlers() and seems to loop on three objects specifically:

[<kivy.logger.LoggerHistory object at 0x3304750>,
 <kivy.logger.FileHandler object at 0x333af50>,
 <kivy.logger.ConsoleHandler object at 0x3349050>]

The above error message gets printed from kivy.logger.ConsoleHandler.filter(). That's about as much as I've figured out for now.

Contributor

aspidites commented Dec 20, 2012

Use Kivy's Logger instead:

from kivy.logger import Logger
...
Logger.info('log stuff')
...

I'm guessing this has something to do with the fact that kivy is trying to implement logging facilities as a singleton, overriding the batteries-included version, thus causing issues.

Owner

tshirtman commented Dec 20, 2012

Sure, this is ok when you are doing a kivy app, but what if you are using
third party libs, and they do use python logger? we need them to be
compatible.
Le 20 déc. 2012 19:56, "Edwin Marshall" notifications@github.com a écrit :

Use Kivy's Logger instead:

from kivy.logger import Logger...Logger.info('log stuff')...

I'm guessing this has something to do with the fact that kivy is trying to
implement logging facilities as a singleton, overriding the
batteries-included version, thus causing issues.


Reply to this email directly or view it on GitHubhttps://github.com/kivy/kivy/issues/825#issuecomment-11585915.

tykonot commented Jan 21, 2013

This code produces the same inifinite log message:

class SeqApp(App):
    def build(self):
        try:
            raise Exception('test')
        except Exception, e:
            logging.exception(e)
        return Button()
SeqApp().run()

also replacing 'logging.exception(e)' with 'kivy.logging.Logger.exception(e)' gives:

     Logger.exception(e)
   File "/usr/lib/python2.7/logging/__init__.py", line 1181, in exception
     self.error(msg, *args, **kwargs)
   File "/usr/lib/python2.7/logging/__init__.py", line 1174, in error
     self._log(ERROR, msg, args, **kwargs)
   File "/usr/lib/python2.7/logging/__init__.py", line 1267, in _log
     self.handle(record)
   File "/usr/lib/python2.7/logging/__init__.py", line 1277, in handle
     self.callHandlers(record)
   File "/usr/lib/python2.7/logging/__init__.py", line 1317, in callHandlers
     hdlr.handle(record)
   File "/usr/lib/python2.7/logging/__init__.py", line 748, in handle
     self.emit(record)
   File "/usr/local/lib/python2.7/dist-packages/Kivy-1.5.1-py2.7-linux-x86_64.egg/kivy/logger.py", line 201, in emit
     self._write_message(message)
   File "/usr/local/lib/python2.7/dist-packages/Kivy-1.5.1-py2.7-linux-x86_64.egg/kivy/logger.py", line 179, in _write_message
     FileHandler.fd.write(record.msg)
 TypeError: expected a character buffer object
Contributor

matham commented Mar 11, 2013

The problem with using the Kivy logger is that I have modules written independently from Kivy which call logging and cause this problem.

I solved it temporarily with:

import logging
from kivy.logger import Logger
logging.root= Logger
Owner

tshirtman commented Mar 13, 2013

This is a nice workaround, i wonder if there are downsides to doing that in kivy.logger directly?

I think I might also be running into this issue, but it's being caused by an error originating in the OSC API...

[ERROR             ] [OSC         ] Error in Tuio recv()
 Exception in thread Thread-3:
 Traceback (most recent call last):
   File "C:\APPS\Cubit\Kivy\Python\lib\threading.py", line 551, in __bootstrap_inner
     self.run()
   File "C:\APPS\Cubit\Kivy\kivy\kivy\lib\osc\oscAPI.py", line 229, in run
     Logger.exception(e)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1172, in exception
     self.error(msg, exc_info=1, *args)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1166, in error
     self._log(ERROR, msg, args, **kwargs)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1258, in _log
     self.handle(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1268, in handle
     self.callHandlers(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1308, in callHandlers
     hdlr.handle(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 748, in handle
     self.emit(record)
   File "C:\APPS\Cubit\Kivy\kivy\kivy\logger.py", line 201, in emit
     self._write_message(message)
   File "C:\APPS\Cubit\Kivy\kivy\kivy\logger.py", line 179, in _write_message
     FileHandler.fd.write(record.msg)
 TypeError: expected a character buffer object

[ERROR             ] [OSC         ] Error in Tuio recv()
 Exception in thread Thread-1:
 Traceback (most recent call last):
   File "C:\APPS\Cubit\Kivy\Python\lib\threading.py", line 551, in __bootstrap_inner
     self.run()
   File "C:\APPS\Cubit\Kivy\kivy\kivy\lib\osc\oscAPI.py", line 229, in run
     Logger.exception(e)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1172, in exception
     self.error(msg, exc_info=1, *args)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1166, in error
     self._log(ERROR, msg, args, **kwargs)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1258, in _log
     self.handle(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1268, in handle
     self.callHandlers(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1308, in callHandlers
     hdlr.handle(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 748, in handle
     self.emit(record)
   File "C:\APPS\Cubit\Kivy\kivy\kivy\logger.py", line 201, in emit
     self._write_message(message)
   File "C:\APPS\Cubit\Kivy\kivy\kivy\logger.py", line 179, in _write_message
     FileHandler.fd.write(record.msg)
 TypeError: expected a character buffer object

[ERROR             ] [OSC         ] Error in Tuio recv()
 Exception in thread Thread-2:
 Traceback (most recent call last):
   File "C:\APPS\Cubit\Kivy\Python\lib\threading.py", line 551, in __bootstrap_inner
     self.run()
   File "C:\APPS\Cubit\Kivy\kivy\kivy\lib\osc\oscAPI.py", line 229, in run
     Logger.exception(e)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1172, in exception
     self.error(msg, exc_info=1, *args)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1166, in error
     self._log(ERROR, msg, args, **kwargs)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1258, in _log
     self.handle(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1268, in handle
     self.callHandlers(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 1308, in callHandlers
     hdlr.handle(record)
   File "C:\APPS\Cubit\Kivy\Python\lib\logging\__init__.py", line 748, in handle
     self.emit(record)
   File "C:\APPS\Cubit\Kivy\kivy\kivy\logger.py", line 201, in emit
     self._write_message(message)
   File "C:\APPS\Cubit\Kivy\kivy\kivy\logger.py", line 179, in _write_message
     FileHandler.fd.write(record.msg)
 TypeError: expected a character buffer object

Note that it's the same error reproduced 3 times, for 3 different threads...

Barring a proper fix sometime soon, I will try the suggesting by matham.

Owner

tito commented Jun 17, 2013

Ok, the logging.exception() expect a string, not an Exception object.
So we get the issue in oscAPI.py, but the code posted by @tykonot is wrong too :)

tito closed this in b392d6a Jun 17, 2013

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment