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)
