Regression test failure on v2.0.4
Adrian Otto
aotto at mosso.com
Fri May 8 19:35:54 CEST 2009
Varnish Devs,
I'm getting intermittent failures with regression test 387 when
running "make check" against 2.0.4. The excerpt-1 below is from the
"make check" output, and the excerpt-2 and excerpt-3 are the verbose
output of the same test with failed, and passed results respectively
(one run right after the other against the same source code and binary).
You'll notice that the ordering of this event:
#### s1 send| 00000000\r\n
...is different between the two. It seems that in the failed result,
the client begins to act upon the response before the server finishes
sending it.
Regards,
Adrian
excerpt-1 (from make test):
# top TEST ././tests/r00387.vtc starting
# TEST Regression test for #387: too long chunk header
## s1 Starting server
### s1 listen on 127.0.0.1:9080 (fd 3)
## s1 Started on 127.0.0.1:9080
## v1 Launch
### v1 CMD: cd ../varnishd && ./varnishd -d -d -n /tmp/__v1 -a
'127.0.0.1:9081' -T 127.0.0.1:9001 -P /tmp/__v1/varnishd.pid
### v1 opening CLI connection
### v1 CLI connection fd = 5
### v1 CLI STATUS 200
### v1 CLI STATUS 200
## v1 Start
### v1 CLI STATUS 200
### v1 CLI STATUS 200
## c1 Starting client
## c1 Started
### c1 Connect to 127.0.0.1:9081
### c1 Connected to 127.0.0.1:9081 fd is 9
### c1 rxresp
## c1 Waiting for client
### s1 Accepted socket fd is 4
### s1 rxreq
### c1 Closing fd 9
## c1 Ending
FAIL: ./tests/r00387.vtc
excerpt-2 (failed varnishtest -v):
$ ./varnishtest -v tests/r00387.vtc
# top TEST tests/r00387.vtc starting
# TEST Regression test for #387: too long chunk header
## s1 Starting server
### s1 listen on 127.0.0.1:9080 (fd 3)
## s1 Started on 127.0.0.1:9080
## v1 Launch
### v1 CMD: cd ../varnishd && ./varnishd -d -d -n /tmp/__v1 -a
'127.0.0.1:9081' -T 127.0.0.1:9001 -P /tmp/__v1/varnishd.pid
### v1 opening CLI connection
#### v1 debug| storage_file: filename: ./varnish.JfeL0S (unlinked)
size 17681 MB.\n
#### v1 debug| Using old SHMFILE\n
#### v1 debug| Debugging mode, enter "start" to start child\n
### v1 CLI connection fd = 5
#### v1 CLI TX| vcl.inline vcl1 "backend s1 { .host = \"127.0.0.1
\"; .port = \"9080\"; }\n"
#### v1 CLI RX| VCL compiled.
### v1 CLI STATUS 200
#### v1 CLI TX| vcl.use vcl1
### v1 CLI STATUS 200
## v1 Start
#### v1 CLI TX| start
#### v1 debug| child (16909) Started\n
#### v1 debug| Child (16909) said Closed fds: 3 5 7 8 11 12 14 15\n
### v1 CLI STATUS 200
#### v1 CLI TX| debug.xid 1000
#### v1 debug| Child (16909) said Child starts\n
#### v1 debug| Child (16909) said managed to mmap 18540429312 bytes
of 18540429312\n
#### v1 debug| Child (16909) said Ready\n
#### v1 CLI RX| XID is 1000
### v1 CLI STATUS 200
## c1 Starting client
## c1 Started
### c1 Connect to 127.0.0.1:9081
### c1 Connected to 127.0.0.1:9081 fd is 9
#### c1 txreq| GET / HTTP/1.1\r\n
#### c1 txreq| \r\n
### c1 rxresp
## c1 Waiting for client
### s1 Accepted socket fd is 4
### s1 rxreq
#### s1 rxhdr| GET / HTTP/1.1\r\n
#### s1 rxhdr| X-Varnish: 1001\r\n
#### s1 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
#### s1 rxhdr| Host: 127.0.0.1\r\n
#### s1 rxhdr| \r\n
#### s1 http[ 0] | GET
#### s1 http[ 1] | /
#### s1 http[ 2] | HTTP/1.1
#### s1 http[ 3] | X-Varnish: 1001
#### s1 http[ 4] | X-Forwarded-For: 127.0.0.1
#### s1 http[ 5] | Host: 127.0.0.1
#### s1 bodylen = 0
#### s1 send| HTTP/1.1 200 Ok\r\n
#### s1 send| Transfer-encoding: chunked\r\n
#### s1 send| \r\n
#### s1 send| 004\r\n
#### s1 send| 1234\r\n
#### s1 send| 000000000000000000001\r\n
#### s1 send| @\r\n
#### c1 rxhdr| HTTP/1.1 503 Service Unavailable\r\n
#### c1 rxhdr| Server: Varnish\r\n
#### c1 rxhdr| Retry-After: 0\r\n
#### c1 rxhdr| Content-Type: text/html; charset=utf-8\r\n
#### c1 rxhdr| Content-Length: 460\r\n
#### c1 rxhdr| Date: Fri, 08 May 2009 16:52:19 GMT\r\n
#### c1 rxhdr| X-Varnish: 1001\r\n
#### c1 rxhdr| Age: 0\r\n
#### c1 rxhdr| Via: 1.1 varnish\r\n
#### c1 rxhdr| Connection: close\r\n
#### c1 rxhdr| \r\n
#### c1 http[ 0] | HTTP/1.1
#### c1 http[ 1] | 503
#### c1 http[ 2] | Service Unavailable
#### c1 http[ 3] | Server: Varnish
#### c1 http[ 4] | Retry-After: 0
#### c1 http[ 5] | Content-Type: text/html; charset=utf-8
#### c1 http[ 6] | Content-Length: 460
#### c1 http[ 7] | Date: Fri, 08 May 2009 16:52:19 GMT
#### c1 http[ 8] | X-Varnish: 1001
#### c1 http[ 9] | Age: 0
#### c1 http[10] | Via: 1.1 varnish
#### c1 http[11] | Connection: close
#### c1 body| \n
#### c1 body| <?xml version="1.0" encoding="utf-8"?>\n
#### c1 body| <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//
EN"\n
#### c1 body| "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">\n
#### c1 body| <html>\n
#### c1 body| <head>\n
#### c1 body| <title>503 Service Unavailable</title>\n
#### c1 body| </head>\n
#### c1 body| <body>\n
#### c1 body| <h1>Error 503 Service Unavailable</h1>\n
#### c1 body| <p>Service Unavailable</p>\n
#### c1 body| <h3>Guru Meditation:</h3>\n
#### c1 body| <p>XID: 1001</p>\n
#### c1 body| <address>\n
#### c1 body| <a href="http://www.varnish-
cache.org/">Varnish</a>\n
#### c1 body| </address>\n
#### c1 body| </body>\n
#### c1 body| </html>\n
#### c1 bodylen = 460
#### c1 EXPECT resp.status (503) == 503 (503) match
### c1 Closing fd 9
## c1 Ending
#### s1 send| 00000000\r\n
Assert error in cmd_http_send(), vtc_http.c line 710:
Condition(i == strlen(av[1])) not true.
errno = 104 (Connection reset by peer)
Aborted
excerpt-3 (passed varnishtest -v):
$ ./varnishtest -v tests/r00387.vtc
# top TEST tests/r00387.vtc starting
# TEST Regression test for #387: too long chunk header
## s1 Starting server
### s1 listen on 127.0.0.1:9080 (fd 3)
## s1 Started on 127.0.0.1:9080
## v1 Launch
### v1 CMD: cd ../varnishd && ./varnishd -d -d -n /tmp/__v1 -a
'127.0.0.1:9081' -T 127.0.0.1:9001 -P /tmp/__v1/varnishd.pid
### v1 opening CLI connection
#### v1 debug| storage_file: filename: ./varnish.H4chHT (unlinked)
size 17681 MB.\n
#### v1 debug| Using old SHMFILE\n
#### v1 debug| Debugging mode, enter "start" to start child\n
### v1 CLI connection fd = 5
#### v1 CLI TX| vcl.inline vcl1 "backend s1 { .host = \"127.0.0.1
\"; .port = \"9080\"; }\n"
#### v1 CLI RX| VCL compiled.
### v1 CLI STATUS 200
#### v1 CLI TX| vcl.use vcl1
### v1 CLI STATUS 200
## v1 Start
#### v1 CLI TX| start
#### v1 debug| child (16970) Started\n
### v1 CLI STATUS 200
#### v1 CLI TX| debug.xid 1000
#### v1 debug| Child (16970) said Closed fds: 3 5 7 8 11 12 14 15\n
#### v1 debug| Child (16970) said Child starts\n
#### v1 debug| Child (16970) said managed to mmap 18540429312 bytes
of 18540429312\n
#### v1 debug| Child (16970) said Ready\n
#### v1 CLI RX| XID is 1000
### v1 CLI STATUS 200
## c1 Starting client
## c1 Started
### c1 Connect to 127.0.0.1:9081
### c1 Connected to 127.0.0.1:9081 fd is 9
#### c1 txreq| GET / HTTP/1.1\r\n
#### c1 txreq| \r\n
### c1 rxresp
## c1 Waiting for client
### s1 Accepted socket fd is 4
### s1 rxreq
#### s1 rxhdr| GET / HTTP/1.1\r\n
#### s1 rxhdr| X-Varnish: 1001\r\n
#### s1 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
#### s1 rxhdr| Host: 127.0.0.1\r\n
#### s1 rxhdr| \r\n
#### s1 http[ 0] | GET
#### s1 http[ 1] | /
#### s1 http[ 2] | HTTP/1.1
#### s1 http[ 3] | X-Varnish: 1001
#### s1 http[ 4] | X-Forwarded-For: 127.0.0.1
#### s1 http[ 5] | Host: 127.0.0.1
#### s1 bodylen = 0
#### s1 send| HTTP/1.1 200 Ok\r\n
#### s1 send| Transfer-encoding: chunked\r\n
#### s1 send| \r\n
#### s1 send| 004\r\n
#### s1 send| 1234\r\n
#### s1 send| 000000000000000000001\r\n
#### s1 send| @\r\n
#### s1 send| 00000000\r\n
### s1 shutting fd 4
## s1 Ending
#### c1 rxhdr| HTTP/1.1 503 Service Unavailable\r\n
#### c1 rxhdr| Server: Varnish\r\n
#### c1 rxhdr| Retry-After: 0\r\n
#### c1 rxhdr| Content-Type: text/html; charset=utf-8\r\n
#### c1 rxhdr| Content-Length: 460\r\n
#### c1 rxhdr| Date: Fri, 08 May 2009 16:53:31 GMT\r\n
#### c1 rxhdr| X-Varnish: 1001\r\n
#### c1 rxhdr| Age: 0\r\n
#### c1 rxhdr| Via: 1.1 varnish\r\n
#### c1 rxhdr| Connection: close\r\n
#### c1 rxhdr| \r\n
#### c1 http[ 0] | HTTP/1.1
#### c1 http[ 1] | 503
#### c1 http[ 2] | Service Unavailable
#### c1 http[ 3] | Server: Varnish
#### c1 http[ 4] | Retry-After: 0
#### c1 http[ 5] | Content-Type: text/html; charset=utf-8
#### c1 http[ 6] | Content-Length: 460
#### c1 http[ 7] | Date: Fri, 08 May 2009 16:53:31 GMT
#### c1 http[ 8] | X-Varnish: 1001
#### c1 http[ 9] | Age: 0
#### c1 http[10] | Via: 1.1 varnish
#### c1 http[11] | Connection: close
#### c1 body| \n
#### c1 body| <?xml version="1.0" encoding="utf-8"?>\n
#### c1 body| <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//
EN"\n
#### c1 body| "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">\n
#### c1 body| <html>\n
#### c1 body| <head>\n
#### c1 body| <title>503 Service Unavailable</title>\n
#### c1 body| </head>\n
#### c1 body| <body>\n
#### c1 body| <h1>Error 503 Service Unavailable</h1>\n
#### c1 body| <p>Service Unavailable</p>\n
#### c1 body| <h3>Guru Meditation:</h3>\n
#### c1 body| <p>XID: 1001</p>\n
#### c1 body| <address>\n
#### c1 body| <a href="http://www.varnish-
cache.org/">Varnish</a>\n
#### c1 body| </address>\n
#### c1 body| </body>\n
#### c1 body| </html>\n
#### c1 bodylen = 460
#### c1 EXPECT resp.status (503) == 503 (503) match
### c1 Closing fd 9
## c1 Ending
# top RESETTING after tests/r00387.vtc
## s1 Waiting for server
## v1 Stop
#### v1 CLI TX| stop
#### v1 debug| Stopping Child\n
#### v1 debug| Child (16970) ended\n
#### v1 debug| Child (-1) said EOF on CLI connection, exiting\n
#### v1 debug| Child cleanup complete\n
### v1 CLI STATUS 200
#### v1 CLI TX| status
#### v1 CLI RX| Child in state stopped
### v1 CLI STATUS 200
## v1 Wait
## v1 R 16947 Status: 0200
# top TEST tests/r00387.vtc completed
More information about the varnish-dev
mailing list