search

varnish / libvmod-curl

cURL Varnish bindings by Varnish Software
Other
48 stars 39 forks source link

Test suite errors #48

Closed lkarsten closed 5 years ago

lkarsten commented 6 years ago

On 0eb40eb6f8 , running make check on debian buster with libcurl 7.60 and varnish cache 6.0.1.

lkarsten@lima:~/work/libvmod-curl/src$ cat test-suite.log
============================================
   libvmod-curl 1.0.4: src/test-suite.log
============================================

# TOTAL: 15
# PASS:  13
# SKIP:  0
# XFAIL: 0
# FAIL:  2
# XPASS: 0
# ERROR: 0

.. contents:: :depth: 2

FAIL: tests/test11
==================

**** top   0.0 extmacro def pwd=/home/lkarsten/work/libvmod-curl/src
**** top   0.0 extmacro def vmod_topbuild=/home/lkarsten/work/libvmod-curl
**** top   0.0 extmacro def localhost=127.0.0.1
**** top   0.0 extmacro def bad_backend=127.0.0.1 45305
**** top   0.0 extmacro def bad_ip=192.0.2.255
**** top   0.0 macro def testdir=/home/lkarsten/work/libvmod-curl/src/./tests
**** top   0.0 macro def tmpdir=/tmp/vtc.7464.22f9888c
*    top   0.0 TEST ./tests/test11.vtc starting
**   top   0.0 === varnishtest "Test sub-second resolution timeouts"
*    top   0.0 TEST Test sub-second resolution timeouts
**   top   0.0 === server s1 -repeat 2 {
**   s1    0.0 Starting server
**** s1    0.0 macro def s1_addr=127.0.0.1
**** s1    0.0 macro def s1_port=45003
**** s1    0.0 macro def s1_sock=127.0.0.1 45003
*    s1    0.0 Listen on 127.0.0.1 45003
**   top   0.0 === varnish v1 -vcl+backend {
**   s1    0.0 Started on 127.0.0.1 45003
***  s1    0.0 Iteration 0
**   v1    0.0 Launch
***  v1    0.0 CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtc.7464.22f9888c/v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p sigsegv_handler=on -p thread_pool_min=10 -p debug=+vtc_mode -a '127.0.0.1:0' -M '127.0.0.1 39445' -P /tmp/vtc.7464.22f9888c/v1/varnishd.pid
***  v1    0.0 CMD: cd /home/lkarsten/work/libvmod-curl/src && exec varnishd  -d -n /tmp/vtc.7464.22f9888c/v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p sigsegv_handler=on -p thread_pool_min=10 -p debug=+vtc_mode -a '127.0.0.1:0' -M '127.0.0.1 39445' -P /tmp/vtc.7464.22f9888c/v1/varnishd.pid
***  v1    0.0 PID: 7481
**** v1    0.0 macro def v1_pid=7481
**** v1    0.0 macro def v1_name=/tmp/vtc.7464.22f9888c/v1
***  v1    0.0 debug|Debug: Version: varnish-6.0.1 revision 8d54bec5330c29304979ebf2c425ae14ab80493c
***  v1    0.0 debug|Debug: Platform: Linux,4.16.0-2-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
***  v1    0.0 debug|200 315
***  v1    0.0 debug|-----------------------------
***  v1    0.0 debug|Varnish Cache CLI 1.0
***  v1    0.0 debug|-----------------------------
***  v1    0.0 debug|Linux,4.16.0-2-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
***  v1    0.0 debug|varnish-6.0.1 revision 8d54bec5330c29304979ebf2c425ae14ab80493c
***  v1    0.0 debug|
***  v1    0.0 debug|Type 'help' for command list.
***  v1    0.0 debug|Type 'quit' to close CLI session.
***  v1    0.0 debug|Type 'start' to launch worker process.
***  v1    0.0 debug|
**** v1    0.1 CLIPOLL 1 0x1 0x0
***  v1    0.1 CLI connection fd = 7
***  v1    0.1 CLI RX  107
**** v1    0.1 CLI RX|rpeituqlqunlxahskxevgyyesnniuwbw
**** v1    0.1 CLI RX|
**** v1    0.1 CLI RX|Authentication required.
**** v1    0.1 CLI TX|auth 9215c157994d27d129654a56b670f4016ed2495aca4dd944d92f59dbc04615dd
***  v1    0.1 CLI RX  200
**** v1    0.1 CLI RX|-----------------------------
**** v1    0.1 CLI RX|Varnish Cache CLI 1.0
**** v1    0.1 CLI RX|-----------------------------
**** v1    0.1 CLI RX|Linux,4.16.0-2-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
**** v1    0.1 CLI RX|varnish-6.0.1 revision 8d54bec5330c29304979ebf2c425ae14ab80493c
**** v1    0.1 CLI RX|
**** v1    0.1 CLI RX|Type 'help' for command list.
**** v1    0.1 CLI RX|Type 'quit' to close CLI session.
**** v1    0.1 CLI RX|Type 'start' to launch worker process.
**** v1    0.1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1    0.1 CLI TX|vcl 4.1;
**** v1    0.1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "45003"; }
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|\timport curl from "/home/lkarsten/work/libvmod-curl/src/.libs/libvmod_curl.so";
**** v1    0.1 CLI TX|\timport std;
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|\tsub vcl_recv {
**** v1    0.1 CLI TX|\t\tif (req.url == "/") {
**** v1    0.1 CLI TX|\t\t\tcurl.set_timeout(200);
**** v1    0.1 CLI TX|\t\t\tcurl.set_connect_timeout(200);
**** v1    0.1 CLI TX|\t\t} else {
**** v1    0.1 CLI TX|\t\t\tcurl.set_timeout(1300);
**** v1    0.1 CLI TX|\t\t\tcurl.set_connect_timeout(1300);
**** v1    0.1 CLI TX|\t\t}
**** v1    0.1 CLI TX|\t\tstd.timestamp("curl:start");
**** v1    0.1 CLI TX|\t\tcurl.get("http://127.0.0.1:45003");
**** v1    0.1 CLI TX|\t\treturn (synth(200));
**** v1    0.1 CLI TX|\t}
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|\tsub vcl_synth {
**** v1    0.1 CLI TX|\t\tstd.timestamp("curl:end");
**** v1    0.1 CLI TX|\t\tset resp.http.x-status = curl.status();
**** v1    0.1 CLI TX|\t\tset resp.http.x-error = curl.error();
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|\t\t# Fix for RHEL5 old curl lib
**** v1    0.1 CLI TX|\t\tif (resp.http.x-error == "a timeout was reached") {
**** v1    0.1 CLI TX|\t\t\tset resp.http.x-error = "Timeout was reached";
**** v1    0.1 CLI TX|\t\t}
**** v1    0.1 CLI TX|\t}
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|%XJEIFLH|)Xspa8P
***  v1    0.2 vsl|No VSL chunk found (child not started ?)
***  v1    0.2 CLI RX  200
**** v1    0.2 CLI RX|VCL compiled.
**** v1    0.2 CLI TX|vcl.use vcl1
***  v1    0.2 CLI RX  200
**   v1    0.2 Start
**** v1    0.2 CLI TX|start
***  v1    0.3 debug|Debug: Child (7596) Started
***  v1    0.3 CLI RX  200
***  v1    0.3 wait-running
***  v1    0.3 debug|Info: Child (7596) said Child starts
**** v1    0.3 CLI TX|status
***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX|Child in state running
**** v1    0.4 CLI TX|debug.listen_address
***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX|127.0.0.1 33125
**** v1    0.4 CLI TX|debug.xid 999
**** v1    0.4 vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1540896990.670351982/vgc.so 1auto
**** v1    0.4 vsl|          0 CLI             - Wr 200 55 Loaded "vcl_vcl1.1540896990.670351982/vgc.so" as "vcl1"
**** v1    0.4 vsl|          0 CLI             - Rd vcl.use "vcl1"
**** v1    0.4 vsl|          0 CLI             - Wr 200 0
**** v1    0.4 vsl|          0 CLI             - Rd start
**** v1    0.4 vsl|          0 CLI             - Wr 200 0
**** v1    0.4 vsl|          0 CLI             - Rd debug.listen_address
**** v1    0.4 vsl|          0 CLI             - Wr 200 16 127.0.0.1 33125

