Tcl Source Code

I downloaded the latest Tcl cvs head from the activestate ftp site. The following tests in http11.test failed. I last tested at the end of May and don't recall seeing these failures.
http11.test

==== http-2.6 -channel,encoding gzip,non-chunked FAILED
==== Contents of test case:

    set tok [http::geturl http://localhost:$httpd_port/testdoc.html?close=1  -ti
meout 5000 -channel $chan -headers {accept-encoding gzip}]
    http::wait $tok
    seek $chan 0
    set data [read $chan]
    list [http::status $tok] [http::code $tok] [check_crc $tok $data] [meta $tok
 connection] [meta $tok content-encoding] [meta $tok transfer-encoding] [expr {[
file size testdoc.html]-[file size testfile.tmp]}]

---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne edc98c73} close gzip {} 121845
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close gzip {} 0
==== http-2.6 FAILED

==== http-2.7 -channel,encoding deflate,non-chunked FAILED
==== Contents of test case:

    set tok [http::geturl http://localhost:$httpd_port/testdoc.html?close=1  -ti
meout 5000 -channel $chan -headers {accept-encoding deflate}]
    http::wait $tok
    seek $chan 0
    set data [read $chan]
    list [http::status $tok] [http::code $tok] [check_crc $tok $data] [meta $tok
 connection] [meta $tok content-encoding] [meta $tok transfer-encoding] [expr {[
file size testdoc.html]-[file size testfile.tmp]}]

---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne edc98c73} close deflate {} 121
845
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close deflate {} 0
==== http-2.7 FAILED

==== http-2.8 -channel,encoding compress,non-chunked FAILED
==== Contents of test case:

    set tok [http::geturl http://localhost:$httpd_port/testdoc.html?close=1  -ti
meout 5000 -channel $chan -headers {accept-encoding compress}]
    http::wait $tok
    seek $chan 0
    set data [read $chan]
    list [http::status $tok] [http::code $tok] [check_crc $tok $data] [meta $tok
 connection] [meta $tok content-encoding] [meta $tok transfer-encoding] [expr {[
file size testdoc.html]-[file size testfile.tmp]}]

---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne edc98c73} close compress {} 12
1845
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close compress {} 0
==== http-2.8 FAILED

Committed this workaround. Also committed a change which causes Z_BUF_ERROR returns from inflate to be ignored. This is per the Zlib FAQ, which says that this is just a temp condition fixable by providing more input/output space.

Keeping open, with changed description and category, as reminder to make a long-term fix.

Now I understand. Here is a trace I made with fprintf at strategic places in the Zlib and general IO code.

    Compressed size is 41
    IO ChanRead (4096)
    IO got 48
    IO OK
    HEADER:hahaha
    Z INFLATE 0x804cdc0
    Z PUSH  0x80681a8
    Now reading through gunzip
    IO DoReadChars c0 -1 /loop 4294967295
    IO DOReadChars Copied -1
    IO ChanRead (4096)
    Z INPUT 0x80681a8 4096
    Z GET RAW 0x80738e0 4096
    IO ChanRead (4055)
    Z         41
    Z processing 41, space for 4096
    Z 0 left 10, remaining 0 /1/0
    Z returning 4096
    IO got 4096
    IO OK
    IO DoReadChars c0 -1 /loop 4294967295
    IO DoReadChars Queued Data
    IO DOReadChars Copied 4096
    IO DoReadChars c4096 -4097 /loop 4294963199
    IO DOReadChars Copied -1
*   IO DOReadChars EOF
    Received 4096 out of 5000
    Z CLOSE 0x80681a8

The problem is shown by the *'d line. 

(1) We have a base channel, and
(2) a transformation on top
(3) By reading from the transformation we cause it to
(4) read from the base channel.
(5) The base channel hits EOF in that read.
(6) The loop in DoReadChars() sees that EOF flag and aborts,
(7) never mind that data is in the transform which we could read.

The generic IO code thinks that the EOF flag applies to the whole stack, while it actually applies only to the base channel. The flags, including EOF are managed in the ChannelState, which is shared between all channels in the stack.

To truly fix this we have to manage some EOF flag on a per-channel/transform base, and look only at the flag of the topmost channel instead of the shared one.

