Hi, I commited my second patch to log subprocess events in debug mode, changeset 9e8b2fcd1144: --- Tulip issue #184: Log subprocess events in debug mode
- Log stdin, stdout and stderr transports and protocols - Log process identifier (pid) - Log connection of pipes - Log process exit - Log Process.communicate() tasks: feed stdin, read stdout and stderr - Add __repr__() method to many classes related to subprocesses --- I developed this changeset to investigate this issue: http://bugs.python.org/issue21645 Victor 2014-07-13 0:35 GMT+02:00 Guido van Rossum <[email protected]>: > This is awesome! At various times I've hacked the asyncio source code to > insert print statements to debug a nasty problem. This is so much better!! > > > On Fri, Jul 11, 2014 at 6:45 PM, Victor Stinner <[email protected]> > wrote: >> >> Hi, >> >> I commited a change to log most important socket events. I added these >> logs because it is hard to develop an asynchronous application. When >> the application is blocked, it's hard to guess if it's a bug in your >> code or just because the network is slow or even blocked. >> >> To enable these logs, you need to: >> >> - set PYTHONASYNCIODEBUG environment variable to 1 (or call >> set_debug(True) on your event loop) >> - *and* configure the asyncio logger to show messages at level DEBUG. >> I'm using logging.basicConfig(level=logging.DEBUG) >> >> I chose to only log when the event loop is in debug mode, because I >> expect that you will get a *lot* of logs and it's difficult to >> configure the logging module to only display DEBUG logs of your code >> but not DEBUG logs of asyncio. Some debug logs might also make the >> program slower. >> >> Logged socket events: >> >> - Log most important socket events: socket connected, new client, >> connection >> reset or closed by peer (EOF), etc. >> - Log time elapsed in DNS resolution (getaddrinfo) >> - Log pause/resume reading >> - Log time of SSL handshake >> - Log SSL handshake errors >> >> Debug logs of examples/fetch0.py: >> --- >> DEBUG:asyncio:Using selector: EpollSelector >> DEBUG:asyncio:Get addresss info python.org:80, >> type=<SocketType.SOCK_STREAM: 1> >> DEBUG:asyncio:Getting addresss info python.org:80, >> type=<SocketType.SOCK_STREAM: 1> took 60.895 ms: >> [(<AddressFamily.AF_INET: 2>, <SocketType.SOCK_STREAM: 1>, 6, '', >> ('140.211.10.69', 80))] >> DEBUG:asyncio:poll took 48.240 ms: 1 events >> DEBUG:asyncio:connect <socket.socket fd=7, >> family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('0.0.0.0', >> 0)> to ('140.211.10.69', 80) >> DEBUG:asyncio:poll took 291.254 ms: 1 events >> DEBUG:asyncio:connected to python.org:80: (<_SelectorSocketTransport >> fd=7 read=polling write=<idle, bufsize=0>>, >> <asyncio.streams.StreamReaderProtocol object at 0x7fafa9ec2bb8>) >> ... >> DEBUG:asyncio:poll took 200.113 ms: 1 events >> ... >> DEBUG:asyncio:<_SelectorSocketTransport fd=7 read=polling write=<idle, >> bufsize=0>> received EOF >> DEBUG:asyncio:Close <_UnixSelectorEventLoop running=False closed=False >> debug=True> >> --- >> >> I'm also working on a patch to log subprocess events: >> https://code.google.com/p/tulip/issues/detail?id=184 >> >> Victor > > > > > -- > --Guido van Rossum (python.org/~guido)
