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