This is an issue any and all transforms can run into, causing loss of the last part of their info.

A related problem which can occur in the middle of a channel is if you have, for example multiple deflated streams in the same channel, then reading data for the first stream may read ahead into data of the next, and you cannot unread this part, it is in the buffers high up and cannot be pushed back for the next stream to be processed.

I believe that is the reason for TIP 230 having the 'limit' method. It can be used to limit the amount of read-ahead. In the case of limit=1 nothing is read beyond the end of a stream, so the next stream is ok, nothing to unread.

This helps in our case actually as well. Because reading the Z_STREAM_END marker byte(s) does not yet trigger eof in the base channel, allowing the outer DoReadChars() loop to run fine.

Thus, changing Tcl_ReadRaw(..., cd->inAllocated); in tclZLib.c to Tcl_ReadRaw(..., 1); is a quick fix for the issue. Correct behaviour at the expense of more calls to the base channels.

If you use strace on that example, you'll notice that all the OS-level I/O goes properly: the full 48 bytes of the stream get written and read over the pipe. Seven of these bytes get out as hahaha\n; so it is really a question of what happens to those buffered last 41 bytes and the subsequent EOF.

write(4, "hahaha\n\37\213\10\0\0\0\0\0\0\3\355\3011\1\0\0\0\302\240l\353_\312\24~"..., 48) = 48
close(4)                                = 0
read(3, "hahaha\n\37\213\10\0\0\0\0\0\0\3\355\3011\1\0\0\0\302\240l\353_\312\24~"..., 4096) = 48
write(2, "HEADER:hahaha", 13HEADER:hahaha)           = 13
write(2, "\r\n", 2
)                     = 2
write(2, "Now reading through gunzip", 26Now reading through gunzip) = 26
write(2, "\r\n", 2
)                     = 2
read(3, "", 4055)                       = 0

[14:16]ferrieuxaku -- thanks, see reply 
[14:17]akuferrieux - Yeah, just started into looking into your simple example.
[14:18]akuHat one is less clear, channel is blocking according to script, read shopuld run until it has drained the transform dry before returning
[14:19]ferrieuxaku -- yes but I have the deep feeling that it is exactly the same bug
[14:19]c_in_cfwith Cameron, just about 1 1/2 hours ago
[14:19]kbkc_in_cf - You obviously have further questions. Please ask them specifically, don't just keep asking if someone can write your program for you.
[14:19]akuWe will see.
[14:19]ferrieuxand it is simpler to chase since there is no race
[14:20]akuHm, when I do not 'close $pw' the get raw hangs ... I guess that is proper, because there might be more, and so the base channel waits ...
[14:20]akuI will add more instrumentation to the internals and report back when I know more ....

For "up" vs "down", OK, of course.
However, you're not commenting on my simpler test case, where there's no race nor [chan pop].

Regarding "that case the buffered zlib'd input is not properly passed down the stack."

You are looking into the wrong direction. This is about _input_. Input walks _up_ the stack.
And while a transformation is able to flush data waiting in its state down the stack on chan pup, thus flushing _write_ buffers, the same is not possible for data waiting _read_ buffers/state. They have nowhere to go. Reading is demand-driven from the core I/O layer, the driver cannot announce 'hey here is some data to splace into your input buffer queue.

This means data waiting to be read at the time 'chan pop' is done (or C equivalent) is _lost_.

And this seems to me to be case here. Sometimes, the 'close' is done early, before all the decompressed data has been read out of the zlib state.

I have seen the http-2.6 test failing and succeeding here now. More fail, but sometimes it is ok. And for that case my trace of the zlib transform internals shows 16 calls of ZlibTransformInput after the initial call of same which pulled the data from the base channel. In the failing case none of these additional calls happen, only the ZlibTransformClose immediately after the initial call pulling data ... It really looks like a race to me where the close is done early, causing the pending data to be lost per the explanation above.

File Added - 363990: zbug.tcl

Now attaching a much simpler test case: no HTTP, no socket, just a standalone [chan pipe].
I'm sending the usual uncompressed/compressed mix, and the bottom line is that only the first 4096 bytes of decompressed data are received (out of 5000 send), while the compressed size is 41.

