Menu
▾
▴
#4729 debug test failures
In a debug build of Tcl (--enable-symbols=all),
a complete `make test` run reliably reports
these failing tests:
==== http11-2.0 -channel FAILED
==== Contents of test case:
set tok [http::geturl http://localhost:$httpd_port/testdoc.html -timeout 5000 -channel $chan]
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 transfer-encoding]
---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne b946628e} close chunked
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close chunked
==== http11-2.0 FAILED
==== http11-2.1 -channel, encoding gzip FAILED
==== Contents of test case:
set tok [http::geturl http://localhost:$httpd_port/testdoc.html -timeout 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]
---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne 6d52cc3} close gzip chunked
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close gzip chunked
==== http11-2.1 FAILED
==== http11-2.2 -channel, encoding deflate FAILED
==== Contents of test case:
set tok [http::geturl http://localhost:$httpd_port/testdoc.html -timeout 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]
---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne b946628e} close deflate chunked
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close deflate chunked
==== http11-2.2 FAILED
==== http11-2.3 -channel,encoding compress FAILED
==== Contents of test case:
set tok [http::geturl http://localhost:$httpd_port/testdoc.html -timeout 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]
---- Result was:
ok {HTTP/1.1 200 OK} {crc32 mismatch: c554bc27 ne ffff1d4} close compress chunked
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok close compress chunked
==== http11-2.3 FAILED
==== http11-2.10 -channel,deflate,keepalive FAILED
==== Contents of test case:
set tok [http::geturl http://localhost:$httpd_port/testdoc.html -timeout 5000 -channel $chan -keepalive 1]
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 b946628e} {} deflate chunked 20203
---- Result should have been (exact matching):
ok {HTTP/1.1 200 OK} ok {} deflate chunked 0
==== http11-2.10 FAILED
When "-file http.test" is used to limit the testing to only
that file, the tests pass.
Oops! The failing tests are in http11.test !
Single file testing is enough to see the problem.
same failures in a --enable-symbols=mem build.
When the tests fail, the writes to testfile.tmp
are incomplete.
The http::wait commands in these tests
appear pointless since all [geturl] calls
are synchronous (no -command option).
Funnily, the missing part in the write seems to be at the beginning. That is, the written file is a suffix of the original.
I would hypothesize that the part of the body that is read along with the headers gets lost.
[$stream add -finalize {}] have different
returns in the FAIL/SUCCEED scenarios.
When the tests fail, the empty string is returned.
Failing $stream is the command returned
by [zlib stream gunzip].
When the tests fail, it is not always
an empty string returned, but it is always
short of the full correct amount.
I see that ZlibStreamCmd uses
the anti-recommended pattern of
Tcl_Obj *obj = Tcl_GetObjResult(interp);
...
write to obj
....
return
where many other Tcl library calls happen
in the ...
Yes, that's pervasive in the file
tclZlib.c and must be changed.
May or may not be the sources of
the trouble reported here.
TIP 24 tells me these things get
dumped on dkf. Sorry.
In the failing tests, there are two calls
to the command $stream.
$stream add $chunk
and later
$stream add -finalize $excess
Between the two calls, the memory pointed
to by zshPtr->stream.next_in gets overwritten
in the failing mem-debug case. This is a memory
corruption bug. Possible suspect is just botched
lifetime management of the intreps of bytearray
values.
The overwritten memory is filled with
bytes holding the decimal value 97,
ASCII character 'a'.
...which is the GUARD_VALUE which
Tcl's debugging free fills freed memory
with. Suggests the second [$stream]
call is reading from freed memory, and
might well be doing this in the "working"
version as well.
Confirmed, the $stream command is
reading from freed memory. In all builds.
ByteArray lifetime management is botched.
Was not due to Tcl_GetObjResult problems; purging that didn't clear things. Will commit that change anyway and then continue to probe...
Problem was shimmering of bytearray representation when zlib still had its claws in it. Nasty.
Many thanks to your bughunting skills, Don. Cut my time-to-solution heavily.
Fixed.