[Varnish] #1451: p00009.vtc is fragile
Varnish
varnish-bugs at varnish-cache.org
Mon Mar 17 13:23:33 CET 2014
#1451: p00009.vtc is fragile
-------------------------+-------------------
Reporter: lkarsten | Owner:
Type: defect | Status: new
Priority: normal | Milestone:
Component: varnishtest | Version: trunk
Severity: minor | Keywords:
-------------------------+-------------------
p00009.vtc failed after a documentation commit just now. (793d67ad)
Make check works fine on my clean tree.
{{{
FAIL: tests/p00009.vtc (exit: 2)
================================
**** top 0.0 macro def varnishd=varnishd
**** top 0.0 macro def varnishadm=varnishadm
**** top 0.0 macro def varnishstat=varnishstat
**** top 0.0 macro def varnishhist=varnishhist
**** top 0.0 macro def varnishlog=varnishlog
**** top 0.0 macro def varnishncsa=varnishncsa
**** top 0.0 macro def vmod_std=std from "/var/lib/jenkins/jobs/varnish-
master-
src/workspace/varnish-4.0.0-tp2/_build/lib/libvmod_std/.libs/libvmod_std.so"
**** top 0.0 macro def vmod_debug=debug from "/var/lib/jenkins/jobs
/varnish-master-
src/workspace/varnish-4.0.0-tp2/_build/lib/libvmod_debug/.libs/libvmod_debug.so"
**** top 0.0 macro def vmod_directors=directors from
"/var/lib/jenkins/jobs/varnish-master-
src/workspace/varnish-4.0.0-tp2/_build/lib/libvmod_directors/.libs/libvmod_directors.so"
**** top 0.0 macro def pwd=/var/lib/jenkins/jobs/varnish-master-
src/workspace/varnish-4.0.0-tp2/_build/bin/varnishtest
**** top 0.0 macro def topbuild=/var/lib/jenkins/jobs/varnish-master-
src/workspace/varnish-4.0.0-tp2/_build
**** top 0.0 macro def bad_ip=192.0.2.255
**** top 0.0 macro def tmpdir=/tmp/vtc.8405.4fdaaca5
* top 0.0 TEST ../../../bin/varnishtest/tests/p00009.vtc starting
*** top 0.0 varnishtest
* top 0.0 TEST Check that reloaded bans with completed flag are
really completed on restart
*** top 0.0 shell
**** top 0.0 shell| rm -f /tmp/vtc.8405.4fdaaca5/_.per[12]
*** top 0.0 server
** s1 0.0 Starting server
**** s1 0.0 macro def s1_addr=127.0.0.1
**** s1 0.0 macro def s1_port=42265
**** s1 0.0 macro def s1_sock=127.0.0.1 42265
* s1 0.0 Listen on 127.0.0.1 42265
*** top 0.0 varnish
** s1 0.0 Started on 127.0.0.1 42265
** v1 0.0 Launch
*** v1 0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n
/tmp/vtc.8405.4fdaaca5/v1 -l 2m,1m,- -p auto_restart=off -p
syslog_cli_traffic=off -p sigsegv_handler=on -a '127.0.0.1:0' -M
'127.0.0.1 54701' -P /tmp/vtc.8405.4fdaaca5/v1/varnishd.pid
-pfeature=+wait_silo -pban_lurker_sleep=0
-sper1=persistent,/tmp/vtc.8405.4fdaaca5/_.per1,10m
-sper2=persistent,/tmp/vtc.8405.4fdaaca5/_.per2,10m
*** v1 0.0 CMD: cd /var/lib/jenkins/jobs/varnish-master-
src/workspace/varnish-4.0.0-tp2/_build/bin/varnishtest && varnishd -d -d
-n /tmp/vtc.8405.4fdaaca5/v1 -l 2m,1m,- -p auto_restart=off -p
syslog_cli_traffic=off -p sigsegv_handler=on -a '127.0.0.1:0' -M
'127.0.0.1 54701' -P /tmp/vtc.8405.4fdaaca5/v1/varnishd.pid
-pfeature=+wait_silo -pban_lurker_sleep=0
-sper1=persistent,/tmp/vtc.8405.4fdaaca5/_.per1,10m
-sper2=persistent,/tmp/vtc.8405.4fdaaca5/_.per2,10m
*** v1 0.0 PID: 8447
*** v1 0.0 debug| sizeof(struct smp_ident) = 112 = 0x70\n
*** v1 0.0 debug| sizeof(struct smp_sign) = 32 = 0x20\n
*** v1 0.0 debug| sizeof(struct smp_segptr) = 32 = 0x20\n
*** v1 0.0 debug| sizeof(struct smp_object) = 56 = 0x38\n
*** v1 0.0 debug| CHK(0x24b7a58 SILO 0x2b38f0420000 <invalid>) = 1\n
*** v1 0.0 debug| Warning SILO (/tmp/vtc.8405.4fdaaca5/_.per1) not
reloaded (reason=1)\n
*** v1 0.1 debug| min_nseg = 10, max_segl = 628729\n
*** v1 0.1 debug| max_nseg = 26212, min_segl = 239\n
*** v1 0.1 debug| aim_nseg = 511, aim_segl = 12303\n
*** v1 0.1 debug| free_reserve = 123030\n
*** v1 0.1 debug| sizeof(struct smp_ident) = 112 = 0x70\n
*** v1 0.1 debug| sizeof(struct smp_sign) = 32 = 0x20\n
*** v1 0.1 debug| sizeof(struct smp_segptr) = 32 = 0x20\n
*** v1 0.1 debug| sizeof(struct smp_object) = 56 = 0x38\n
*** v1 0.1 debug| CHK(0x24b7ee8 SILO 0x2b38f0e20000 <invalid>) = 1\n
*** v1 0.1 debug| Warning SILO (/tmp/vtc.8405.4fdaaca5/_.per2) not
reloaded (reason=1)\n
*** v1 0.1 debug| min_nseg = 10, max_segl = 628729\n
*** v1 0.1 debug| max_nseg = 26212, min_segl = 239\n
*** v1 0.1 debug| aim_nseg = 511, aim_segl = 12303\n
*** v1 0.1 debug| free_reserve = 123030\n
*** v1 0.2 debug| Platform:
Linux,3.2.0-60-virtual,x86_64,-spersistent,-spersistent,-smalloc,-hcritbit\n
*** v1 0.2 debug| 200 296 \n
*** v1 0.2 debug| -----------------------------\n
*** v1 0.2 debug| Varnish Cache CLI 1.0\n
*** v1 0.2 debug| -----------------------------\n
*** v1 0.2 debug|
Linux,3.2.0-60-virtual,x86_64,-spersistent,-spersistent,-smalloc,-hcritbit\n
*** v1 0.2 debug| varnish-4.0.0-tp2 revision 793d67a\n
*** v1 0.2 debug| \n
*** v1 0.2 debug| Type 'help' for command list.\n
*** v1 0.2 debug| Type 'quit' to close CLI session.\n
*** v1 0.2 debug| Type 'start' to launch worker process.\n
*** v1 0.2 debug| \n
**** v1 0.3 CLIPOLL 1 0x1 0x0
*** v1 0.3 CLI connection fd = 9
*** v1 0.3 CLI RX 107
**** v1 0.3 CLI RX| sdwmwtdxomqprgyvfqbwzmqzkqdjlieg\n
**** v1 0.3 CLI RX| \n
**** v1 0.3 CLI RX| Authentication required.\n
**** v1 0.3 CLI TX| auth
f0d6f51cb680dc1c21582f30a9c861c94d9d2e055d5ece86f7e56ca779079a3a\n
*** v1 0.3 CLI RX 200
**** v1 0.3 CLI RX| -----------------------------\n
**** v1 0.3 CLI RX| Varnish Cache CLI 1.0\n
**** v1 0.3 CLI RX| -----------------------------\n
**** v1 0.3 CLI RX|
Linux,3.2.0-60-virtual,x86_64,-spersistent,-spersistent,-smalloc,-hcritbit\n
**** v1 0.3 CLI RX| varnish-4.0.0-tp2 revision 793d67a\n
**** v1 0.3 CLI RX| \n
**** v1 0.3 CLI RX| Type 'help' for command list.\n
**** v1 0.3 CLI RX| Type 'quit' to close CLI session.\n
**** v1 0.3 CLI RX| Type 'start' to launch worker process.\n
**** v1 0.3 CLI TX| vcl.inline vcl1 << %XJEIFLH|)Xspa8P\n
**** v1 0.3 CLI TX| vcl 4.0;\n
**** v1 0.3 CLI TX| backend s1 { .host = "127.0.0.1"; .port = "42265";
}\n
**** v1 0.3 CLI TX| \n
**** v1 0.3 CLI TX| \n
**** v1 0.3 CLI TX| \t\n
**** v1 0.3 CLI TX| %XJEIFLH|)Xspa8P\n
*** v1 0.4 CLI RX 200
**** v1 0.4 CLI RX| Message from VCC-compiler:\n
**** v1 0.4 CLI RX| Not running as root, no priv-sep\n
**** v1 0.4 CLI RX| Message from C-compiler:\n
**** v1 0.4 CLI RX| Not running as root, no priv-sep\n
**** v1 0.4 CLI RX| Message from dlopen:\n
**** v1 0.4 CLI RX| Not running as root, no priv-sep\n
**** v1 0.4 CLI RX| \n
**** v1 0.4 CLI RX| VCL compiled.
**** v1 0.4 CLI TX| vcl.use vcl1
*** v1 0.4 CLI RX 200
**** v1 0.4 CLI RX| VCL 'vcl1' now active
*** top 0.4 varnish
** v1 0.4 Start
**** v1 0.4 CLI TX| start
*** v1 0.5 debug| child (9322) Started\n
**** v1 0.6 vsl| 0 CLI - Rd vcl.load "vcl1"
./vcl.lU8d_9fm.so
*** v1 0.6 CLI RX 200
*** v1 0.6 wait-running
**** v1 0.6 CLI TX| status
*** v1 0.6 debug| Child (9322) said Not running as root, no priv-sep\n
*** v1 0.6 debug| Child (9322) said Child starts\n
*** v1 0.6 debug| Child (9322) said Wrapped silo\n
*** v1 0.6 debug| Child (9322) said Wrapped silo\n
*** v1 0.6 debug| Child (9322) said Silo completely loaded\n
*** v1 0.6 debug| Child (9322) said Silo completely loaded\n
*** v1 0.6 CLI RX 200
**** v1 0.6 CLI RX| Child in state running
**** v1 0.6 CLI TX| debug.xid 999
**** v1 0.6 vsl| 0 CLI - Wr 200 36 Loaded
"./vcl.lU8d_9fm.so" as "vcl1"
**** v1 0.6 vsl| 0 CLI - Rd vcl.use "vcl1"
**** v1 0.6 vsl| 0 CLI - Wr 200 0
**** v1 0.6 vsl| 0 CLI - Rd start
**** v1 0.6 vsl| 0 CLI - Wr 200 0
*** v1 0.6 CLI RX 200
**** v1 0.6 CLI RX| XID is 999
**** v1 0.6 CLI TX| debug.listen_address
**** v1 0.6 vsl| 0 CLI - Rd debug.xid 999
**** v1 0.6 vsl| 0 CLI - Wr 200 10 XID is 999
*** v1 0.6 CLI RX 200
**** v1 0.6 CLI RX| 127.0.0.1 49091\n
** v1 0.6 Listen on 127.0.0.1 49091
**** v1 0.6 macro def v1_addr=127.0.0.1
**** v1 0.6 macro def v1_port=49091
**** v1 0.6 macro def v1_sock=127.0.0.1 49091
*** top 0.6 client
** c1 0.6 Starting client
** c1 0.6 Waiting for client
*** c1 0.6 Connect to 127.0.0.1 49091
*** c1 0.6 connected fd 10 from 127.0.0.1 35269 to 127.0.0.1 49091
*** c1 0.6 txreq
**** c1 0.6 txreq| GET / HTTP/1.1\r\n
**** c1 0.6 txreq| \r\n
*** c1 0.6 rxresp
*** s1 0.6 accepted fd 4
*** s1 0.6 rxreq
**** s1 0.6 rxhdr| GET / HTTP/1.1\r\n
**** s1 0.6 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
**** s1 0.6 rxhdr| Accept-Encoding: gzip\r\n
**** s1 0.6 rxhdr| X-Varnish: 1002\r\n
**** s1 0.6 rxhdr| Host: 127.0.0.1\r\n
**** s1 0.6 rxhdr| \r\n
**** s1 0.6 http[ 0] | GET
**** s1 0.6 http[ 1] | /
**** s1 0.6 http[ 2] | HTTP/1.1
**** s1 0.6 http[ 3] | X-Forwarded-For: 127.0.0.1
**** s1 0.6 http[ 4] | Accept-Encoding: gzip
**** s1 0.6 http[ 5] | X-Varnish: 1002
**** s1 0.6 http[ 6] | Host: 127.0.0.1
**** s1 0.6 bodylen = 0
*** s1 0.6 txresp
**** s1 0.6 txresp| HTTP/1.1 200 Ok\r\n
**** s1 0.6 txresp| x-foo: foo\r\n
**** s1 0.6 txresp| Content-Length: 0\r\n
**** s1 0.6 txresp| \r\n
*** s1 0.6 accept
**** s1 0.6 Accepting
**** c1 0.6 rxhdr| HTTP/1.1 200 Ok\r\n
**** c1 0.6 rxhdr| x-foo: foo\r\n
**** c1 0.6 rxhdr| Date: Mon, 17 Mar 2014 12:13:19 GMT\r\n
**** c1 0.6 rxhdr| X-Varnish: 1001\r\n
**** c1 0.6 rxhdr| Age: 0\r\n
**** c1 0.6 rxhdr| Via: 1.1 varnish\r\n
**** c1 0.6 rxhdr| Content-Length: 0\r\n
**** c1 0.6 rxhdr| Connection: keep-alive\r\n
**** c1 0.6 rxhdr| Accept-Ranges: bytes\r\n
**** c1 0.6 rxhdr| \r\n
**** c1 0.6 http[ 0] | HTTP/1.1
**** c1 0.6 http[ 1] | 200
**** c1 0.6 http[ 2] | Ok
**** c1 0.6 http[ 3] | x-foo: foo
**** c1 0.6 http[ 4] | Date: Mon, 17 Mar 2014 12:13:19 GMT
**** c1 0.6 http[ 5] | X-Varnish: 1001
**** c1 0.6 http[ 6] | Age: 0
**** c1 0.6 http[ 7] | Via: 1.1 varnish
**** c1 0.6 http[ 8] | Content-Length: 0
**** c1 0.6 http[ 9] | Connection: keep-alive
**** c1 0.6 http[10] | Accept-Ranges: bytes
**** c1 0.6 bodylen = 0
*** c1 0.6 expect
**** c1 0.6 EXPECT resp.http.x-foo (foo) == "foo" match
*** c1 0.6 closing fd 10
** c1 0.6 Ending
*** top 0.6 varnish
**** v1 0.6 CLI TX| ban req.url == /test
**** v1 0.6 vsl| 0 CLI - Rd debug.listen_address
**** v1 0.6 vsl| 0 CLI - Wr 200 16 127.0.0.1 49091
**** v1 0.6 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 0.6 vsl| 1000 SessOpen c 127.0.0.1 35269
127.0.0.1:0 127.0.0.1 49091 1395058399.582462 13
**** v1 0.6 vsl| 1000 Link c req 1001 rxreq
**** v1 0.6 vsl| 1002 Begin b bereq 1001 fetch
**** v1 0.6 vsl| 1002 BereqMethod b GET
**** v1 0.6 vsl| 1002 BereqURL b /
**** v1 0.6 vsl| 1002 BereqProtocol b HTTP/1.1
**** v1 0.6 vsl| 1002 BereqHeader b X-Forwarded-For:
127.0.0.1
**** v1 0.6 vsl| 1002 BereqHeader b Accept-Encoding: gzip
**** v1 0.6 vsl| 1002 BereqHeader b X-Varnish: 1002
**** v1 0.6 vsl| 1002 VCL_call b BACKEND_FETCH
**** v1 0.6 vsl| 1002 VCL_return b fetch
**** v1 0.6 vsl| 1002 BackendOpen b 16 s1(127.0.0.1,,42265)
127.0.0.1 54416
**** v1 0.6 vsl| 1002 Backend b 16 s1
s1(127.0.0.1,,42265)
**** v1 0.6 vsl| 1002 BereqHeader b Host: 127.0.0.1
**** v1 0.6 vsl| 1002 BerespProtocol b HTTP/1.1
**** v1 0.6 vsl| 1002 BerespStatus b 200
**** v1 0.6 vsl| 1002 BerespResponse b Ok
**** v1 0.6 vsl| 1002 BerespHeader b x-foo: foo
**** v1 0.6 vsl| 1002 BerespHeader b Content-Length: 0
**** v1 0.6 vsl| 1002 TTL b RFC 20 -1 -1 1395058400
1395058400 0 0 0
**** v1 0.6 vsl| 1002 VCL_call b BACKEND_RESPONSE
**** v1 0.6 vsl| 1002 VCL_return b deliver
**** v1 0.6 vsl| 1002 Storage b persistent per2
**** v1 0.6 vsl| 1002 ObjProtocol b HTTP/1.1
**** v1 0.6 vsl| 1002 ObjStatus b 200
**** v1 0.6 vsl| 1002 ObjResponse b Ok
**** v1 0.6 vsl| 1002 ObjHeader b x-foo: foo
**** v1 0.6 vsl| 1002 Fetch_Body b 3 length stream
**** v1 0.6 vsl| 1002 BackendReuse b 16 s1(127.0.0.1,,42265)
**** v1 0.6 vsl| 1002 Length b 0
**** v1 0.6 vsl| 1002 BereqEnd b 1395058399.583058596
1395058399.583804369 0.000028228 0.000366001 0.000046941 0.000412942
**** v1 0.6 vsl| 1002 End b
**** v1 0.6 vsl| 0 ExpKill - EXP_Inbox
p=0x2b3928000950 e=0.000000000 f=0x1c10
**** v1 0.6 vsl| 0 ExpKill - EXP_When p=0x2b3928000950
e=1395058429.582860470 f=0x1c10
**** v1 0.6 vsl| 1001 Begin c req 1000 rxreq
**** v1 0.6 vsl| 1001 ReqStart c 127.0.0.1 35269
**** v1 0.6 vsl| 1001 ReqMethod c GET
**** v1 0.6 vsl| 1001 ReqURL c /
**** v1 0.6 vsl| 1001 ReqProtocol c HTTP/1.1
**** v1 0.6 vsl| 1001 VCL_call c RECV
**** v1 0.6 vsl| 1001 ReqHeader c X-Forwarded-For:
127.0.0.1
**** v1 0.6 vsl| 1001 VCL_return c hash
**** v1 0.6 vsl| 1001 VCL_call c HASH
**** v1 0.6 vsl| 1001 VCL_return c lookup
**** v1 0.6 vsl| 1001 Debug c XXXX MISS
**** v1 0.6 vsl| 1001 VCL_call c MISS
**** v1 0.6 vsl| 1001 VCL_return c fetch
**** v1 0.6 vsl| 1001 Link c bereq 1002 fetch
**** v1 0.6 vsl| 1001 RespProtocol c HTTP/1.1
**** v1 0.6 vsl| 1001 RespStatus c 200
**** v1 0.6 vsl| 1001 RespResponse c Ok
**** v1 0.6 vsl| 1001 RespHeader c x-foo: foo
**** v1 0.6 vsl| 1001 RespHeader c Date: Mon, 17 Mar 2014
12:13:19 GMT
**** v1 0.6 vsl| 1001 RespHeader c X-Varnish: 1001
**** v1 0.6 vsl| 1001 RespHeader c Age: 0
**** v1 0.6 vsl| 1001 RespHeader c Via: 1.1 varnish
**** v1 0.6 vsl| 1001 VCL_call c DELIVER
**** v1 0.6 vsl| 1001 VCL_return c deliver
**** v1 0.6 vsl| 1001 RespHeader c Content-Length: 0
**** v1 0.6 vsl| 1001 Debug c RES_MODE 2
**** v1 0.6 vsl| 1001 RespHeader c Connection: keep-alive
**** v1 0.6 vsl| 1001 RespHeader c Accept-Ranges: bytes
**** v1 0.6 vsl| 1001 Debug c XXX REF 2
**** v1 0.6 vsl| 1001 Length c 0
**** v1 0.6 vsl| 1001 ReqEnd c 1395058399.582860470
1395058399.582461596 -0.001381636 0.000982761 -0.001381636
**** v1 0.6 vsl| 1001 End c
**** v1 0.6 vsl| 1000 SessClose c REM_CLOSE 0.002 1 0 0 1 1
0
**** v1 0.6 vsl| 1000 End c
*** v1 0.7 CLI RX 200
** v1 0.7 CLI 200 <ban req.url == /test>
*** top 0.7 varnish
**** v1 0.7 CLI TX| ban req.url == /test
**** v1 0.7 vsl| 0 CLI - Rd ban req.url == /test
**** v1 0.7 vsl| 0 CLI - Wr 200 0
*** v1 0.7 CLI RX 200
** v1 0.7 CLI 200 <ban req.url == /test>
*** top 0.7 varnish
**** v1 0.7 CLI TX| ban.list
**** v1 0.7 vsl| 0 CLI - Rd ban req.url == /test
**** v1 0.7 vsl| 0 CLI - Wr 200 0
*** v1 0.8 CLI RX 200
**** v1 0.8 CLI RX| Present bans:\n
**** v1 0.8 CLI RX| 1395058399.661653 0 req.url == /test\n
**** v1 0.8 CLI RX| 1395058399.621650 0 C \n
**** v1 0.8 CLI RX| 1395058399.431171 1 C \n
** v1 0.8 CLI 200 <ban.list>
*** top 0.8 varnish
** v1 0.8 as expected: bans (3) == 3
*** top 0.8 varnish
** v1 0.8 as expected: bans_dups (1) == 1
*** top 0.8 varnish
** v1 0.8 as expected: bans_completed (2) == 2
*** top 0.8 varnish
**** v1 0.8 macro undef v1_addr
**** v1 0.8 macro undef v1_port
**** v1 0.8 macro undef v1_sock
** v1 0.8 Stop
**** v1 0.8 CLI TX| stop
**** v1 0.8 vsl| 0 CLI - Rd ban.list
**** v1 0.8 vsl| 0 CLI - Wr 200 114 Present bans:
1395058399.661653 0 req.url == /test
1395058399.621650 0 C
1395058399.431171 1 C
*** v1 0.8 debug| Stopping Child\n
**** v1 0.8 vsl| 0 CLI - EOF on CLI connection,
worker stops
*** v1 1.8 debug| Child (9322) died status=1\n
*** v1 1.8 debug| Child (9322) said Child dies\n
*** v1 1.8 debug| Child cleanup complete\n
*** v1 1.8 CLI RX 200
**** v1 1.8 CLI TX| status
*** v1 1.9 CLI RX 200
**** v1 1.9 CLI RX| Child in state stopped
*** top 1.9 varnish
** v1 1.9 Start
**** v1 1.9 CLI TX| start
*** v1 1.9 debug| child (11852) Started\n
**** v1 1.9 vsl| 0 ExpKill - EXP_Inbox
p=0x2b390c0008c0 e=1395058429.582860470 f=0x1830
**** v1 1.9 vsl| 0 ExpKill - EXP_When p=0x2b390c0008c0
e=1395058429.582860470 f=0x1830
**** v1 2.9 vsl| 0 CLI - Rd vcl.load "vcl1"
./vcl.lU8d_9fm.so
**** v1 2.9 vsl| 0 CLI - Wr 200 36 Loaded
"./vcl.lU8d_9fm.so" as "vcl1"
**** v1 2.9 vsl| 0 CLI - Rd vcl.use "vcl1"
**** v1 2.9 vsl| 0 CLI - Wr 200 0
*** v1 2.9 CLI RX 200
*** v1 2.9 wait-running
**** v1 2.9 CLI TX| status
*** v1 2.9 debug| Child (11852) said Not running as root, no priv-
sep\n
*** v1 2.9 debug| Child (11852) said Child starts\n
*** v1 2.9 debug| Child (11852) said Wrapped silo\n
*** v1 2.9 debug| Child (11852) said Silo completely loaded\n
*** v1 2.9 debug| Child (11852) said Dropped 0 segments to make
free_reserve\n
*** v1 2.9 debug| Child (11852) said Silo completely loaded\n
*** v1 2.9 CLI RX 200
**** v1 2.9 CLI RX| Child in state running
**** v1 2.9 CLI TX| debug.xid 999
**** v1 2.9 vsl| 0 CLI - Rd start
**** v1 2.9 vsl| 0 CLI - Wr 200 0
*** v1 3.0 CLI RX 200
**** v1 3.0 CLI RX| XID is 999
**** v1 3.0 CLI TX| debug.listen_address
**** v1 3.0 vsl| 0 CLI - Rd debug.xid 999
**** v1 3.0 vsl| 0 CLI - Wr 200 10 XID is 999
*** v1 3.0 CLI RX 200
**** v1 3.0 CLI RX| 127.0.0.1 41200\n
** v1 3.0 Listen on 127.0.0.1 41200
**** v1 3.0 macro def v1_addr=127.0.0.1
**** v1 3.0 macro def v1_port=41200
**** v1 3.0 macro def v1_sock=127.0.0.1 41200
*** top 3.0 varnish
**** v1 3.0 CLI TX| ban.list
**** v1 3.0 vsl| 0 CLI - Rd debug.listen_address
**** v1 3.0 vsl| 0 CLI - Wr 200 16 127.0.0.1 41200
*** v1 3.0 CLI RX 200
**** v1 3.0 CLI RX| Present bans:\n
**** v1 3.0 CLI RX| 1395058400.834320 0 C \n
**** v1 3.0 CLI RX| 1395058399.661653 0 req.url == /test\n
**** v1 3.0 CLI RX| 1395058399.621650 0 C \n
**** v1 3.0 CLI RX| 1395058399.431171 1 C \n
** v1 3.0 CLI 200 <ban.list>
*** top 3.0 client
** c1 3.0 Starting client
** c1 3.0 Waiting for client
*** c1 3.0 Connect to 127.0.0.1 41200
*** c1 3.0 connected fd 10 from 127.0.0.1 45002 to 127.0.0.1 41200
*** c1 3.0 txreq
**** c1 3.0 txreq| GET / HTTP/1.1\r\n
**** c1 3.0 txreq| \r\n
*** c1 3.0 rxresp
**** c1 3.0 rxhdr| HTTP/1.1 200 Ok\r\n
**** c1 3.0 rxhdr| x-foo: foo\r\n
**** c1 3.0 rxhdr| Date: Mon, 17 Mar 2014 12:13:21 GMT\r\n
**** c1 3.0 rxhdr| X-Varnish: 1001 1002\r\n
**** c1 3.0 rxhdr| Age: 2\r\n
**** c1 3.0 rxhdr| Via: 1.1 varnish\r\n
**** c1 3.0 rxhdr| Content-Length: 0\r\n
**** c1 3.0 rxhdr| Connection: keep-alive\r\n
**** c1 3.0 rxhdr| Accept-Ranges: bytes\r\n
**** c1 3.0 rxhdr| \r\n
**** c1 3.0 http[ 0] | HTTP/1.1
**** c1 3.0 http[ 1] | 200
**** c1 3.0 http[ 2] | Ok
**** c1 3.0 http[ 3] | x-foo: foo
**** c1 3.0 http[ 4] | Date: Mon, 17 Mar 2014 12:13:21 GMT
**** c1 3.0 http[ 5] | X-Varnish: 1001 1002
**** c1 3.0 http[ 6] | Age: 2
**** c1 3.0 http[ 7] | Via: 1.1 varnish
**** c1 3.0 http[ 8] | Content-Length: 0
**** c1 3.0 http[ 9] | Connection: keep-alive
**** c1 3.0 http[10] | Accept-Ranges: bytes
**** c1 3.0 bodylen = 0
*** c1 3.0 expect
**** c1 3.0 EXPECT resp.http.x-foo (foo) == "foo" match
*** c1 3.0 closing fd 10
** c1 3.0 Ending
*** top 3.0 varnish
**** v1 3.0 vsl| 0 CLI - Rd ban.list
**** v1 3.0 vsl| 0 CLI - Wr 200 142 Present bans:
1395058400.834320 0 C
1395058399.661653 0 req.url == /test
1395058399.621650 0 C
1395058399.431171 1 C
**** v1 3.0 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 3.0 vsl| 1000 SessOpen c 127.0.0.1 45002
127.0.0.1:0 127.0.0.1 41200 1395058401.982032 13
**** v1 3.0 vsl| 1000 Link c req 1001 rxreq
**** v1 3.0 vsl| 0 ExpKill - EXP_Rearm
p=0x2b390c0008c0 E=1395058429.582860470 e=1395058429.582860470 f=0x1000
**** v1 3.0 vsl| 0 ExpKill - EXP_Inbox
p=0x2b390c0008c0 e=1395058429.582860470 f=0x1410
**** v1 3.0 vsl| 0 ExpKill - EXP_When p=0x2b390c0008c0
e=1395058429.582860470 f=0x1410
**** v1 3.0 vsl| 1001 Begin c req 1000 rxreq
**** v1 3.0 vsl| 1001 ReqStart c 127.0.0.1 45002
**** v1 3.0 vsl| 1001 ReqMethod c GET
**** v1 3.0 vsl| 1001 ReqURL c /
**** v1 3.0 vsl| 1001 ReqProtocol c HTTP/1.1
**** v1 3.0 vsl| 1001 VCL_call c RECV
**** v1 3.0 vsl| 1001 ReqHeader c X-Forwarded-For:
127.0.0.1
**** v1 3.0 vsl| 1001 VCL_return c hash
**** v1 3.0 vsl| 1001 VCL_call c HASH
**** v1 3.0 vsl| 1001 VCL_return c lookup
**** v1 3.0 vsl| 1001 Hit c 2147484650
**** v1 3.0 vsl| 1001 VCL_call c HIT
**** v1 3.0 vsl| 1001 VCL_return c deliver
**** v1 3.0 vsl| 1001 RespProtocol c HTTP/1.1
**** v1 3.0 vsl| 1001 RespStatus c 200
**** v1 3.0 vsl| 1001 RespResponse c Ok
**** v1 3.0 vsl| 1001 RespHeader c x-foo: foo
**** v1 3.0 vsl| 1001 RespHeader c Date: Mon, 17 Mar 2014
12:13:21 GMT
**** v1 3.0 vsl| 1001 RespHeader c X-Varnish: 1001 1002
**** v1 3.0 vsl| 1001 RespHeader c Age: 2
**** v1 3.0 vsl| 1001 RespHeader c Via: 1.1 varnish
**** v1 3.0 vsl| 1001 VCL_call c DELIVER
**** v1 3.0 vsl| 1001 VCL_return c deliver
**** v1 3.0 vsl| 1001 RespHeader c Content-Length: 0
**** v1 3.0 vsl| 1001 Debug c RES_MODE 2
**** v1 3.0 vsl| 1001 RespHeader c Connection: keep-alive
**** v1 3.0 vsl| 1001 RespHeader c Accept-Ranges: bytes
**** v1 3.0 vsl| 1001 Debug c XXX REF 2
**** v1 3.0 vsl| 1001 Length c 0
**** v1 3.0 vsl| 1001 ReqEnd c 1395058401.982092381
1395058401.982031584 -0.000237942 0.000177145 -0.000237942
**** v1 3.0 vsl| 1001 End c
**** v1 3.0 vsl| 1000 SessClose c REM_CLOSE 0.001 1 0 0 0 1
0
**** v1 3.0 vsl| 1000 End c
** v1 3.3 as expected: bans_dups (1) == 1
*** top 3.3 varnish
---- v1 4.3 Not true: bans_completed (1) == 3 (3)
* top 4.3 RESETTING after ../../../bin/varnishtest/tests/p00009.vtc
** s1 4.3 Waiting for server
**** s1 4.3 macro undef s1_addr
**** s1 4.3 macro undef s1_port
**** s1 4.3 macro undef s1_sock
**** v1 4.9 vsl| 0 CLI - Rd ping
**** v1 4.9 vsl| 0 CLI - Wr 200 19 PONG 1395058403
1.0
** v1 5.3 Wait
**** v1 5.3 vsl| 0 CLI - EOF on CLI connection,
worker stops
** v1 7.4 R 8447 Status: 0000 (u 0.144009 s 0.144009)
* top 7.4 TEST ../../../bin/varnishtest/tests/p00009.vtc FAILED
# top TEST ../../../bin/varnishtest/tests/p00009.vtc FAILED (7.427)
exit=1
}}}
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1451>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list