I wonder why it is 4096 here and 8192 in the original test (maybe socket vs pipe ?)
Anyway hope this simpler test helps.

Ah, for traces I didn't change anything to the sources, just tcpdump/strace.

Sure: http11-2.6 "-channel,encoding gzip,non-chunked" is the one I looked more into, though with the strace slowdown the three 2.[678] fail equally. Clearly the compression method doesn't matter.

For comparison look at tclIORTrans.c. That is the 'generic' transformation, i.e. the foundation for the 'chan push ' (TIP 230).

Alexandre,
can you tell me which of the failing test cases you investigated more deeply and are referencing in your comment ? Also, can you send me a patch of any changes you made to the sources for your investigation (i.e. additional output and such), if any.

Further investigation shows that the problem arises when a single
read/recv() contains both uncompressed and compressed data . Clearly in
that case the buffered zlib'd input is not properly passed down the stack.
Reassigning to Andreas for (1) an explanation of how this is supposed to work in the general case and (2) a review of how the zlib stacked channel (mis)handles it.

Just figured the 435 bytes are the valid result of compressing with gzip the highly repetitiver 130k input file :} So, was barking up the wrong tree. Now to look on the receive side.

Hypothesis proven wrong. The attached patch to httpd11.tcl turns it from overlapped, coro-based, to blocking, one-client-at-a-time, and still displays the bug.

Hypothesis proven wrong. The attached patch to httpd11.tcl turns it from overlapped, coro-based, to blocking, one-client-at-a-time, and still displays the bug.

File Added - 362579: httpd11.patch

Random hypothesis: since this tiny httpd is coro-based, yielding to the event loop, timing affects the exact order of stack activation. Could a bug there corrupt the big byte array ?

New progress. A bit of debug puts in httpd11.tcl around

            puts -nonewline $chan [zlib $encoding $data]

show that [string length $data] is 130037,
while [string length [zlib $encoding $data]] is 435 !!! (emphasis, not triple factorial)

So this looks like a plain bug in [zlib].
Now to find the reason for the timing-dependent trigger...

See new observations in (unrelated) 2946474.
Basically, (1) "strace -f -o /dev/null make test" reproduces with probability>90%, and (2) the problem occurs even with a blocking flush of the gzip channel. At this point only a single block of 435 gzipped bytes, corresponding to 8192 (!) uncompressed bytes, is written.
The sequence of events leading to that state is timing-dependent in this case, though the final step (flushing and truncating) is not.

FWIW, I see these tests fail much
more reliably on the dgp-refactor-branch
than on HEAD.

Just a note that this continues to be an issue, 5 months later. on Solaris 8.

Note that today, June 26, 2009, I downloaded the tcl cvs head from the activestate ftp site, configured and built it on my solaris 8 machine using Sun's C compiler, and here's what I see for these tests:
http11.test

==== http11-2.6 -channel,encoding gzip,non-chunked FAILED
==== Contents of test case:

    set tok [http::geturl http://localhost:$httpd_port/testdoc.html?close=1  -ti
meout 5000 -channel $chan -headers {accept-encoding gzip}]
    http::wait $tok
    seek $chan 0
    set data [read $chan]
    list [http::status $tok] [http::code $tok] [check_crc $tok $data] [meta $tok
 connection] [meta $tok content-encoding] [meta $tok transfer-encoding] [expr {[
file size testdoc.html]-[file size testfile.tmp]}]

---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne edc98c73} close gzip {} 121845
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close gzip {} 0
==== http11-2.6 FAILED

==== http11-2.7 -channel,encoding deflate,non-chunked FAILED
==== Contents of test case:

    set tok [http::geturl http://localhost:$httpd_port/testdoc.html?close=1  -ti
meout 5000 -channel $chan -headers {accept-encoding deflate}]
    http::wait $tok
    seek $chan 0
    set data [read $chan]
    list [http::status $tok] [http::code $tok] [check_crc $tok $data] [meta $tok
 connection] [meta $tok content-encoding] [meta $tok transfer-encoding] [expr {[
file size testdoc.html]-[file size testfile.tmp]}]

---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne edc98c73} close deflate {} 121
845
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close deflate {} 0
==== http11-2.7 FAILED

