[Tcl-bugs] [ tcl-Bugs-2446662 ] chanIO.test failures on Win32 msys/mingw

[SourceForge.net <no...@so...>]

Bugs item #2446662, was opened at 2008-12-18 19:41
Message generated for change (Comment added) made by davygrvy
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=110894&aid=2446662&group_id=10894

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: 25. Channel System
Group: current: 8.6b1
Status: Open
Resolution: None
Priority: 8
Private: No
Submitted By: Kevin B KENNY (kennykb)
Assigned to: Alexandre Ferrieux (ferrieux)
Summary: chanIO.test failures on Win32 msys/mingw

Initial Comment:
On the msys/mingw build on Windows, 'make test' gives:



==== chan-io-28.7 Tcl_CloseEx (half-close) socket FAILED
==== Contents of test case:

    set echo [makeFile {
        proc accept {s args} {set ::sok $s}
        set s [socket -server accept 0]
        puts [lindex [fconfigure $s -sockname] 2]
        flush stdout
        vwait ::sok
        fconfigure $::sok -buffering line
        while {[gets $::sok line]>=0} {puts $::sok $line}
        puts $::sok DONE
        exit 0
    } echo.tcl]
    set ::ff [open "|[list [interpreter] $echo]" r]
    gets $::ff port
    set ::s [socket 127.0.0.1 $port]
    puts $::s Hey
    close $::s w
    set timer [after 1000 {set ::done Failed}]
    set ::acc {}
    fileevent $::s readable {
        if {[gets $::s line]<0} {
            set ::done Succeeded
        } else {
            lappend ::acc $line
        }
    }
    vwait ::done
    after cancel $timer
    close $::s r
    close $::ff
    list $::done $::acc

---- Result was:
Succeeded {}
---- Result should have been (exact matching):
Succeeded {Hey DONE}
==== chan-io-28.7 FAILED




----------------------------------------------------------------------

>Comment By: David Gravereaux (davygrvy)
Date: 2009-01-05 11:03

Message:
a new fconfigure called -ignorereset?

----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2009-01-05 10:38

Message:
Now this is getting interesting.  A reset is an error.  It shows an
inappropriate closure that might have data loss.  Is it correct that it is
hidden?

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-05 08:04

Message:
Andreas, when you're back, do you know why he said that "the higher level
of the IO mechanism" would be upset by seeing an EOF instead of an
ECONNRESET ?
Do you see an objection to re-establishing symmetry (unix behavior) ?

----------------------------------------------------------------------

Comment By: Donal K. Fellows (dkf)
Date: 2009-01-05 07:54

Message:
JL = Jacob Levy, one of the Scriptics staffers. The last I heard he was at
Yahoo, but I doubt he'd remember the details of this. After all, it's over
12 years ago...


----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-05 07:13

Message:
Some progress on the ECONNRESET/EOF issue:
Detailed analysis on Linux, shows that on receiving an RST, the [gets]
yields -1 (EOF) in all cases (i.e whether the recv() is initiated before
reception of RST or not, while at the syscall level (strace) we can see
that the recv() returned ECONNRESET in both cases. 

In summary: on unix, ECONNRESET is purely an internal matter, purposefully
turned into an EOF, as witnessed by  the following code in tclUnixChan.c:

    if (errno == ECONNRESET) {
	/*
	 * Turn ECONNRESET into a soft EOF condition.
	 */
	return 0;

while on Windows, it is exposed as an error, as commented in this comment
from 1996 in the "changes" file:

   8/20/96 (bug fix) No longer masking ECONNRESET on Windows sockets so
   that the higher level of the IO mechanism sees the error instead of
   entering an infinite loop. (JL)

Very old indeed... and beyond 8.x CVS history ! Do you know who JL is ?
Anyway, I don't see why turning ECONNRESET into EOF (just like on unix)
would create an infinite loop...


----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2009-01-03 17:31

Message:
Yet again, more proof that a bi-directional channel is really two
independent simplex connections ;)  Bug 1028264 is very interesting. 

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 17:11

Message:
OK I'll do some more hunting to bring the ECONNRESET/EOF balance close to
50-50 :)

Regarding SF, starting from
https://sourceforge.net/tracker/?atid=110894&group_id=10894&func=browse
if you go into the upper-right box tagged "Trackers" near the Search
button and Advanced link, and just paste a bug ID there, it brings you a
single solution which has the proper link...

----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2009-01-03 16:57

