Re: co problem status report

On Thu, Oct 25, 2001 at 03:16:46PM +0100, Joe Orton wrote:
> On Thu, Oct 25, 2001 at 03:58:10PM +0200, Daniel Stenberg wrote:
> > To see an entire neon dump for a failure, get this:
> > http://storebror.haxx.se/~daniel/svn/neon-dump.bz2 (373KB) or get the last
> > 200 lines of that logfile here:
> > http://storebror.haxx.se/~daniel/svn/neon-dump-200
>
> Thanks! Well; this shows that it is a persistent connection handling
> problem, at least. I'd thought that persistent connections were still
> turned off, looks like this they aren't for the second session. Putting
>
> ne_sess_persist(sess2, 0);
>
> after the other ne_set_persist call in session.c should work around
> this.

Joe... did you look at that ethereal dump? As far as I can tell, this is a
*client* problem. It has nothing to do with server persistence, or problems
on the server. I fixed the server persistence problems a while ago.

My initial investigation last night was flawed. I saw something that was
weird, but that was just fallout from earlier in the trace.

The root of the problem is some kind of packet loss. At t=1.73, the client
sent a SYN to the server. This packet was lost, the server did not respond,
so at t=4.72, the client sent it again. This time, the server responded at
t=4.87. The client ACK'd the response, but that got lost and the server
resent the SYN response at t=4.90.

Next up, the client sends a request at t=4.879. The server does not respond
to this, so the client resends at t=24.38. It sends again at t=63.4.

Now... those requests are occurring over a different session than the one
used for GET (a bug, but not the cause here).

*While* that resend is occuring, the Apache server times out the GET session
at t=16.68 (15 seconds after the prior activity on that session). This is
*normal* behavior, and is to be expected.

Here is where things get interesting. The server closes the connection at
t=16.68. The client ACKs that at t=16.72 (I'm not sure whether the server
gets that packet or not, but I think it is irrelevant). Next, the client
tries to send a GET request at t=84.83. I believe this generates an error on
the client, so Neon closes its side of the connection at t=84.83 (the FIN,
ACK packet). However, the bug is this: Neon *resends* the request on the
same socket that it just tried to shut down. This ocurs at t=85.29. The
server gets that packet, know the TCP connection is closed, so it sends an
RST packet at t=85.47.

It is that RST packet that causes Neon to throw up the "server closed
connection" error message.

At this point, I would recommendation re-enabling persistent connections and
debugging the Neon problem.

And to those with packet loss occurring: you can see the delays during
checkout were caused by that loss rather than client/server problems. The
final error is definitely a client problem, though :-)

Cheers,
-g

-- 
Greg Stein, http://www.lyra.org/
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@subversion.tigris.org
For additional commands, e-mail: dev-help@subversion.tigris.org