==== http11-2.8 -channel,encoding compress,non-chunked FAILED
==== Contents of test case:

    set tok [http::geturl http://localhost:$httpd_port/testdoc.html?close=1  -ti
meout 5000 -channel $chan -headers {accept-encoding compress}]
    http::wait $tok
    seek $chan 0
    set data [read $chan]
    list [http::status $tok] [http::code $tok] [check_crc $tok $data] [meta $tok
 connection] [meta $tok content-encoding] [meta $tok transfer-encoding] [expr {[
file size testdoc.html]-[file size testfile.tmp]}]

---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne edc98c73} close compress {} 12
1845
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close compress {} 0
==== http11-2.8 FAILED

It is definately some interaction with the 'zlib push' and the fcopy we use in the http package when the -channel option has been provided. The only tests that fail use both -channel and a compression algorithm which leads to a 'zlib push'. Test http11-2.9 is the same as 2.[678] but doesn't use any compression (hence does not 'zlib push' and it never fails.

Recognizing this I've added some puts commands into http::CopyDone and arranged to retry when we see an [eof]. On [eof] I set a flag in the state array and try one more time. This causes the tests to pass now and in the following output we can see that 2.7 had an early [eof] then continued. I suspect that given more data we might see additional [eof] later so a single retry is probably not robust.

The channel termination can't be due to the data being sent - first, -eofchar is {} here and secondly the three failing tests use different compression algorithms so the data stream will be different in each case.

Tests began at Thu Jun 25 22:03:25 BST 2009
http11.test
== CopyDone: count:8192 total: 8192 err:''
== Eof '1'
== Retry on Eof
== CopyDone: count:8192 total: 16384 err:''
== CopyDone: count:8192 total: 24576 err:''
== CopyDone: count:8192 total: 32768 err:''
== CopyDone: count:8192 total: 40960 err:''
== CopyDone: count:8192 total: 49152 err:''
== CopyDone: count:8192 total: 57344 err:''
== CopyDone: count:8192 total: 65536 err:''
== CopyDone: count:8192 total: 73728 err:''
== CopyDone: count:8192 total: 81920 err:''
== CopyDone: count:8192 total: 90112 err:''
== CopyDone: count:8192 total: 98304 err:''
== CopyDone: count:8192 total: 106496 err:''
== CopyDone: count:8192 total: 114688 err:''
== CopyDone: count:8192 total: 122880 err:''
== CopyDone: count:7157 total: 130037 err:''
== Eof '1'
++++ http11-2.7 PASSED
== CopyDone: count:8192 total: 8192 err:''
== CopyDone: count:8192 total: 16384 err:''
== CopyDone: count:8192 total: 24576 err:''
== CopyDone: count:8192 total: 32768 err:''
== CopyDone: count:8192 total: 40960 err:''
== CopyDone: count:8192 total: 49152 err:''
== CopyDone: count:8192 total: 57344 err:''
== CopyDone: count:8192 total: 65536 err:''
== CopyDone: count:8192 total: 73728 err:''
== CopyDone: count:8192 total: 81920 err:''
== CopyDone: count:8192 total: 90112 err:''
== CopyDone: count:8192 total: 98304 err:''
== CopyDone: count:8192 total: 106496 err:''
== CopyDone: count:8192 total: 114688 err:''
== CopyDone: count:8192 total: 122880 err:''
== CopyDone: count:7157 total: 130037 err:''
== Eof '1'
== Retry on Eof
== CopyDone: count:0 total: 130037 err:''
== Eof '1'
++++ http11-2.9 PASSED

I can confirm the same failures on netbsd 5.0, on both 32 bits (i386 port) and 64 bits (amd64 port).
I think bug 2780687 is a duplicate if this.

Just testing today on a 64-bit system:

$ uname -a
Linux <REDACTED>.nist.gov 2.6.18-128.1.6.el5 #1 SMP Wed Apr 1 09:10:25 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux

and I see tests http-2.7 and http-2.8 reliably fail there
just as they do in the original report here.

No failure of http-2.6 though.

these are new files. For some reason we are having trouble writing to a file via -channel so the crc and the size checks are wrong.  Reproduced on my solaris10 box.