On Mon, Jan 06, 2020 at 06:38:29PM +0000, Travis CI wrote: > Build Update for apache/httpd > ------------------------------------- > > Build: #190 > Status: Still Failing > > Duration: 7 mins and 11 secs > Commit: 894b6a1 (trunk) > Author: Luca Toscano > Message: travis: add verbose config to perl test suite for Ubuntu Worker All > Modules > > For some reason we get sporadic failures only in Ubuntu Worker All Modules' > test: > > t/apache/rwrite.t ................... 53/? # Failed test 113 in > /home/travis/build/apache/httpd/test/perl-framework/blib/lib/Apache/TestCommon.pm > at line 56 fail #113 > t/apache/rwrite.t ................... Failed 1/114 subtests
It is quite easy to reproduce this for me under worker as well, if you run ./t/TEST t/apache/rwrite.t t/apache/pass_brigade.t in a loop, one of them will fail quite quickly. It looks like the client gets a socket closure instead of the very last block of the response, here is the client output: #server response: #HTTP/1.1 200 OK #Connection: close #Date: Tue, 07 Jan 2020 10:55:28 GMT #Server: Apache/2.5.1-dev (Unix) OpenSSL/1.1.1d #Vary: In-If1 #Content-Length: 0 #Client-Aborted: die #Client-Date: Tue, 07 Jan 2020 10:55:28 GMT #Client-Peer: 127.0.0.1:8529 #Client-Response-Num: 1 #Client-Transfer-Encoding: chunked #DMMATCH1: 1 #X-Content-Length-Note: added by Apache::TestRequest #X-Died: EOF when chunk header expected at /usr/share/perl5/vendor_perl/Net/HTTP/Methods.pm line 532. # # testing : bytes in body # expected: 10190848 # received: 10240000 not ok 114 Failed 1/114 subtests The tail end of error_log it looks like this: [Tue Jan 07 10:55:28.414864 2020] [core:trace8] [pid 37542:tid 140091146098432] util_filter.c(1129): [client 127.0.0.1:49470] brigade contains: bytes: 49205, non-file bytes: 49205, eor buckets: 1, morphing buckets: 0 [Tue Jan 07 10:55:28.414866 2020] [core:trace6] [pid 37542:tid 140091146098432] util_filter.c(942): [client 127.0.0.1:49470] setaside full brigade to empty brigade in 'req_core' output filter [Tue Jan 07 10:55:28.414872 2020] [core:trace6] [pid 37542:tid 140091146098432] util_filter.c(1015): [client 127.0.0.1:49470] reinstate full brigade to full brigade in 'core' output filter [Tue Jan 07 10:55:28.414876 2020] [core:trace6] [pid 37542:tid 140091146098432] core_filters.c(670): (11)Resource temporarily unavailable: [client 127.0.0.1:49470] writev_nonblocking: 0/1656 [Tue Jan 07 10:55:28.414879 2020] [core:trace6] [pid 37542:tid 140091146098432] util_filter.c(1015): [client 127.0.0.1:49470] reinstate empty brigade to full brigade in 'core' output filter [Tue Jan 07 10:55:28.414881 2020] [core:trace6] [pid 37542:tid 140091146098432] util_filter.c(1104): [client 127.0.0.1:49470] will flush because of FLUSH bucket [Tue Jan 07 10:55:28.414883 2020] [core:trace8] [pid 37542:tid 140091146098432] util_filter.c(1106): [client 127.0.0.1:49470] seen in brigade so far: bytes: 1656, non-file bytes: 1656, eor buckets: 0, morphing buckets: 0 [Tue Jan 07 10:55:28.414888 2020] [core:trace8] [pid 37542:tid 140091146098432] util_filter.c(1129): [client 127.0.0.1:49470] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0 [Tue Jan 07 10:55:28.418754 2020] [core:trace6] [pid 37542:tid 140091146098432] core_filters.c(670): [client 127.0.0.1:49470] writev_nonblocking: 1656/1656 [Tue Jan 07 10:55:28.418764 2020] [core:trace6] [pid 37542:tid 140091146098432] util_filter.c(942): [client 127.0.0.1:49470] setaside empty brigade to empty brigade in 'core' output filter [Tue Jan 07 10:55:28.427067 2020] [optional_hook_import:error] [pid 37542:tid 140091146098432] AH01866: Optional hook test said: GET /test_rwrite?8192,10240000 HTTP/1.1 [Tue Jan 07 10:55:28.427072 2020] [optional_fn_export:error] [pid 37542:tid 140091146098432] AH01871: Optional function test said: GET /test_rwrite?8192,10240000 HTTP/1.1 and nothing else is logged for the connection. In both cases, with an explicit FLUSH at the end of the response I cannot reproduce this any more. I added one #if 0'ed out here: http://svn.apache.org/viewvc?view=revision&revision=1872431 and it's a simple ap_rflush(r) in mod_test_rwrite.c as well. This seems like a bug to me (not obviously in the tests) but I'm not sure exactly where. The "writev_nonblocking: 1656/1656" line *appears* to suggest the last block was successfully written to the socket. Regards, Joe > Recent examples: > https://travis-ci.org/apache/httpd/jobs/632425202 > https://travis-ci.org/apache/httpd/jobs/633250739 > > Add "-verbose" as test option to capture more data about the failure > when it happens. > > > > git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1872389 > 13f79535-47bb-0310-9956-ffa450edef68 > > View the changeset: > https://github.com/apache/httpd/compare/0bd4a3d88cba...894b6a185041 > > View the full build log and details: > https://travis-ci.org/apache/httpd/builds/633409517?utm_medium=notification&utm_source=email > > -- > > You can unsubscribe from build emails from the apache/httpd repository going > to > https://travis-ci.org/account/preferences/unsubscribe?repository=69847&utm_medium=notification&utm_source=email. > Or unsubscribe from *all* email updating your settings at > https://travis-ci.org/account/preferences/unsubscribe?utm_medium=notification&utm_source=email. > Or configure specific recipients for build notifications in your .travis.yml > file. See https://docs.travis-ci.com/user/notifications. >
