[Twisted-Python] How do I debug this network problem?

[Peter Westlake]

On Thu, 13 Nov 2014, at 17:01, Peter Westlake wrote:
>
>>> I've put in the dataReceived, and the answer box does*not*make it
>>> into the Protocol. There are two entries in
>>> protocol._outstandingRequests: {'2189': <Deferred...>, '2188':
>>> <Deferred...>} and the log output shows 2186, 2187, 218a, 218b, ...
>>
>> So, wait a second.
>>
>> You said you're looking at tcpdump, and it's showing you that your
>> outstanding requests - in this case, 2188 and 2189 - are in fact
>> being answered. But then you say you're looking at the dump from
>> dataReceived, and seeing that not only are 2188 and 2189 not being
>> answered from that layer, but 218a and 218b *are* being answered?
>>
>> Simply put: that should be impossible. TCP is an ordered stream. If
>> you received answers to 2188 and 2189 on the wire in tcpdump, you
>> should see those come back to dataReceived first. What kind of
>> transport is this hooked up to? A regular socket? Is there TLS
>> involved? Did you run tcpdump for that same session?
>
> No TLS, just TCP, created with
> twisted.application.internet.TCPClient(host, port, protocolfactory).
>
> I didn't record this session with tcpdump, but from a previous one I
> can say that yes, some Deferreds are left hanging around waiting for a
> response while subsequent ones have already received one. There was no
> interruption or irregularity in the TCP stream.
>
> tcpdump: 2186, 2187, 2188, 2189, 218a, 218b
>
> dataReceived: 2186, 2187, 218a, 218b
>
> _outstandingRequests: {2188, 2189}

Here is some highly suspicious-looking output from strace:

sendto(5, "\0\4_ask\0\004867c\0\10_command\0\tLogOutpu"..., 343, 0,
NULL, 0) = 343 recvfrom(5,
"\0\7_answer\0\004867c\0\6status\0\4True\0\0", 65536, 0, NULL, NULL) =
31 sendto(5, "\0\4_ask\0\004867d\0\10_command\0\tLogOutpu"..., 183, 0,
NULL, 0) = 183 sendto(5, "\0\4_ask\0\004867e\0\10_command\0\4Ping\0\0",
30, 0, NULL, 0) = 30 recvfrom(5, 0x7fec3005c6d4, 65536, 0, 0, 0) = -1
EAGAIN (Resource temporarily unavailable) sendto(5,
"\0\4_ask\0\004867f\0\10_command\0\4Ping\0\0", 30, 0, NULL, 0) = 30
recvfrom(5, "\0\7_answer\0\004867f\0\3ack\0\4True\0\0", 65536, 0, NULL,
NULL) = 28

Requests 867d and 867e never receive their callbacks.

I see that twisted.internet.tcp.Connection.doRead() does check for
EWOULDBLOCK (=EAGAIN), and returns None. Shouldn't it try to read again?

Peter.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: </pipermail/twisted-python/attachments/20141114/1e2997e3/attachment-0002.html>