Message:
Should be ECONNRESET only, I'd assume.  I don't see that problem here. 
Though I haven't stared at packets.

What SF box?  the browse page just searches on keywords.  At least
mozilla's BugDB software knows the string 'Bug 12345' is meant to be a
link.  I asked the SF folks ages ago to add cross-referencing features such
as 'depends on' and 'similar to'..  That was like 7 years ago.

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 16:45

Message:
Sorry, I'm being unclear :)
The WSACleanup bug explains the *generation* of the RST (in the server);
the race condition is on *reception* of that RST on the other side.

The other URL is
https://sourceforge.net/tracker/index.php?func=detail&aid=1028264&group_id=10894&atid=110894
(I gave only the bug number assuming it was easy to paste it in SF's box)

OK to fix the tear-down first (other bug)
But when we're done and back here, what I called "Problem 2" is that on
reception of an RST it seems unpredictable whether the outcome will be an
EOF or an ECONNRESET.




----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2009-01-03 16:41

Message:
What race condition?  If WSACleanUp() hit, expect everything open to be
screwed.  What's the URL to that other bug as the search functions are
hideous on SF?  Please define "problem 2" in more detail.  No [close] bad,
with [close] all good, therefore fix the tear-down first and come back to
this.

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 16:36

Message:
Yes, please read my other comments ;-)
I prefer to leave the bug open as it is not normal to generate an RST on
exit.
And I really want to grok Problem 2 !

----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2009-01-03 16:34

Message:
With 'close $::sok' in the echo server, I don't see that problem at all. 
There is no bug anymore.

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 16:27

Message:
Yes, please go to the other bug, and see my last comments about the
sequence of events. Basically the process-wide SocketExitHandler, which is
called much too soon in the sequence, does all the harm. See my proposed
solution there and please amend it (there). In the current entry, let's
only talk about "problem 2": the race condition on incoming RST that makes
them sometimes just make an EOF, sometimes raise "connection reset by
peer". Any idea ?

----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2009-01-03 16:06

Message:
Yup, you nailed it alright.  I feel silly.  I should have seen it.

If WSACleanup hits first, all bets off.  Shouldn't Tcl close open channels
as part of the tear-down?  Is this one of those ExitHandler hits, but the
per-thread didn't things?  Call the per-thread from the ExitHandler when
TheadId is the same?  Just reading I get a bit blurry from the thread
transfer stuff.

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 11:25

Message:
By the way, this socket finalization problem was already apparent in
1028264.
This is interesting because the analysis there shows that the culprit is
the mess in multithreaded finalization; so the problem might not be
Winsock, but the fact that the Windows build is threaded.
I'm not closing any of the two as Dup yet; I'd like to know about problem
2 first...



----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 10:58

Message:
Got it !!! ... At least for the first problem, "why is the server sending
an RST ?".

This seems to be linked to the absence of [close] before [exit].
Just adding a close before exit in the server makes the test succeed
reliably.
I'm *not* updating the test because this is a bug. On unix for example, a
close-less exit() doesn't result in an RST.
David, any idea why the Winsock teardown does this ?
*And* we still need an explanation for problem 2 ;-)



----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 03:53

Message:
Further analysis of the Heisenbug part: it is not completely abnormal !
Indeed, RFC793 says on http://www.freesoft.org/CIE/RFC/793/34.htm

     ESTABLISHED
      FIN-WAIT-1
      FIN-WAIT-2
      CLOSE-WAIT

        If the RST bit is set then, any outstanding RECEIVEs and SEND
        should receive "reset" responses.  All segment queues should be
        flushed.


This means that two situations may occur:

  - either we manage to drink all data up to the Tcl level before the RST
occurs
  - or we lag somewhere (introduce an [after] to see this) and go back to
doing recv() while the TCP stack has already received the RST

These two perfectly normal situations lead to different sizes of data on
the receive side.
What is *not* normal though is that the Tcl-level outcome has *three* (not
two) cases:

  (a) full data
  (b) connection reset by peer
  (c) truncated data

In particular, adding an [after 1000] before the reading loop in my above
synchronous client deterministically yields (c), while without the delay we
get (b) with prob==0.1 and (a) with prob==0.9 (and also (c) with
prob==epsilon)

So the bug hunt can now be summarized as:
  - find out why the Tcl server is sending RST
  - iron out the Tcl-level outcomes (b vs. c)




----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 03:33

