Mailman 3 [Twisted-Python] Keeping logger from snatching stdout? - Twisted

newer
[Twisted-Python] Weekly Bug Summary

[Twisted-Python] Keeping logger from snatching stdout?

older
[Twisted-Python] Weekly Bug Summary

Jeff Grimmett

30 Aug 2018 30 Aug '18

4:18 a.m.

I'm working on a Flask project using the flask_twisted package from PyPI and have encountered a mystery. I don't *have* to solve it to move on, but darn it, I can't let it go :) https://pypi.org/project/Flask-Twisted/ https://github.com/cravler/flask-twisted/ So here's the breakdown: when use the standard logging module to output to a logfile + stdout, everything is fine. I do see some logging output from Twisted as well (the web server part) but for the most part life is groovy. I'm going to be integrating in a wxPython windows app to this (previously it's been a shell app) and step 1 was to make my own stdout handler that eventually would pipe all that stuff to a window in the wx app. The first step of THAT (step 1.a) was to replace all the logging stuff with print() placeholders. At that point, things got confusing, as now ALL of my print()s are being handled by Twisted's logging handler. I brought flask-twisted in local to my code so I could monkey around with it. First thing I noticed was that it was using twisted.python.log. I messed around with that - commented it out, and now I get no stdout output at all. Set the parameter setStdout to False, same thing. The adapter code uses twisted.internet.reactor, threads, twisted.web.server.Site, twisted.web.wsgi.WSGIResource, and twisted.web.resource.Resource, any one which might be responsible. I spent yesterday evening digging around but haven't found anything yet. Any guidance / ideas? Regards, Jeff

Attachments:

attachment.htm (text/html — 1.9 KB)

Show replies by date

Glyph

5 Sep 5 Sep

12:57 p.m.

On Aug 29, 2018, at 3:48 PM, Jeff Grimmett mailto:grimmtooth@gmail.com> wrote:

...

I'm working on a Flask project using the flask_twisted package from PyPI and have encountered a mystery. I don't *have* to solve it to move on, but darn it, I can't let it go :)

https://pypi.org/project/Flask-Twisted/ https://pypi.org/project/Flask-Twisted/ https://github.com/cravler/flask-twisted/ https://github.com/cravler/flask-twisted/

So here's the breakdown: when use the standard logging module to output to a logfile + stdout, everything is fine. I do see some logging output from Twisted as well (the web server part) but for the most part life is groovy.

I'm going to be integrating in a wxPython windows app to this (previously it's been a shell app) and step 1 was to make my own stdout handler that eventually would pipe all that stuff to a window in the wx app. The first step of THAT (step 1.a) was to replace all the logging stuff with print() placeholders.

Why would you do this rather than simply handle logging events? Both twisted and the stdlib have mechanisms for adding observers that will give you access to more structured information - particularly useful if you are trying to display something in a GUI.

...

At that point, things got confusing, as now ALL of my print()s are being handled by Twisted's logging handler.

This (sort of) makes sense...

...

I brought flask-twisted in local to my code so I could monkey around with it. First thing I noticed was that it was using twisted.python.log. I messed around with that - commented it out, and now I get no stdout output at all. Set the parameter setStdout to False, same thing.

So, this is the old, legacy API, and what you want to use is this: https://twistedmatrix.com/documents/current/api/twisted.logger.LogBeginner.b... https://twistedmatrix.com/documents/current/api/twisted.logger.LogBeginner.b... But it doesn’t make sense to me that you would see no output at all, or that setStdout=False would swallow your print statements.

...

The adapter code uses twisted.internet.reactor, threads, twisted.web.server.Site, twisted.web.wsgi.WSGIResource, and twisted.web.resource.Resource, any one which might be responsible. I spent yesterday evening digging around but haven't found anything yet.

The only thing starting logging here appears to be flask-twisted; we only start logging in twist & twistd, within twisted itself.

...

Any guidance / ideas?

I'm very curious what is going on here, and whether it's a logging system bug. Could you whittle this down to a minimal reproducer? -glyph

Jeff Grimmett

12 Sep 12 Sep

4:03 a.m.

Hi, Glyph, On Wed, Sep 5, 2018 at 3:27 AM Glyph wrote:

...

On Aug 29, 2018, at 3:48 PM, Jeff Grimmett wrote:

Why would you do this rather than simply handle logging events? Both twisted and the stdlib have mechanisms for adding observers that will give you access to more structured information - particularly useful if you are trying to display something in a GUI.