***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX|XID is 999
**** v1    0.4 CLI TX|debug.listen_address
***  v1    0.5 CLI RX  200
**** v1    0.5 CLI RX|127.0.0.1 33125
**   v1    0.5 Listen on 127.0.0.1 33125
**** v1    0.5 macro def v1_addr=127.0.0.1
**** v1    0.5 macro def v1_port=33125
**** v1    0.5 macro def v1_sock=127.0.0.1 33125
**   top   0.5 === logexpect l1 -v v1 -g request {
**   l1    0.5 === expect * 1001    Timestamp   {curl:start: \S+ 0\.0\d+ 0\.\d+}
**   l1    0.5 === expect * =   Timestamp   {curl:end: \S+ 0\.2\d+ 0\.\d+}
**   l1    0.5 === expect * 1002    Timestamp   {curl:start: \S+ 0\.\d+ 0\.\d+}
**   l1    0.5 === expect * =   Timestamp   {curl:end: \S+ 1\.3\d+ 0\.\d+}
**   top   0.5 === client c1 {
**   c1    0.5 Starting client
**   c1    0.5 Waiting for client
**** l1    0.5 begin|
***  l1    0.5 expecting| expect * 1001 Timestamp curl:start: \\S+ 0\\.0\\d+ 0\\.\\d+
***  c1    0.5 Connect to 127.0.0.1 33125
***  c1    0.5 connected fd 22 from 127.0.0.1 33950 to 127.0.0.1 33125
**   c1    0.5 === txreq -url "/"
**** c1    0.5 txreq|GET / HTTP/1.1\r
**** c1    0.5 txreq|Host: 127.0.0.1\r
**** c1    0.5 txreq|\r
**   c1    0.5 === rxresp
***  s1    0.5 accepted fd 5 127.0.0.1 55092
**   s1    0.5 === rxreq
**** s1    0.5 rxhdr|GET / HTTP/1.1\r
**** s1    0.5 rxhdr|Host: 127.0.0.1:45003\r
**** s1    0.5 rxhdr|Accept: */*\r
**** s1    0.5 rxhdr|\r
**** s1    0.5 rxhdrlen = 54
**** s1    0.5 http[ 0] |GET
**** s1    0.5 http[ 1] |/
**** s1    0.5 http[ 2] |HTTP/1.1
**** s1    0.5 http[ 3] |Host: 127.0.0.1:45003
**** s1    0.5 http[ 4] |Accept: */*
**** s1    0.5 bodylen = 0
**   s1    0.5 === delay 2
***  s1    0.5 delaying 2 second(s)
**** v1    0.5 vsl|          0 CLI             - Rd debug.xid 999
**** v1    0.5 vsl|          0 CLI             - Wr 200 10 XID is 999
**** v1    0.5 vsl|          0 CLI             - Rd debug.listen_address
**** v1    0.5 vsl|          0 CLI             - Wr 200 16 127.0.0.1 33125

**** v1    0.5 vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    0.5 vsl|       1000 SessOpen        c 127.0.0.1 33950 a0 127.0.0.1 33125 1540896991.054139 20
**** v1    0.5 vsl|       1000 Link            c req 1001 rxreq
**** c1    0.7 rxhdr|HTTP/1.1 200 OK\r
**** c1    0.7 rxhdr|Date: Tue, 30 Oct 2018 10:56:31 GMT\r
**** c1    0.7 rxhdr|Server: Varnish\r
**** c1    0.7 rxhdr|X-Varnish: 1001\r
**** c1    0.7 rxhdr|x-status: 0\r
**** c1    0.7 rxhdr|x-error: Timeout was reached\r
**** c1    0.7 rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    0.7 rxhdr|Retry-After: 5\r
**** c1    0.7 rxhdr|Content-Length: 227\r
**** c1    0.7 rxhdr|Accept-Ranges: bytes\r
**** c1    0.7 rxhdr|Connection: keep-alive\r
**** c1    0.7 rxhdr|\r
**** c1    0.7 rxhdrlen = 256
**** c1    0.7 http[ 0] |HTTP/1.1
**** c1    0.7 http[ 1] |200
**** c1    0.7 http[ 2] |OK
**** c1    0.7 http[ 3] |Date: Tue, 30 Oct 2018 10:56:31 GMT
**** c1    0.7 http[ 4] |Server: Varnish
**** c1    0.7 http[ 5] |X-Varnish: 1001
**** c1    0.7 http[ 6] |x-status: 0
**** c1    0.7 http[ 7] |x-error: Timeout was reached
**** c1    0.7 http[ 8] |Content-Type: text/html; charset=utf-8
**** c1    0.7 http[ 9] |Retry-After: 5
**** c1    0.7 http[10] |Content-Length: 227
**** c1    0.7 http[11] |Accept-Ranges: bytes
**** c1    0.7 http[12] |Connection: keep-alive
**** c1    0.7 body|<!DOCTYPE html>
**** c1    0.7 body|<html>
**** c1    0.7 body|  <head>
**** c1    0.7 body|    <title>200 OK</title>
**** c1    0.7 body|  </head>
**** c1    0.7 body|  <body>
**** c1    0.7 body|    <h1>Error 200 OK</h1>
**** c1    0.7 body|    <p>OK</p>
**** c1    0.7 body|    <h3>Guru Meditation:</h3>
**** c1    0.7 body|    <p>XID: 1001</p>
**** c1    0.7 body|    <hr>
**** c1    0.7 body|    <p>Varnish cache server</p>
**** c1    0.7 body|  </body>
**** c1    0.7 body|</html>
**** c1    0.7 bodylen = 227
**   c1    0.7 === expect resp.http.x-status == 0
**** c1    0.7 EXPECT resp.http.x-status (0) == "0" match
**   c1    0.7 === expect resp.http.x-error == "Timeout was reached"
**** c1    0.7 EXPECT resp.http.x-error (Timeout was reached) == "Timeout was reached" match
**   c1    0.7 === txreq -url "/other"
**** c1    0.7 txreq|GET /other HTTP/1.1\r
**** c1    0.7 txreq|Host: 127.0.0.1\r
**** c1    0.7 txreq|\r
**   c1    0.7 === rxresp
**** l1    0.7 match|       1001 Timestamp       c curl:start: 1540896991.054185 0.000016 0.000016
***  l1    0.7 expecting| expect * = Timestamp curl:end: \\S+ 0\\.2\\d+ 0\\.\\d+
**** l1    0.7 match|       1001 Timestamp       c curl:end: 1540896991.254615 0.200446 0.000075
***  l1    0.7 expecting| expect * 1002 Timestamp curl:start: \\S+ 0\\.\\d+ 0\\.\\d+
**** v1    0.7 vsl|       1001 Begin           c req 1000 rxreq
**** v1    0.7 vsl|       1001 Timestamp       c Start: 1540896991.054169 0.000000 0.000000
**** v1    0.7 vsl|       1001 Timestamp       c Req: 1540896991.054169 0.000000 0.000000
**** v1    0.7 vsl|       1001 ReqStart        c 127.0.0.1 33950 a0
**** v1    0.7 vsl|       1001 ReqMethod       c GET
**** v1    0.7 vsl|       1001 ReqURL          c /
**** v1    0.7 vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    0.7 vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v1    0.7 vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    0.7 vsl|       1001 VCL_call        c RECV
**** v1    0.7 vsl|       1001 Timestamp       c curl:start: 1540896991.054185 0.000016 0.000016
**** v1    0.7 vsl|       1001 VCL_return      c synth
**** v1    0.7 vsl|       1001 VCL_call        c HASH
**** v1    0.7 vsl|       1001 VCL_return      c lookup
**** v1    0.7 vsl|       1001 Timestamp       c Process: 1540896991.254540 0.200371 0.200355
**** v1    0.7 vsl|       1001 RespHeader      c Date: Tue, 30 Oct 2018 10:56:31 GMT
**** v1    0.7 vsl|       1001 RespHeader      c Server: Varnish
**** v1    0.7 vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    0.7 vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    0.7 vsl|       1001 RespStatus      c 200
**** v1    0.7 vsl|       1001 RespReason      c OK
**** v1    0.7 vsl|       1001 RespReason      c OK
**** v1    0.7 vsl|       1001 VCL_call        c SYNTH
**** v1    0.7 vsl|       1001 Timestamp       c curl:end: 1540896991.254615 0.200446 0.000075
**** v1    0.7 vsl|       1001 RespHeader      c x-status: 0
**** v1    0.7 vsl|       1001 RespHeader      c x-error: Timeout was reached
**** v1    0.7 vsl|       1001 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    0.7 vsl|       1001 RespHeader      c Retry-After: 5
**** v1    0.7 vsl|       1001 VCL_return      c deliver
**** v1    0.7 vsl|       1001 RespHeader      c Content-Length: 227
**** v1    0.7 vsl|       1001 Storage         c malloc Transient
**** v1    0.7 vsl|       1001 RespHeader      c Accept-Ranges: bytes
**** v1    0.7 vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    0.7 vsl|       1001 Timestamp       c Resp: 1540896991.254711 0.200542 0.000096
**** v1    0.7 vsl|       1001 ReqAcct         c 35 0 35 256 227 483
**** v1    0.7 vsl|       1001 End             c
**** v1    0.7 vsl|       1000 Link            c req 1002 rxreq
**** c1    2.0 rxhdr|HTTP/1.1 200 OK\r
**** c1    2.0 rxhdr|Date: Tue, 30 Oct 2018 10:56:32 GMT\r
**** c1    2.0 rxhdr|Server: Varnish\r
**** c1    2.0 rxhdr|X-Varnish: 1002\r
**** c1    2.0 rxhdr|x-status: 0\r
**** c1    2.0 rxhdr|x-error: Timeout was reached\r
**** c1    2.0 rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    2.0 rxhdr|Retry-After: 5\r
**** c1    2.0 rxhdr|Content-Length: 227\r
**** c1    2.0 rxhdr|Accept-Ranges: bytes\r
**** c1    2.0 rxhdr|Connection: keep-alive\r
**** c1    2.0 rxhdr|\r
**** c1    2.0 rxhdrlen = 256
**** c1    2.0 http[ 0] |HTTP/1.1
**** c1    2.0 http[ 1] |200
**** c1    2.0 http[ 2] |OK
**** c1    2.0 http[ 3] |Date: Tue, 30 Oct 2018 10:56:32 GMT
**** c1    2.0 http[ 4] |Server: Varnish
**** c1    2.0 http[ 5] |X-Varnish: 1002
**** c1    2.0 http[ 6] |x-status: 0
**** c1    2.0 http[ 7] |x-error: Timeout was reached
**** c1    2.0 http[ 8] |Content-Type: text/html; charset=utf-8
**** c1    2.0 http[ 9] |Retry-After: 5
**** c1    2.0 http[10] |Content-Length: 227
**** c1    2.0 http[11] |Accept-Ranges: bytes
**** c1    2.0 http[12] |Connection: keep-alive
**** c1    2.0 body|<!DOCTYPE html>
**** c1    2.0 body|<html>
**** c1    2.0 body|  <head>
**** c1    2.0 body|    <title>200 OK</title>
**** c1    2.0 body|  </head>
**** c1    2.0 body|  <body>
**** c1    2.0 body|    <h1>Error 200 OK</h1>
**** c1    2.0 body|    <p>OK</p>
**** c1    2.0 body|    <h3>Guru Meditation:</h3>
**** c1    2.0 body|    <p>XID: 1002</p>
**** c1    2.0 body|    <hr>
**** c1    2.0 body|    <p>Varnish cache server</p>
**** c1    2.0 body|  </body>
**** c1    2.0 body|</html>
**** c1    2.0 bodylen = 227
**   c1    2.0 === expect resp.http.x-status == 0
**** c1    2.0 EXPECT resp.http.x-status (0) == "0" match
**   c1    2.0 === expect resp.http.x-error == "Timeout was reached"
**** c1    2.0 EXPECT resp.http.x-error (Timeout was reached) == "Timeout was reached" match
***  c1    2.0 closing fd 22
**   c1    2.0 Ending
**   top   2.0 === logexpect l1 -wait
**   l1    2.0 Waiting for logexp
**** l1    2.0 match|       1002 Timestamp       c curl:start: 1540896991.255019 0.000012 0.000012
***  l1    2.0 expecting| expect * = Timestamp curl:end: \\S+ 1\\.3\\d+ 0\\.\\d+
**** v1    2.0 vsl|       1002 Begin           c req 1000 rxreq
**** v1    2.0 vsl|       1002 Timestamp       c Start: 1540896991.255007 0.000000 0.000000
**** v1    2.0 vsl|       1002 Timestamp       c Req: 1540896991.255007 0.000000 0.000000
**** v1    2.0 vsl|       1002 ReqStart        c 127.0.0.1 33950 a0
**** v1    2.0 vsl|       1002 ReqMethod       c GET
**** v1    2.0 vsl|       1002 ReqURL          c /other
**** v1    2.0 vsl|       1002 ReqProtocol     c HTTP/1.1
**** v1    2.0 vsl|       1002 ReqHeader       c Host: 127.0.0.1
**** v1    2.0 vsl|       1002 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    2.0 vsl|       1002 VCL_call        c RECV
**** v1    2.0 vsl|       1002 Timestamp       c curl:start: 1540896991.255019 0.000012 0.000012
**** v1    2.0 vsl|       1002 VCL_return      c synth
**** v1    2.0 vsl|       1002 VCL_call        c HASH
**** v1    2.0 vsl|       1002 VCL_return      c lookup
**** v1    2.0 vsl|       1002 Timestamp       c Process: 1540896992.554575 1.299568 1.299556
**** v1    2.0 vsl|       1002 RespHeader      c Date: Tue, 30 Oct 2018 10:56:32 GMT
**** v1    2.0 vsl|       1002 RespHeader      c Server: Varnish
**** v1    2.0 vsl|       1002 RespHeader      c X-Varnish: 1002
**** v1    2.0 vsl|       1002 RespProtocol    c HTTP/1.1
**** v1    2.0 vsl|       1002 RespStatus      c 200
**** v1    2.0 vsl|       1002 RespReason      c OK
**** v1    2.0 vsl|       1002 RespReason      c OK
**** v1    2.0 vsl|       1002 VCL_call        c SYNTH
**** v1    2.0 vsl|       1002 Timestamp       c curl:end: 1540896992.554598 1.299591 0.000023
**** v1    2.0 vsl|       1002 RespHeader      c x-status: 0
**** v1    2.0 vsl|       1002 RespHeader      c x-error: Timeout was reached
**** v1    2.0 vsl|       1002 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    2.0 vsl|       1002 RespHeader      c Retry-After: 5
**** v1    2.0 vsl|       1002 VCL_return      c deliver
**** v1    2.0 vsl|       1002 RespHeader      c Content-Length: 227
**** v1    2.0 vsl|       1002 Storage         c malloc Transient
**** v1    2.0 vsl|       1002 RespHeader      c Accept-Ranges: bytes
**** v1    2.0 vsl|       1002 RespHeader      c Connection: keep-alive
**** v1    2.0 vsl|       1002 Timestamp       c Resp: 1540896992.554680 1.299673 0.000082
**** v1    2.0 vsl|       1002 ReqAcct         c 40 0 40 256 227 483
**** v1    2.0 vsl|       1002 End             c
**** v1    2.0 vsl|       1000 SessClose       c REM_CLOSE 1.501
**** v1    2.0 vsl|       1000 End             c
**   s1    2.5 === txresp -hdr "Foo: bar"
**** s1    2.5 txresp|HTTP/1.1 200 OK\r
**** s1    2.5 txresp|Foo: bar\r
**** s1    2.5 txresp|Content-Length: 0\r
**** s1    2.5 txresp|\r
***  s1    2.5 shutting fd 5
***  s1    2.5 Iteration 1
***  s1    2.5 accepted fd 5 127.0.0.1 55112
**   s1    2.5 === rxreq
**** s1    2.5 rxhdr|GET / HTTP/1.1\r
**** s1    2.5 rxhdr|Host: 127.0.0.1:45003\r
**** s1    2.5 rxhdr|Accept: */*\r
**** s1    2.5 rxhdr|\r
**** s1    2.5 rxhdrlen = 54
**** s1    2.5 http[ 0] |GET
**** s1    2.5 http[ 1] |/
**** s1    2.5 http[ 2] |HTTP/1.1
**** s1    2.5 http[ 3] |Host: 127.0.0.1:45003
**** s1    2.5 http[ 4] |Accept: */*
**** s1    2.5 bodylen = 0
**   s1    2.5 === delay 2
***  s1    2.5 delaying 2 second(s)
**** v1    3.3 vsl|          0 CLI             - Rd ping
**** v1    3.3 vsl|          0 CLI             - Wr 200 19 PONG 1540896993 1.0
**   s1    4.5 === txresp -hdr "Foo: bar"
**** s1    4.5 txresp|HTTP/1.1 200 OK\r
**** s1    4.5 txresp|Foo: bar\r
**** s1    4.5 txresp|Content-Length: 0\r
**** s1    4.5 txresp|\r
***  s1    4.5 shutting fd 5
**   s1    4.5 Ending
**** v1    6.3 vsl|          0 CLI             - Rd ping
**** v1    6.3 vsl|          0 CLI             - Wr 200 19 PONG 1540896996 1.0
**** v1    9.3 vsl|          0 CLI             - Rd ping
**** v1    9.3 vsl|          0 CLI             - Wr 200 19 PONG 1540896999 1.0
**** v1   12.3 vsl|          0 CLI             - Rd ping
**** v1   12.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897002 1.0
**** v1   15.3 vsl|          0 CLI             - Rd ping
**** v1   15.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897005 1.0
**** v1   18.3 vsl|          0 CLI             - Rd ping
**** v1   18.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897008 1.0
**** v1   21.3 vsl|          0 CLI             - Rd ping
**** v1   21.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897011 1.0
**** v1   24.3 vsl|          0 CLI             - Rd ping
**** v1   24.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897014 1.0
**** v1   27.3 vsl|          0 CLI             - Rd ping
**** v1   27.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897017 1.0
**** v1   30.3 vsl|          0 CLI             - Rd ping
**** v1   30.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897020 1.0
**** v1   33.3 vsl|          0 CLI             - Rd ping
**** v1   33.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897023 1.0
**** v1   36.3 vsl|          0 CLI             - Rd ping
**** v1   36.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897026 1.0
**** v1   39.3 vsl|          0 CLI             - Rd ping
**** v1   39.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897029 1.0
**** v1   42.3 vsl|          0 CLI             - Rd ping
**** v1   42.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897032 1.0
**** v1   45.3 vsl|          0 CLI             - Rd ping
**** v1   45.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897035 1.0
**** v1   48.3 vsl|          0 CLI             - Rd ping
**** v1   48.3 vsl|          0 CLI             - Wr 200 19 PONG 1540897038 1.0
**** v1   51.4 vsl|          0 CLI             - Rd ping
**** v1   51.4 vsl|          0 CLI             - Wr 200 19 PONG 1540897041 1.0
**** v1   54.4 vsl|          0 CLI             - Rd ping
**** v1   54.4 vsl|          0 CLI             - Wr 200 19 PONG 1540897044 1.0
**** v1   57.4 vsl|          0 CLI             - Rd ping
**** v1   57.4 vsl|          0 CLI             - Wr 200 19 PONG 1540897047 1.0
#    top  TEST ./tests/test11.vtc TIMED OUT (kill -9)
#    top  TEST ./tests/test11.vtc FAILED (60.060) signal=9
FAIL tests/test11.vtc (exit status: 2)

FAIL: tests/test15
==================

**** top   0.0 extmacro def pwd=/home/lkarsten/work/libvmod-curl/src
**** top   0.0 extmacro def vmod_topbuild=/home/lkarsten/work/libvmod-curl
**** top   0.0 extmacro def localhost=127.0.0.1
**** top   0.0 extmacro def bad_backend=127.0.0.1 39945
**** top   0.0 extmacro def bad_ip=192.0.2.255
**** top   0.0 macro def testdir=/home/lkarsten/work/libvmod-curl/src/./tests
**** top   0.0 macro def tmpdir=/tmp/vtc.7522.7ef90f72
*    top   0.0 TEST ./tests/test15.vtc starting
**   top   0.0 === varnishtest "test curl.error"
*    top   0.0 TEST test curl.error
**   top   0.0 === server s1 {
**   s1    0.0 Starting server
**** s1    0.0 macro def s1_addr=127.0.0.1
**** s1    0.0 macro def s1_port=33911
**** s1    0.0 macro def s1_sock=127.0.0.1 33911
*    s1    0.0 Listen on 127.0.0.1 33911
**   top   0.0 === varnish v1 -vcl+backend {
**   s1    0.0 Started on 127.0.0.1 33911
**   v1    0.0 Launch
***  v1    0.0 CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtc.7522.7ef90f72/v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p sigsegv_handler=on -p thread_pool_min=10 -p debug=+vtc_mode -a '127.0.0.1:0' -M '127.0.0.1 37659' -P /tmp/vtc.7522.7ef90f72/v1/varnishd.pid
***  v1    0.0 CMD: cd /home/lkarsten/work/libvmod-curl/src && exec varnishd  -d -n /tmp/vtc.7522.7ef90f72/v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p sigsegv_handler=on -p thread_pool_min=10 -p debug=+vtc_mode -a '127.0.0.1:0' -M '127.0.0.1 37659' -P /tmp/vtc.7522.7ef90f72/v1/varnishd.pid
***  v1    0.0 PID: 7533
**** v1    0.0 macro def v1_pid=7533
**** v1    0.0 macro def v1_name=/tmp/vtc.7522.7ef90f72/v1
***  v1    0.0 debug|Debug: Version: varnish-6.0.1 revision 8d54bec5330c29304979ebf2c425ae14ab80493c
***  v1    0.0 debug|Debug: Platform: Linux,4.16.0-2-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
***  v1    0.0 debug|200 315
***  v1    0.0 debug|-----------------------------
***  v1    0.0 debug|Varnish Cache CLI 1.0
***  v1    0.0 debug|-----------------------------
***  v1    0.0 debug|Linux,4.16.0-2-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
***  v1    0.0 debug|varnish-6.0.1 revision 8d54bec5330c29304979ebf2c425ae14ab80493c
***  v1    0.0 debug|
***  v1    0.0 debug|Type 'help' for command list.
***  v1    0.0 debug|Type 'quit' to close CLI session.
***  v1    0.0 debug|Type 'start' to launch worker process.
***  v1    0.0 debug|
**** v1    0.1 CLIPOLL 1 0x1 0x0
***  v1    0.1 CLI connection fd = 7
***  v1    0.1 CLI RX  107
**** v1    0.1 CLI RX|xapxdctstvgdrzbwhmbnomdmhjucqing
**** v1    0.1 CLI RX|
**** v1    0.1 CLI RX|Authentication required.
**** v1    0.1 CLI TX|auth 2b49ea429e6fa343b9ea1a1a165c5aaf00c153806642381c0cd3af66e80c8ae1
***  v1    0.1 CLI RX  200
**** v1    0.1 CLI RX|-----------------------------
**** v1    0.1 CLI RX|Varnish Cache CLI 1.0
**** v1    0.1 CLI RX|-----------------------------
**** v1    0.1 CLI RX|Linux,4.16.0-2-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
**** v1    0.1 CLI RX|varnish-6.0.1 revision 8d54bec5330c29304979ebf2c425ae14ab80493c
**** v1    0.1 CLI RX|
**** v1    0.1 CLI RX|Type 'help' for command list.
**** v1    0.1 CLI RX|Type 'quit' to close CLI session.
**** v1    0.1 CLI RX|Type 'start' to launch worker process.
**** v1    0.1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1    0.1 CLI TX|vcl 4.1;
**** v1    0.1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "33911"; }
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|\timport curl from "/home/lkarsten/work/libvmod-curl/src/.libs/libvmod_curl.so";
**** v1    0.1 CLI TX|\timport std;
**** v1    0.1 CLI TX|\tsub vcl_deliver {
**** v1    0.1 CLI TX|\t\tcurl.set_timeout(1000);
**** v1    0.1 CLI TX|\t\tcurl.get("http://127.0.0.1:33911/");
**** v1    0.1 CLI TX|\t\tif (curl.error()) {
**** v1    0.1 CLI TX|\t\t\tstd.log("curl error1 is: '" + curl.error() + "'");
**** v1    0.1 CLI TX|\t\t\treturn(synth(500, "curlerror1: " + curl.error()));
**** v1    0.1 CLI TX|\t\t}
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|\t\tcurl.get("http://localhost:65500");
**** v1    0.1 CLI TX|\t\tif (curl.error()) {
**** v1    0.1 CLI TX|\t\t\tstd.log("curl error2 is: '" + curl.error() + "'");
**** v1    0.1 CLI TX|\t\t\treturn(synth(500, "curlerror2: " + curl.error()));
**** v1    0.1 CLI TX|\t\t}
**** v1    0.1 CLI TX|\t}
**** v1    0.1 CLI TX|
**** v1    0.1 CLI TX|%XJEIFLH|)Xspa8P
***  v1    0.2 vsl|No VSL chunk found (child not started ?)
***  v1    0.3 CLI RX  200
**** v1    0.3 CLI RX|VCL compiled.
**** v1    0.3 CLI TX|vcl.use vcl1
***  v1    0.3 CLI RX  200
**   v1    0.3 Start
**** v1    0.3 CLI TX|start
***  v1    0.3 debug|Debug: Child (7716) Started
***  v1    0.3 CLI RX  200
***  v1    0.3 wait-running
**** v1    0.3 CLI TX|status
***  v1    0.3 debug|Info: Child (7716) said Child starts
***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX|Child in state running
**** v1    0.4 CLI TX|debug.listen_address
***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX|127.0.0.1 42235
**** v1    0.4 CLI TX|debug.xid 999
**** v1    0.4 vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1540896990.754279613/vgc.so 1auto
**** v1    0.4 vsl|          0 CLI             - Wr 200 55 Loaded "vcl_vcl1.1540896990.754279613/vgc.so" as "vcl1"
**** v1    0.4 vsl|          0 CLI             - Rd vcl.use "vcl1"
**** v1    0.4 vsl|          0 CLI             - Wr 200 0
**** v1    0.4 vsl|          0 CLI             - Rd start
**** v1    0.4 vsl|          0 CLI             - Wr 200 0
**** v1    0.4 vsl|          0 CLI             - Rd debug.listen_address
**** v1    0.4 vsl|          0 CLI             - Wr 200 16 127.0.0.1 42235

***  v1    0.5 CLI RX  200
**** v1    0.5 CLI RX|XID is 999
**** v1    0.5 CLI TX|debug.listen_address
***  v1    0.5 CLI RX  200
**** v1    0.5 CLI RX|127.0.0.1 42235
**   v1    0.5 Listen on 127.0.0.1 42235
**** v1    0.5 macro def v1_addr=127.0.0.1
**** v1    0.5 macro def v1_port=42235
**** v1    0.5 macro def v1_sock=127.0.0.1 42235
**   top   0.5 === client c1 {
**   top   0.5 === client c1 -run
**   c1    0.5 Starting client
**   c1    0.5 Waiting for client
***  c1    0.5 Connect to 127.0.0.1 42235
***  c1    0.5 connected fd 17 from 127.0.0.1 57222 to 127.0.0.1 42235
**   c1    0.5 === txreq -url "/"
**** c1    0.5 txreq|GET / HTTP/1.1\r
**** c1    0.5 txreq|Host: 127.0.0.1\r
**** c1    0.5 txreq|\r
**   c1    0.5 === rxresp
***  s1    0.5 accepted fd 5 127.0.0.1 48336
**   s1    0.5 === rxreq
**** s1    0.5 rxhdr|GET / HTTP/1.1\r
**** s1    0.5 rxhdr|Host: 127.0.0.1\r
**** s1    0.5 rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    0.5 rxhdr|Accept-Encoding: gzip\r
**** s1    0.5 rxhdr|X-Varnish: 1002\r
**** s1    0.5 rxhdr|\r
**** s1    0.5 rxhdrlen = 103
**** s1    0.5 http[ 0] |GET
**** s1    0.5 http[ 1] |/
**** s1    0.5 http[ 2] |HTTP/1.1
**** s1    0.5 http[ 3] |Host: 127.0.0.1
**** s1    0.5 http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    0.5 http[ 5] |Accept-Encoding: gzip
**** s1    0.5 http[ 6] |X-Varnish: 1002
**** s1    0.5 bodylen = 0
**   s1    0.5 === txresp
**** s1    0.5 txresp|HTTP/1.1 200 OK\r
**** s1    0.5 txresp|Content-Length: 0\r
**** s1    0.5 txresp|\r
***  s1    0.5 shutting fd 5
**   s1    0.5 Ending
**** v1    0.5 vsl|          0 CLI             - Rd debug.xid 999
**** v1    0.5 vsl|          0 CLI             - Wr 200 10 XID is 999
**** v1    0.5 vsl|          0 CLI             - Rd debug.listen_address
**** v1    0.5 vsl|          0 CLI             - Wr 200 16 127.0.0.1 42235

**** v1    0.5 vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    0.5 vsl|       1000 SessOpen        c 127.0.0.1 57222 a0 127.0.0.1 42235 1540896991.142046 20
**** v1    0.5 vsl|       1000 Link            c req 1001 rxreq
**** v1    0.5 vsl|          0 ExpKill         - EXP_Inbox flg=1e p=0x7f754a0110c0 e=0.000000000 f=0x0
**** v1    0.5 vsl|          0 ExpKill         - EXP_When p=0x7f754a0110c0 e=1540897121.142591715 f=0x1e
**** v1    0.5 vsl|          0 ExpKill         - EXP_expire p=0x7f754a0110c0 e=129.999913931 f=0x0
**** v1    0.5 vsl|       1002 Begin           b bereq 1001 fetch
**** v1    0.5 vsl|       1002 Timestamp       b Start: 1540896991.142112 0.000000 0.000000
**** v1    0.5 vsl|       1002 BereqMethod     b GET
**** v1    0.5 vsl|       1002 BereqURL        b /
**** v1    0.5 vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    0.5 vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v1    0.5 vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    0.5 vsl|       1002 BereqHeader     b Accept-Encoding: gzip
**** v1    0.5 vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v1    0.5 vsl|       1002 VCL_call        b BACKEND_FETCH
**** v1    0.5 vsl|       1002 VCL_return      b fetch
**** v1    0.5 vsl|       1002 BackendOpen     b 26 vcl1.s1 127.0.0.1 33911 127.0.0.1 48336
**** v1    0.5 vsl|       1002 BackendStart    b 127.0.0.1 33911
**** v1    0.5 vsl|       1002 Timestamp       b Bereq: 1540896991.142457 0.000346 0.000346
**** v1    0.5 vsl|       1002 Timestamp       b Beresp: 1540896991.142592 0.000480 0.000134
**** v1    0.5 vsl|       1002 BerespProtocol  b HTTP/1.1
**** v1    0.5 vsl|       1002 BerespStatus    b 200
**** v1    0.5 vsl|       1002 BerespReason    b OK
**** v1    0.5 vsl|       1002 BerespHeader    b Content-Length: 0
**** v1    0.5 vsl|       1002 BerespHeader    b Date: Tue, 30 Oct 2018 10:56:31 GMT
**** v1    0.5 vsl|       1002 TTL             b RFC 120 10 0 1540896991 1540896991 1540896991 0 0 cacheable
**** v1    0.5 vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** v1    0.5 vsl|       1002 VCL_return      b deliver
**** v1    0.5 vsl|       1002 Storage         b malloc s0
**** v1    0.5 vsl|       1002 Fetch_Body      b 0 none -
**** v1    0.5 vsl|       1002 BackendReuse    b 26 vcl1.s1
**** v1    0.5 vsl|       1002 Timestamp       b BerespBody: 1540896991.152730 0.010619 0.010139
**** v1    0.5 vsl|       1002 Length          b 0
**** v1    0.5 vsl|       1002 BereqAcct       b 103 0 103 38 0 38
**** v1    0.5 vsl|       1002 End             b
**** c1    1.5 rxhdr|HTTP/1.1 500 curlerror1: Timeout was reached\r
**** c1    1.5 rxhdr|Date: Tue, 30 Oct 2018 10:56:32 GMT\r
**** c1    1.5 rxhdr|Server: Varnish\r
**** c1    1.5 rxhdr|X-Varnish: 1001\r
**** c1    1.5 rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    1.5 rxhdr|Retry-After: 5\r
**** c1    1.5 rxhdr|Content-Length: 314\r
**** c1    1.5 rxhdr|Connection: keep-alive\r
**** c1    1.5 rxhdr|\r
**** c1    1.5 rxhdrlen = 220
**** c1    1.5 http[ 0] |HTTP/1.1
**** c1    1.5 http[ 1] |500
**** c1    1.5 http[ 2] |curlerror1: Timeout was reached
**** c1    1.5 http[ 3] |Date: Tue, 30 Oct 2018 10:56:32 GMT
**** c1    1.5 http[ 4] |Server: Varnish
**** c1    1.5 http[ 5] |X-Varnish: 1001
**** c1    1.5 http[ 6] |Content-Type: text/html; charset=utf-8
**** c1    1.5 http[ 7] |Retry-After: 5
**** c1    1.5 http[ 8] |Content-Length: 314
**** c1    1.5 http[ 9] |Connection: keep-alive
**** c1    1.5 body|<!DOCTYPE html>
**** c1    1.5 body|<html>
**** c1    1.5 body|  <head>
**** c1    1.5 body|    <title>500 curlerror1: Timeout was reached</title>
**** c1    1.5 body|  </head>
**** c1    1.5 body|  <body>
**** c1    1.5 body|    <h1>Error 500 curlerror1: Timeout was reached</h1>
**** c1    1.5 body|    <p>curlerror1: Timeout was reached</p>
**** c1    1.5 body|    <h3>Guru Meditation:</h3>
**** c1    1.5 body|    <p>XID: 1001</p>
**** c1    1.5 body|    <hr>
**** c1    1.5 body|    <p>Varnish cache server</p>
**** c1    1.5 body|  </body>
**** c1    1.5 body|</html>
**** c1    1.5 bodylen = 314
**   c1    1.5 === expect resp.status == 200
---- c1    1.5 EXPECT resp.status (500) == "200" failed
*    top   1.5 RESETTING after ./tests/test15.vtc
**   s1    1.5 Waiting for server (4/-1)
**   v1    1.5 Wait
**** v1    1.5 CLI TX|panic.clear
**** v1    1.5 vsl|       1001 Begin           c req 1000 rxreq
**** v1    1.5 vsl|       1001 Timestamp       c Start: 1540896991.142074 0.000000 0.000000
**** v1    1.5 vsl|       1001 Timestamp       c Req: 1540896991.142074 0.000000 0.000000
**** v1    1.5 vsl|       1001 ReqStart        c 127.0.0.1 57222 a0
**** v1    1.5 vsl|       1001 ReqMethod       c GET
**** v1    1.5 vsl|       1001 ReqURL          c /
**** v1    1.5 vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    1.5 vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v1    1.5 vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    1.5 vsl|       1001 VCL_call        c RECV
**** v1    1.5 vsl|       1001 VCL_return      c hash
**** v1    1.5 vsl|       1001 VCL_call        c HASH
**** v1    1.5 vsl|       1001 VCL_return      c lookup
**** v1    1.5 vsl|       1001 VCL_call        c MISS
**** v1    1.5 vsl|       1001 VCL_return      c fetch
**** v1    1.5 vsl|       1001 Link            c bereq 1002 fetch
**** v1    1.5 vsl|       1001 Timestamp       c Fetch: 1540896991.152736 0.010662 0.010662
**** v1    1.5 vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    1.5 vsl|       1001 RespStatus      c 200
**** v1    1.5 vsl|       1001 RespReason      c OK
**** v1    1.5 vsl|       1001 RespHeader      c Content-Length: 0
**** v1    1.5 vsl|       1001 RespHeader      c Date: Tue, 30 Oct 2018 10:56:31 GMT
**** v1    1.5 vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    1.5 vsl|       1001 RespHeader      c Age: 0
**** v1    1.5 vsl|       1001 RespHeader      c Via: 1.1 varnish (Varnish/6.0)
**** v1    1.5 vsl|       1001 VCL_call        c DELIVER
**** v1    1.5 vsl|       1001 VCL_Log         c curl error1 is: 'Timeout was reached'
**** v1    1.5 vsl|       1001 VCL_return      c synth
**** v1    1.5 vsl|       1001 Timestamp       c Process: 1540896992.153479 1.011405 1.000743
**** v1    1.5 vsl|       1001 Timestamp       c Process: 1540896992.153493 1.011419 0.000015
**** v1    1.5 vsl|       1001 RespHeader      c Date: Tue, 30 Oct 2018 10:56:32 GMT
**** v1    1.5 vsl|       1001 RespHeader      c Server: Varnish
**** v1    1.5 vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    1.5 vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    1.5 vsl|       1001 RespStatus      c 500
**** v1    1.5 vsl|       1001 RespReason      c Internal Server Error
**** v1    1.5 vsl|       1001 RespReason      c curlerror1: Timeout was reached
**** v1    1.5 vsl|       1001 VCL_call        c SYNTH
**** v1    1.5 vsl|       1001 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    1.5 vsl|       1001 RespHeader      c Retry-After: 5
**** v1    1.5 vsl|       1001 VCL_return      c deliver
**** v1    1.5 vsl|       1001 RespHeader      c Content-Length: 314
**** v1    1.5 vsl|       1001 Storage         c malloc Transient
**** v1    1.5 vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    1.5 vsl|       1001 Timestamp       c Resp: 1540896992.153597 1.011523 0.000104
**** v1    1.5 vsl|       1001 ReqAcct         c 35 0 35 220 314 534
**** v1    1.5 vsl|       1001 End             c
***  v1    1.6 CLI RX  300
**** v1    1.6 CLI RX|No panic to clear
***  v1    1.6 debug|Info: manager stopping child
***  v1    1.6 debug|Debug: Stopping Child
**** v1    1.6 vsl|          0 CLI             - EOF on CLI connection, worker stops
***  v1    2.6 debug|Info: Child (7716) ended
***  v1    2.6 debug|Info: Child (7716) said Child dies
***  v1    2.6 debug|Debug: Child cleanup complete
***  v1    2.6 debug|Info: manager dies
**** v1    2.6 STDOUT poll 0x10
**   v1    2.6 WAIT4 pid=7533 status=0x0000 (user 0.133956 sys 0.038034)
*    top   2.6 TEST ./tests/test15.vtc FAILED
#    top  TEST ./tests/test15.vtc FAILED (2.611) exit=2
FAIL tests/test15.vtc (exit status: 2)
dridi commented 5 years ago

Is this still happening? I just tried with libcurl/7.61.1 on Fedora and the test suite is passing. I can try later on Debian if the answer is yes.

If it fails, is it systematic or maybe a flaky test instead?

lkarsten commented 5 years ago

For my part this has been overtaken by external events.

dridi commented 5 years ago

test11.vtc is flaky, it failed once: I'm running time while make -sj32 check VERBOSE=1; do sleep 3; done and let you know how much time it took to trigger a test15.vtc failure if it eventually does.

dridi commented 5 years ago

Oh, I didn't see you closed the ticket until I last commented, alright then.

Feel free to reopen if it becomes relevant again.