Message:
Even more interesting, the sequence of packets is exactly the same
regardless of the outcome of the probability-0.1 test !
That is, there are at least two issues:

 - the server sending RST
 - the client Heisenbugging on that RST

TBC...

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-03 03:21

Message:
Some progress at last !
For some reason one trick that had not worked before, works :)
Basically add a route to the host itself (the LAN address, not 127.0.0.1)
forcing it to go through the home router:

   route add 192.168.1.11 mask 255.255.255.255 192.168.1.1

This has the delicious property of going through the non-loopback while
remaining on the machine (provided that address is used instead of
127.0.0.1). The only ill effect is that every packet is seen twice, and
Wireshark is not too smart about them (complains about out-of-sequence or
dup'ed acks), but that doesn't prevent human analysis !

Now the good news is that the bug shows up all the same with this
"instrumented loopback" !
I'm happy to have been wrong about loopback-specific issues ;-)

Will continue investigations, but I have already found the following:

 - the FIN+DATA, when it occurs (not with a Tcl server), is handled
without bugs.

 - what occurs in Tcl-server tests, is rather "DATA ; RST" (the ';' means
2 separate packets)

So it seems all this is due to an RST from the server where a FIN would
have been in order.
Have to dig to understand why that RST is sent...

----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2009-01-01 12:02

Message:
http://www.freesoft.org/CIE/RFC/793/23.htm

Just for reference.

----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2009-01-01 11:53

Message:
Beyond ethereal, I never explored much.  I did try -myaddr [info hostname]
but had the same effect.  I see the failures and successes, too, at the
same percentage.

Does this work across two machines where the other hosts the echo server? 
I haven't tried that yet.  Is this purely a localhost issue?

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2009-01-01 09:15

Message:
Sure. However, as mentioned earlier the problem only occurs on the loopback
interface. Moreover, the code I last posted below has a probability of
failure of ~ 0.1 , so you have to run it many times to see it. But when you
see it, it's definitely there.

David, do you know of a better tool than CommView, that would both see the
loopback *and* display FINs ?



----------------------------------------------------------------------

Comment By: David Gravereaux (davygrvy)
Date: 2008-12-31 16:33

Message:
Alexandre, I've been looking at this issue a bit.  Apparently, Google is
rude.  I guess they just consider a client initiated graceful close to be a
full close.  There was always some weird stuff around http/1.0 anyways.  I
guess they are being defensive.  By doing so, they have to collect the
TIME_WAITs on their side.

I tested some other services, and got an appropriate closure without
loss.

proc go1 {} {
    set s [socket mail.pobox.com smtp]
    fconfigure $s -buffering line -blocking 0
    fileevent $s readable [list gotreadable $s]
    puts $s "ehlo [lindex [fconfigure $s -sockname] 1]"
    puts $s "quit"
    close $s w
}

proc go2 {} {
    set s [socket www.google.com http]
    fconfigure $s -buffering line -blocking 0
    fileevent $s readable [list gotreadable $s]
    puts $s "GET / HTTP/1.1\n"
    close $s w
}

proc gotreadable {chan} {
    if {[string length [set err [fconfigure $chan -error]]]} {
        puts $err
        close $chan
        return
    }
    if {[gets $chan data] != -1} {
        puts $data
    }
    if {[eof $chan]} {
        puts "got eof"
        close $chan
    }
}


----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2008-12-28 04:41

Message:
Hmm, withdrawing that last remark about separate DATA and FIN: I've just
noticed that Tcl sockets don't use TCL_NODELAY, hence the Nagle method is
at work. That makes a plausible link with timing: if the data and FIN are
within the Nagle delay (200ms), the TCP stack may glue them together !

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2008-12-28 04:34

Message:
Update: we can release one constraint !
Indeed, I get spurious "connection reset by peer" and EOFs even with code
devoid of any half-close (see below).
So only one FIN from B is needed. Moreover, the code below clearly
separates the last data write from the close (flush in the server, distinct
from exit), so the FIN packet itself is separate from the data. It seems
only the *timing* plays a role in that nasty bug.

#client
set ::s [socket $host $port]
puts $::s Hey1
puts $::s Hey2
puts $::s Hey3
flush $::s
while {[gets $::s line]>=0} {
    lappend ::acc $line
}
puts RESULT:$::acc

#server
proc accept {s args} {set ::sok $s}
set s [socket -server accept $port]
vwait ::sok
set cnt 0
while {[gets $::sok line]>=0} {puts $::sok $line;puts stderr
XMIT:$line;incr cnt;if {$cnt>=3} break}
puts $::sok DONE
flush $::sok
puts stderr WRITTEN
exit 0



----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2008-12-27 15:23

Message:
David, thanks for looking into this (though anonymously ;-)

However, this google example, as indicated previously, is a red herring
for the bug under scrutiny, because if you take a network snoop of the
interaction you'll see that when that line is uncommented, google refrains
from sending the HTTP reply altogether. I assume this is an anti-attack
strategy of sorts...

According to my tests, the bug is witness only when the following
conditions are met:

 - On loopback interface
 - A sends a FIN
 - B writes and sends a FIN all in one packet
 - A receives the FIN ignoring the data
 - A is Tcl



----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2008-12-27 13:36

Message:
I like this TIP very much.  I was pondering what to do about a graceful
close for my iocp work, too.  close2proc is the right way, and this is just
proof of it.

Yes something is wrong..  the following script bit shows it for me:

set s [socket www.google.com 80]
fconfigure $s -buffering line
puts $s "GET / HTTP/1.0\n"
#close $s w
read $s
close $s

Uncommenting the line that causes shutdown() to be called breaks it, but
shouldn't.  I can't look at it much further at the moment, but I'll do some
debugging soon after the holiday madness.


----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2008-12-26 08:23

Message:
Reporting progress: using CommView I was able to trace the loopback
interface. However, something seems to prevent the normal use of the FIN
TCP flag on that faked interface (Windows is definitely weird), since a
normal socket closes without a single FIN being observed (while they are
normally seen on a non-faked interface).
Anyway, I wrote standalone C executables (variants of "nc") for both sides
and they don't display the Tcl bug (ie only the Tcl-Tcl combination
displays it), so there's hope ;-)
One key thing seems to be the timing of the write-back and close by the
server: an [after] between the child-side [flush] and [exit] removes the
problem. In TCP terms this would seem to confirm Andreas' hypothesis that a
data-loaded packet bearing the second FIN induces loss of the data by
"fast-tracking" the interpretation of the FIN.
Now to find why in tclWinSock.c...

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2008-12-22 10:30