That's a little more blam than this little script really needs, though I appreciate the suggestion.

...

I brought flask-twisted in local to my code so I could monkey around with it. First thing I noticed was that it was using twisted.python.log. I messed around with that - commented it out, and now I get no stdout output at all. Set the parameter setStdout to False, same thing.

So, this is the old, legacy API, and what you want to use is this: https://twistedmatrix.com/documents/current/api/twisted.logger.LogBeginner.b...

Yeah. Also noted when I saw it. Again, seemed to be more effort than I wanted, though if someone were to say "well, that's what you're stuck with if you use that legacy stuff" I'd be off to do the thing.

...

I'm very curious what is going on here, and whether it's a logging system bug. Could you whittle this down to a minimal reproducer?

The sad part is that when I went to put together the minimal reproducer, the problem went away. There is something in my code somewhere that is causing this. I have no idea what it is, yet, but when I put together a minimal web server that uses twisted.reactor.callLater() to periodically start a background task, Twisted is not grabbing stdout or even pushing its own logging to sdtout. I think it might be how I set up the original project in my IDE - for the sample project, I started with a clean directory and clean project file (PyCharm if it matters). So I'm gonna pursue that further. I think that it might be the IDE's environment if you tell it "this is a Flask project". I was seeing weird things from the minimal example as well until I cleared out all the IDE meta files and reinitiated it as a "pure Python" (in PyCharm terms) project. Thanks for your time and thanks for the push that got me moving (hopefully) in the right direction. :) Regards, Jeff

Jeff Grimmett

15 Sep 15 Sep

8:08 p.m.

For the curious, it looks like the culprit is Flask's logging features. I'm not entirely sure what all is happening, but it's clear from docs and code (and a lot of unresolved Stack Overflow threads) that it's hijacking stdout in a way that is confusing to many. Looks like the best approach is to not let it use its defaults for logging (which I was doing initially until I decided to be "clever") - explicitly configure logging so that you can control its behavior explicitly as well. Its internal logging uses the python native logging, so once I get that squared away I can focus on wrangling the Twisted logger as well. Regards, Jeff On Tue, Sep 11, 2018 at 6:33 PM Jeff Grimmett wrote:

...

Hi, Glyph,

On Wed, Sep 5, 2018 at 3:27 AM Glyph wrote:

...
On Aug 29, 2018, at 3:48 PM, Jeff Grimmett wrote:

Why would you do this rather than simply handle logging events? Both twisted and the stdlib have mechanisms for adding observers that will give you access to more structured information - particularly useful if you are trying to display something in a GUI.

That's a little more blam than this little script really needs, though I appreciate the suggestion.

...
I brought flask-twisted in local to my code so I could monkey around with it. First thing I noticed was that it was using twisted.python.log. I messed around with that - commented it out, and now I get no stdout output at all. Set the parameter setStdout to False, same thing.

So, this is the old, legacy API, and what you want to use is this: https://twistedmatrix.com/documents/current/api/twisted.logger.LogBeginner.b...

Yeah. Also noted when I saw it. Again, seemed to be more effort than I wanted, though if someone were to say "well, that's what you're stuck with if you use that legacy stuff" I'd be off to do the thing.

...
I'm very curious what is going on here, and whether it's a logging system bug. Could you whittle this down to a minimal reproducer?

The sad part is that when I went to put together the minimal reproducer, the problem went away.

There is something in my code somewhere that is causing this. I have no idea what it is, yet, but when I put together a minimal web server that uses twisted.reactor.callLater() to periodically start a background task, Twisted is not grabbing stdout or even pushing its own logging to sdtout.

I think it might be how I set up the original project in my IDE - for the sample project, I started with a clean directory and clean project file (PyCharm if it matters). So I'm gonna pursue that further. I think that it might be the IDE's environment if you tell it "this is a Flask project". I was seeing weird things from the minimal example as well until I cleared out all the IDE meta files and reinitiated it as a "pure Python" (in PyCharm terms) project.

Thanks for your time and thanks for the push that got me moving (hopefully) in the right direction. :)

Regards,

Jeff

2043

Age (days ago)

2060

Last active (days ago)

List overview

Download

3 comments

2 participants

participants (2)

Glyph
Jeff Grimmett

[Twisted-Python] Keeping logger from snatching stdout?

Jeff Grimmett

Glyph

Jeff Grimmett

Jeff Grimmett

tags

participants (2)