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

[Peter Westlake]

On Fri, 14 Nov 2014, at 20:36, exarkun at twistedmatrix.com wrote:
> On 05:38 pm, peter.westlake at pobox.com wrote:
> >
> >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.
>
> But in this trace, it looks like those two calls also never received
> a response from the server - so it's correct that the callbacks
> never fire.
>
> Keep in mind this is a totally valid AMP interaction. The reason
> these things have unique identifiers is so responses can arrive out
> of order.
>
> Earlier you mentioned you saw tcpdump reporting that the response data
> corresponding to the unfired Deferreds was arriving. Can you double
> check that? From this `strace` output I would guess that it isn't. The
> alternative explanation is a terrible, data-losing bug in the kernel's
> TCP stack...

It really does arrive. Here's the relevant bit of tcpdump output for
867d, hostnames redacted:

16:19:33.542428 IP wheezy-1.example.com.43517 >
xenbuilder.example.com.8091: Flags [P.], seq 6156084:6156267, ack
807019, win 296, options [nop,nop,TS val 62810704 ecr 696524361],
length 183
E...b. at .@... . ..........7.....(/...... ..jP)..I.._ask..867d.._command.
  LogOutput..action..xe-clean..branch..test-secure-build..data..16:19:33
  00:00:00 E: + dry=
  ..job..core..number..89613..product..carbon..site..cam..stream..out..

16:19:33.542935 IP xenbuilder.example.com.8091 >
wheezy-1.example.com.43517: Flags [P.], seq 807019:807050, ack 6156267,
win 816, options [nop,nop,TS val 696524413 ecr 62810704], length 31
F..S.P at .@.U. . ......7.........0Zm.....
  )..}..jP.._answer..867d..status..True.. 16:19:33.542986 IP
  wheezy-1.example.com.43517 > xenbuilder.example.com.8091: Flags [.],
  ack 807050, win 296, options [nop,nop,TS val 62810705 ecr 696524413],
  length 0 (etc)

Peter.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: </pipermail/twisted-python/attachments/20141115/dc49a4e9/attachment-0002.html>