Message:
Could well be, though the google example is no proof (here the HTTP server
must be doing some optimization to resist attacks).
Still trying to pinpoint it. Windows' unability to wireshark on loopback
interface is a nightmare... Do you know of an alternative ?
Or a public echo server ?

----------------------------------------------------------------------

Comment By: Andreas Kupries (andreas_kupries)
Date: 2008-12-22 09:29

Message:
Oh, could this be where Windows, the OS, is fast-tracking the close
operation, discarding buffered data ? IIRC this was trouble for something
else as well. I do not recollect details however :(

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2008-12-21 10:44

Message:
Getting closer I think :-)
The following code:

set s [socket www.google.fr 80];puts $s "GET / HTTP/1.0\n";close $s
w;after 1000;puts [read $s];close $s

consistently displays en empty line. I have the impression that it
shouldn't. (Am I right ?)
Wireshark says that a FIN is sent after the GET, and that google responds
by another FIN with no data.
Have to check the RFC again to check why the Windows shutdown() does that
bad variant of FIN.

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2008-12-20 04:12

Message:
Oh, now I can again with HEAD. Heisenbug.. race condition ?

----------------------------------------------------------------------

Comment By: Alexandre Ferrieux (ferrieux)
Date: 2008-12-19 09:41

Message:
Kevin, are you still seeing it ? Cannot seem to repro.

----------------------------------------------------------------------

Comment By: Andreas Kupries (andreas_kupries)
Date: 2008-12-18 21:14

Message:
2444274 is a gob of multiple problems.

My changes fixed the underlying flush handling in the generic IO layer.

dgp's changes, as I understood it, prevent the test cases from writing
errorInfo contents to stderr, causing the chanio.test reported as exiting
with error, for -singleproc 0.


----------------------------------------------------------------------

Comment By: Kevin B KENNY (kennykb)
Date: 2008-12-18 20:52

Message:
For what it's worth, this happened *after* dgp committed changes purporting
to fix 2444274

----------------------------------------------------------------------

Comment By: Andreas Kupries (andreas_kupries)
Date: 2008-12-18 20:38

Message:
Yes, see the latest comments at
https://sourceforge.net/tracker2/index.php?func=detail&aid=2444274&group_id=10894&atid=110894


----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=110894&aid=2446662&group_id=10894