search

nigoroll / libvmod-dynamic

The Varnish dns/named director continued
BSD 2-Clause "Simplified" License
95 stars 34 forks source link

via.vtc failing with "Cannot assign requested address" #97

Closed gquintard closed 1 year ago

gquintard commented 1 year ago

stumbled onto this when trying to build https://github.com/varnish/docker-varnish/blob/master/fresh/debian/Dockerfile

could it be that

shell "getent hosts localhost www.localhost img.localhost || true"

should actually be

feature cmd "getent hosts localhost www.localhost img.localhost || true"

?

FAIL: tests/via
===============

**** dT    0.000
*    top   TEST ./tests/via.vtc starting
**** top   extmacro def pkg_version=7.3.0
**** top   extmacro def pkg_branch=7.3
**** top   extmacro def pwd=/tmp/module_to_build/src
**** top   extmacro def date(...)
**** top   extmacro def string(...)
**** top   extmacro def vmod_dynamic=dynamic from "/tmp/module_to_build/src/.libs/libvmod_dynamic.so"
**** top   extmacro def localhost=127.0.0.1
**** top   extmacro def bad_backend=127.0.0.1:37455
**** top   extmacro def listen_addr=127.0.0.1:0
**** top   extmacro def bad_ip=192.0.2.255
**** top   macro def testdir=/tmp/module_to_build/src/./tests
**** top   macro def tmpdir=/tmp/vtc.31252.7c6136c4
**   top   === varnishtest "via"
*    top   VTEST via
**   top   === shell "getent hosts localhost www.localhost img.localhost ||...
**** top   shell_cmd|exec 2>&1 ; getent hosts localhost www.localhost img.localhost || true
**** dT    0.213
**** top   shell_out|::1             localhost ip6-localhost ip6-loopback
**** top   shell_status = 0x0000
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=41173
**** s1    macro def s1_sock=127.0.0.1:41173
*    s1    Listen on 127.0.0.1:41173
**   top   === varnish v2 -proto PROXY -vcl {
**   s1    Started on 127.0.0.1:41173 (1 iterations)
**** dT    0.216
**   v2    Launch
***  v2    CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtc.31252.7c6136c4/v2 -i v2 -p debug=+vcl_keep -p debug=+vmod_so_keep -p debug=+vsm_keep -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0',PROXY -M '127.0.0.1 45329' -P /tmp/vtc.31252.7c6136c4/v2/varnishd.pid 
***  v2    CMD: cd /tmp/module_to_build/src && exec varnishd  -d -n /tmp/vtc.31252.7c6136c4/v2 -i v2 -p debug=+vcl_keep -p debug=+vmod_so_keep -p debug=+vsm_keep -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0',PROXY -M '127.0.0.1 45329' -P /tmp/vtc.31252.7c6136c4/v2/varnishd.pid 
***  v2    PID: 31281
**** v2    macro def v2_pid=31281
**** v2    macro def v2_name=/tmp/vtc.31252.7c6136c4/v2
**** dT    0.226
***  v2    debug|Debug: Version: varnish-7.3.0 revision 84d79120b6d17b11819a663a93160743f293e63f
***  v2    debug|Debug: Platform: Linux,6.1.11-arch1-1,x86_64,-junix,-sdefault,-sdefault,-hcritbit
***  v2    debug|200 315     
***  v2    debug|-----------------------------
***  v2    debug|Varnish Cache CLI 1.0
***  v2    debug|-----------------------------
***  v2    debug|Linux,6.1.11-arch1-1,x86_64,-junix,-sdefault,-sdefault,-hcritbit
***  v2    debug|varnish-7.3.0 revision 84d79120b6d17b11819a663a93160743f293e63f
***  v2    debug|
***  v2    debug|Type 'help' for command list.
***  v2    debug|Type 'quit' to close CLI session.
***  v2    debug|Type 'start' to launch worker process.
***  v2    debug|
**** dT    0.325
**** v2    CLIPOLL 1 0x1 0x0 0x0
***  v2    CLI connection fd = 7
***  v2    CLI RX  107
**** v2    CLI RX|tpbjefitubonnjbuqolncwowdyrfjdyh
**** v2    CLI RX|
**** v2    CLI RX|Authentication required.
**** v2    CLI TX|auth d37955cd96eb9ec6ae08fedc09e18c6ffcf62bd5fbc1526bc3ef40c651cb3a9b
**** dT    0.326
***  v2    CLI RX  200
**** v2    CLI RX|-----------------------------
**** v2    CLI RX|Varnish Cache CLI 1.0
**** v2    CLI RX|-----------------------------
**** v2    CLI RX|Linux,6.1.11-arch1-1,x86_64,-junix,-sdefault,-sdefault,-hcritbit
**** v2    CLI RX|varnish-7.3.0 revision 84d79120b6d17b11819a663a93160743f293e63f
**** v2    CLI RX|
**** v2    CLI RX|Type 'help' for command list.
**** v2    CLI RX|Type 'quit' to close CLI session.
**** v2    CLI RX|Type 'start' to launch worker process.
**** v2    CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v2    CLI TX|vcl 4.1;
**** v2    CLI TX|
**** v2    CLI TX|\timport dynamic from "/tmp/module_to_build/src/.libs/libvmod_dynamic.so";
**** v2    CLI TX|\timport std;
**** v2    CLI TX|\timport proxy;
**** v2    CLI TX|
**** v2    CLI TX|\tbackend dummy { .host = "127.0.0.1:37455"; }
**** v2    CLI TX|
**** v2    CLI TX|\tsub vcl_init {
**** v2    CLI TX|\t\tnew d1 = dynamic.director();
**** v2    CLI TX|\t}
**** v2    CLI TX|
**** v2    CLI TX|\tsub vcl_recv {
**** v2    CLI TX|\t\tset req.backend_hint = d1.backend(server.ip,
**** v2    CLI TX|\t\t    std.port(server.ip));
**** v2    CLI TX|\t\tset req.http.Authority = proxy.authority();
**** v2    CLI TX|
**** v2    CLI TX|\t\treturn (pass);
**** v2    CLI TX|\t}
**** v2    CLI TX|
**** v2    CLI TX|\tsub vcl_deliver {
**** v2    CLI TX|\t\tset resp.http.Authority = req.http.Authority;
**** v2    CLI TX|\t}
**** v2    CLI TX|
**** v2    CLI TX|%XJEIFLH|)Xspa8P
**** dT    0.426
***  v2    vsl|No VSL chunk found (child not started ?)
**** dT    0.526
***  v2    vsl|No VSL chunk found (child not started ?)
**** dT    0.606
***  v2    CLI RX  200
**** v2    CLI RX|VCL compiled.
**** v2    CLI TX|vcl.use vcl1
***  v2    CLI RX  200
**** v2    CLI RX|VCL 'vcl1' now active
**   v2    Start
**** v2    CLI TX|start
**** dT    0.626
***  v2    vsl|No VSL chunk found (child not started ?)
**** dT    0.649
***  v2    debug|Debug: Child (31370) Started
**** dT    0.673
***  v2    debug|Child launched OK
**** dT    0.678
***  v2    debug|Info: Child (31370) said Child starts
***  v2    CLI RX  200
***  v2    wait-running
**** v2    CLI TX|status
**** dT    0.721
***  v2    CLI RX  200
**** v2    CLI RX|Child in state running
**** v2    CLI TX|debug.listen_address
**** dT    0.727
**** v2    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1679028965.187541/vgc.so 1auto
**** v2    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1679028965.187541/vgc.so" as "vcl1"
**** v2    vsl|          0 CLI             - Rd vcl.use "vcl1"
**** v2    vsl|          0 CLI             - Wr 200 0 
**** v2    vsl|          0 CLI             - Rd start
**** v2    vsl|          0 Debug           - sockopt: Setting SO_LINGER for a0=127.0.0.1:35713
**** v2    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:35713
**** v2    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:35713
**** v2    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:35713
**** v2    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:35713
**** v2    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:35713
**** v2    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:35713
**** v2    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:35713
**** v2    vsl|          0 CLI             - Wr 200 0 
**** dT    0.764
***  v2    CLI RX  200
**** v2    CLI RX|a0 127.0.0.1 35713
**** v2    CLI TX|debug.xid 1000
**** dT    0.811
***  v2    CLI RX  200
**** v2    CLI RX|XID is 1000 chunk 1
**** v2    CLI TX|debug.listen_address
**** dT    0.827
**** v2    vsl|          0 CLI             - Rd debug.listen_address 
**** v2    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 35713

**** v2    vsl|          0 CLI             - Rd debug.xid 1000 
**** v2    vsl|          0 CLI             - Wr 200 19 XID is 1000 chunk 1
**** dT    0.854
***  v2    CLI RX  200
**** v2    CLI RX|a0 127.0.0.1 35713
**   v2    Listen on 127.0.0.1 35713
**** v2    macro def v2_addr=127.0.0.1
**** v2    macro def v2_port=35713
**** v2    macro def v2_sock=127.0.0.1:35713
**** v2    macro def v2_a0_addr=127.0.0.1
**** v2    macro def v2_a0_port=35713
**** v2    macro def v2_a0_sock=127.0.0.1:35713
**   top   === varnish v1 -vcl {
**** dT    0.857
**   v1    Launch
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtc.31252.7c6136c4/v1 -i v1 -p debug=+vcl_keep -p debug=+vmod_so_keep -p debug=+vsm_keep -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 33113' -P /tmp/vtc.31252.7c6136c4/v1/varnishd.pid 
***  v1    CMD: cd /tmp/module_to_build/src && exec varnishd  -d -n /tmp/vtc.31252.7c6136c4/v1 -i v1 -p debug=+vcl_keep -p debug=+vmod_so_keep -p debug=+vsm_keep -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 33113' -P /tmp/vtc.31252.7c6136c4/v1/varnishd.pid 
***  v1    PID: 31413
**** v1    macro def v1_pid=31413
**** v1    macro def v1_name=/tmp/vtc.31252.7c6136c4/v1
**** dT    0.866
***  v1    debug|Debug: Version: varnish-7.3.0 revision 84d79120b6d17b11819a663a93160743f293e63f
***  v1    debug|Debug: Platform: Linux,6.1.11-arch1-1,x86_64,-junix,-sdefault,-sdefault,-hcritbit
***  v1    debug|200 315     
***  v1    debug|-----------------------------
***  v1    debug|Varnish Cache CLI 1.0
***  v1    debug|-----------------------------
***  v1    debug|Linux,6.1.11-arch1-1,x86_64,-junix,-sdefault,-sdefault,-hcritbit
***  v1    debug|varnish-7.3.0 revision 84d79120b6d17b11819a663a93160743f293e63f
***  v1    debug|
***  v1    debug|Type 'help' for command list.
***  v1    debug|Type 'quit' to close CLI session.
***  v1    debug|Type 'start' to launch worker process.
***  v1    debug|
**** dT    0.927
**** v2    vsl|          0 CLI             - Rd debug.listen_address 
**** v2    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 35713

**** dT    0.966
**** v1    CLIPOLL 1 0x1 0x0 0x0
***  v1    CLI connection fd = 18
***  v1    CLI RX  107
**** v1    CLI RX|sivrodaptpqwhiockdagcddondbmlnoq
**** v1    CLI RX|
**** v1    CLI RX|Authentication required.
**** v1    CLI TX|auth d2c2d189e19fd9551e2913d49c42111c030d1fc301821431c9802913b9bf5307
***  v1    CLI RX  200
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Varnish Cache CLI 1.0
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Linux,6.1.11-arch1-1,x86_64,-junix,-sdefault,-sdefault,-hcritbit
**** v1    CLI RX|varnish-7.3.0 revision 84d79120b6d17b11819a663a93160743f293e63f
**** v1    CLI RX|
**** v1    CLI RX|Type 'help' for command list.
**** v1    CLI RX|Type 'quit' to close CLI session.
**** v1    CLI RX|Type 'start' to launch worker process.
**** dT    0.967
**** v1    CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|
**** v1    CLI TX|\timport dynamic from "/tmp/module_to_build/src/.libs/libvmod_dynamic.so";
**** v1    CLI TX|
**** v1    CLI TX|\tbackend v2 { .host = "127.0.0.1"; .port = "35713"; }
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_init {
**** v1    CLI TX|\t\tnew d1 = dynamic.director(
**** v1    CLI TX|\t\t    port = "41173",
**** v1    CLI TX|\t\t    via = v2);
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_recv {
**** v1    CLI TX|\t\tset req.backend_hint = d1.backend("localhost");
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_error {
**** v1    CLI TX|\t\t# the director may resolve ::1 first
**** v1    CLI TX|\t\treturn (retry);
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    1.067
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.167
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.228
***  v1    CLI RX  200
**** v1    CLI RX|VCL compiled.
**** v1    CLI TX|vcl.use vcl1
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl1' now active
**   v1    Start
**** v1    CLI TX|start
**** dT    1.267
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    1.272
***  v1    debug|Debug: Child (31486) Started
**** dT    1.297
***  v1    debug|Child launched OK
**** dT    1.301
***  v1    CLI RX  200
***  v1    debug|Info: Child (31486) said Child starts
***  v1    wait-running
**** v1    CLI TX|status
**** dT    1.344
***  v1    CLI RX  200
**** v1    CLI RX|Child in state running
**** v1    CLI TX|debug.listen_address
**** dT    1.367
**** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1679028965.828132/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1679028965.828132/vgc.so" as "vcl1"
**** v1    vsl|          0 CLI             - Rd vcl.use "vcl1"
**** v1    vsl|          0 CLI             - Wr 200 0 
**** v1    vsl|          0 CLI             - Rd start
**** v1    vsl|          0 Debug           - sockopt: Setting SO_LINGER for a0=127.0.0.1:44415
**** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:44415
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:44415
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:44415
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:44415
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:44415
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:44415
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:44415
**** v1    vsl|          0 CLI             - Wr 200 0 
**** dT    1.391
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 44415
**** v1    CLI TX|debug.xid 1000
**** dT    1.434
***  v1    CLI RX  200
**** v1    CLI RX|XID is 1000 chunk 1
**** v1    CLI TX|debug.listen_address
**** dT    1.467
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 44415

**** v1    vsl|          0 CLI             - Rd debug.xid 1000 
**** v1    vsl|          0 CLI             - Wr 200 19 XID is 1000 chunk 1
**** dT    1.477
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 44415
**   v1    Listen on 127.0.0.1 44415
**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=44415
**** v1    macro def v1_sock=127.0.0.1:44415
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=44415
**** v1    macro def v1_a0_sock=127.0.0.1:44415
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:44415 (1 iterations)
***  c1    Connect to 127.0.0.1:44415
***  c1    connected fd 28 from 127.0.0.1 38040 to 127.0.0.1:44415
**** dT    1.478
**   c1    === txreq
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    1.480
**** c1    rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1    rxhdr|Date: Fri, 17 Mar 2023 04:56:06 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|X-Varnish: 1001\r
**** c1    rxhdr|Authority: localhost\r
**** c1    rxhdr|Content-Length: 281\r
**** c1    rxhdr|X-Varnish: 1001\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v2 (Varnish/7.3), 1.1 v1 (Varnish/7.3)\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 305
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Backend fetch failed
**** c1    http[ 3] |Date: Fri, 17 Mar 2023 04:56:06 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |Content-Type: text/html; charset=utf-8
**** c1    http[ 6] |Retry-After: 5
**** c1    http[ 7] |X-Varnish: 1001
**** c1    http[ 8] |Authority: localhost
**** c1    http[ 9] |Content-Length: 281
**** c1    http[10] |X-Varnish: 1001
**** c1    http[11] |Age: 0
**** c1    http[12] |Via: 1.1 v2 (Varnish/7.3), 1.1 v1 (Varnish/7.3)
**** c1    http[13] |Connection: keep-alive
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Backend fetch failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 Backend fetch failed</h1>
**** c1    c-l|    <p>Backend fetch failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1002</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 281
**   c1    === expect resp.status == 200
---- c1    EXPECT resp.status (503) == "200" failed
*    top   RESETTING after ./tests/via.vtc
**   s1    Waiting for server (4/-1)
**   v2    Wait
**** v2    CLI TX|panic.show
**** dT    1.524
***  v2    CLI RX  300
**** v2    CLI RX|Child has not panicked or panic has been cleared
***  v2    debug|Info: manager stopping child
***  v2    debug|Debug: Stopping Child
**** dT    1.528
**** v2    vsl|       1000 Begin           c sess 0 PROXY
**** v2    vsl|       1000 SessOpen        c 127.0.0.1 59120 a0 127.0.0.1 35713 1679028966.339887 19
**** v2    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:35713
**** v2    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:35713
**** v2    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:35713
**** v2    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:35713
**** v2    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:35713
**** v2    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:35713
**** v2    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:35713
**** v2    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:35713
**** v2    vsl|       1000 Proxy           c 2 :: 0 ::1 41173
**** v2    vsl|       1000 Link            c req 1001 rxreq
**** v2    vsl|          0 Timestamp       - vmod-dynamic vcl1.d1(::1:41173) Lookup: 1679028966.340034 0.000000 0.000000
**** v2    vsl|          0 Timestamp       - vmod-dynamic vcl1.d1(::1:41173) Results: 1679028966.340130 0.000096 0.000096
**** v2    vsl|          0 Timestamp       - vmod-dynamic vcl1.d1(::1:41173) Update: 1679028966.340295 0.000261 0.000165
**** v2    vsl|       1002 Begin           b bereq 1001 pass
**** v2    vsl|       1002 VCL_use         b vcl1
**** v2    vsl|       1002 Timestamp       b Start: 1679028966.340091 0.000000 0.000000
**** v2    vsl|       1002 BereqMethod     b GET
**** v2    vsl|       1002 BereqURL        b /
**** v2    vsl|       1002 BereqProtocol   b HTTP/1.1
**** v2    vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v2    vsl|       1002 BereqHeader     b Accept-Encoding: gzip
**** v2    vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v2    vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1, ::
**** v2    vsl|       1002 BereqHeader     b Via: 1.1 v1 (Varnish/7.3), 1.1 v2 (Varnish/7.3)
**** v2    vsl|       1002 BereqHeader     b Authority: localhost
**** v2    vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v2    vsl|       1002 VCL_call        b BACKEND_FETCH
**** v2    vsl|       1002 VCL_return      b fetch
**** v2    vsl|       1002 Timestamp       b Fetch: 1679028966.340108 0.000017 0.000017
**** v2    vsl|       1002 FetchError      b backend d1(::1:41173): fail errno 99 (Cannot assign requested address)
**** v2    vsl|       1002 Timestamp       b Beresp: 1679028966.340422 0.000331 0.000313
**** v2    vsl|       1002 Timestamp       b Error: 1679028966.340424 0.000333 0.000002
**** v2    vsl|       1002 BerespProtocol  b HTTP/1.1
**** v2    vsl|       1002 BerespStatus    b 503
**** v2    vsl|       1002 BerespReason    b Backend fetch failed
**** v2    vsl|       1002 BerespHeader    b Date: Fri, 17 Mar 2023 04:56:06 GMT
**** v2    vsl|       1002 BerespHeader    b Server: Varnish
**** v2    vsl|       1002 VCL_call        b BACKEND_ERROR
**** v2    vsl|       1002 BerespHeader    b Content-Type: text/html; charset=utf-8
**** v2    vsl|       1002 BerespHeader    b Retry-After: 5
**** v2    vsl|       1002 VCL_return      b deliver
**** v2    vsl|       1002 Storage         b malloc Transient
**** v2    vsl|       1002 Length          b 281
**** v2    vsl|       1002 BereqAcct       b 0 0 0 0 0 0
**** v2    vsl|       1002 End             b 
**** v2    vsl|       1001 Begin           c req 1000 rxreq
**** v2    vsl|       1001 Timestamp       c Start: 1679028966.339929 0.000000 0.000000
**** v2    vsl|       1001 Timestamp       c Req: 1679028966.339929 0.000000 0.000000
**** v2    vsl|       1001 VCL_use         c vcl1
**** v2    vsl|       1001 ReqStart        c :: 0 a0
**** v2    vsl|       1001 ReqMethod       c GET
**** v2    vsl|       1001 ReqURL          c /
**** v2    vsl|       1001 ReqProtocol     c HTTP/1.1
**** v2    vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v2    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v2    vsl|       1001 ReqHeader       c Via: 1.1 v1 (Varnish/7.3)
**** v2    vsl|       1001 ReqHeader       c Accept-Encoding: gzip
**** v2    vsl|       1001 ReqHeader       c X-Varnish: 1002
**** v2    vsl|       1001 ReqUnset        c X-Forwarded-For: 127.0.0.1
**** v2    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1, ::
**** v2    vsl|       1001 ReqUnset        c Via: 1.1 v1 (Varnish/7.3)
**** v2    vsl|       1001 ReqHeader       c Via: 1.1 v1 (Varnish/7.3), 1.1 v2 (Varnish/7.3)
**** v2    vsl|       1001 VCL_call        c RECV
**** v2    vsl|       1001 ReqHeader       c Authority: localhost
**** v2    vsl|       1001 VCL_return      c pass
**** v2    vsl|       1001 VCL_call        c HASH
**** v2    vsl|       1001 VCL_return      c lookup
**** v2    vsl|       1001 VCL_call        c PASS
**** v2    vsl|       1001 VCL_return      c fetch
**** v2    vsl|       1001 Link            c bereq 1002 pass
**** v2    vsl|       1001 Timestamp       c Fetch: 1679028966.340555 0.000625 0.000625
**** v2    vsl|       1001 RespProtocol    c HTTP/1.1
**** v2    vsl|       1001 RespStatus      c 503
**** v2    vsl|       1001 RespReason      c Backend fetch failed
**** v2    vsl|       1001 RespHeader      c Date: Fri, 17 Mar 2023 04:56:06 GMT
**** v2    vsl|       1001 RespHeader      c Server: Varnish
**** v2    vsl|       1001 RespHeader      c Content-Type: text/html; charset=utf-8
**** v2    vsl|       1001 RespHeader      c Retry-After: 5
**** v2    vsl|       1001 RespHeader      c X-Varnish: 1001
**** v2    vsl|       1001 RespHeader      c Age: 0
**** v2    vsl|       1001 RespHeader      c Via: 1.1 v2 (Varnish/7.3)
**** v2    vsl|       1001 VCL_call        c DELIVER
**** v2    vsl|       1001 RespHeader      c Authority: localhost
**** v2    vsl|       1001 VCL_return      c deliver
**** v2    vsl|       1001 Timestamp       c Process: 1679028966.340574 0.000644 0.000018
**** v2    vsl|       1001 Filters         c 
**** v2    vsl|       1001 RespHeader      c Content-Length: 281
**** v2    vsl|       1001 RespHeader      c Connection: keep-alive
**** v2    vsl|       1001 Timestamp       c Resp: 1679028966.340619 0.000689 0.000045
**** v2    vsl|       1001 ReqAcct         c 130 0 130 266 281 547
**** v2    vsl|       1001 End             c 
**** v2    vsl|          0 CLI             - EOF on CLI connection, worker stops
**** dT    1.567
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 44415

**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    vsl|       1000 SessOpen        c 127.0.0.1 38040 a0 127.0.0.1 44415 1679028966.339009 19
**** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:44415
**** v1    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:44415
**** v1    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:44415
**** v1    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:44415
**** v1    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:44415
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:44415
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:44415
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:44415
**** v1    vsl|       1000 Link            c req 1001 rxreq
**** v1    vsl|          0 Timestamp       - vmod-dynamic vcl1.d1(localhost:41173) Lookup: 1679028966.339141 0.000000 0.000000
**** v1    vsl|          0 Timestamp       - vmod-dynamic vcl1.d1(localhost:41173) Results: 1679028966.339372 0.000231 0.000231
**** v1    vsl|          0 Timestamp       - vmod-dynamic vcl1.d1(localhost:41173) Update: 1679028966.339616 0.000475 0.000244
**** v1    vsl|       1002 Begin           b bereq 1001 fetch
**** v1    vsl|       1002 VCL_use         b vcl1
**** v1    vsl|       1002 Timestamp       b Start: 1679028966.339237 0.000000 0.000000
**** v1    vsl|       1002 BereqMethod     b GET
**** v1    vsl|       1002 BereqURL        b /
**** v1    vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** dT    1.568
**** v1    vsl|       1002 BereqHeader     b Via: 1.1 v1 (Varnish/7.3)
**** v1    vsl|       1002 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v1    vsl|       1002 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1002 VCL_return      b fetch
**** v1    vsl|       1002 Timestamp       b Fetch: 1679028966.339257 0.000019 0.000019
**** v1    vsl|       1002 Timestamp       b Connected: 1679028966.339806 0.000568 0.000549
**** v1    vsl|       1002 BackendOpen     b 25 d1.localhost(::1:41173) 127.0.0.1 35713 127.0.0.1 59120 connect
**** v1    vsl|       1002 Timestamp       b Bereq: 1679028966.339835 0.000597 0.000028
**** v1    vsl|       1002 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1002 BerespStatus    b 503
**** v1    vsl|       1002 BerespReason    b Backend fetch failed
**** v1    vsl|       1002 BerespHeader    b Date: Fri, 17 Mar 2023 04:56:06 GMT
**** v1    vsl|       1002 BerespHeader    b Server: Varnish
**** v1    vsl|       1002 BerespHeader    b Content-Type: text/html; charset=utf-8
**** v1    vsl|       1002 BerespHeader    b Retry-After: 5
**** v1    vsl|       1002 BerespHeader    b X-Varnish: 1001
**** v1    vsl|       1002 BerespHeader    b Age: 0
**** v1    vsl|       1002 BerespHeader    b Via: 1.1 v2 (Varnish/7.3)
**** v1    vsl|       1002 BerespHeader    b Authority: localhost
**** v1    vsl|       1002 BerespHeader    b Content-Length: 281
**** v1    vsl|       1002 BerespHeader    b Connection: keep-alive
**** v1    vsl|       1002 Timestamp       b Beresp: 1679028966.340633 0.001396 0.000798
**** v1    vsl|       1002 TTL             b RFC -1 10 0 1679028966 1679028966 1679028966 0 0 cacheable
**** v1    vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1002 TTL             b VCL 120 10 0 1679028966 cacheable
**** v1    vsl|       1002 TTL             b VCL 120 10 0 1679028966 uncacheable
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Timestamp       b Process: 1679028966.340654 0.001416 0.000020
**** v1    vsl|       1002 Filters         b 
**** v1    vsl|       1002 Storage         b malloc Transient
**** v1    vsl|       1002 Fetch_Body      b 3 length stream
**** v1    vsl|       1002 BackendClose    b 25 d1.localhost(::1:41173) recycle
**** v1    vsl|       1002 Timestamp       b BerespBody: 1679028966.350797 0.011559 0.010143
**** v1    vsl|       1002 Length          b 281
**** v1    vsl|       1002 BereqAcct       b 130 0 130 266 281 547
**** v1    vsl|       1002 End             b 
**** v1    vsl|       1001 Begin           c req 1000 rxreq
**** v1    vsl|       1001 Timestamp       c Start: 1679028966.339053 0.000000 0.000000
**** v1    vsl|       1001 Timestamp       c Req: 1679028966.339053 0.000000 0.000000
**** v1    vsl|       1001 VCL_use         c vcl1
**** v1    vsl|       1001 ReqStart        c 127.0.0.1 38040 a0
**** v1    vsl|       1001 ReqMethod       c GET
**** v1    vsl|       1001 ReqURL          c /
**** v1    vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c Via: 1.1 v1 (Varnish/7.3)
**** v1    vsl|       1001 VCL_call        c RECV
**** v1    vsl|       1001 VCL_return      c hash
**** v1    vsl|       1001 VCL_call        c HASH
**** v1    vsl|       1001 VCL_return      c lookup
**** v1    vsl|       1001 VCL_call        c MISS
**** v1    vsl|       1001 VCL_return      c fetch
**** v1    vsl|       1001 Link            c bereq 1002 fetch
**** v1    vsl|       1001 Timestamp       c Fetch: 1679028966.340701 0.001648 0.001648
**** v1    vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    vsl|       1001 RespStatus      c 503
**** v1    vsl|       1001 RespReason      c Backend fetch failed
**** v1    vsl|       1001 RespHeader      c Date: Fri, 17 Mar 2023 04:56:06 GMT
**** v1    vsl|       1001 RespHeader      c Server: Varnish
**** v1    vsl|       1001 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1001 RespHeader      c Retry-After: 5
**** v1    vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    vsl|       1001 RespHeader      c Via: 1.1 v2 (Varnish/7.3)
**** v1    vsl|       1001 RespHeader      c Authority: localhost
**** v1    vsl|       1001 RespHeader      c Content-Length: 281
**** v1    vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    vsl|       1001 RespHeader      c Age: 0
**** v1    vsl|       1001 RespUnset       c Via: 1.1 v2 (Varnish/7.3)
**** v1    vsl|       1001 RespHeader      c Via: 1.1 v2 (Varnish/7.3), 1.1 v1 (Varnish/7.3)
**** v1    vsl|       1001 VCL_call        c DELIVER
**** v1    vsl|       1001 VCL_return      c deliver
**** v1    vsl|       1001 Timestamp       c Process: 1679028966.340725 0.001672 0.000023
**** v1    vsl|       1001 Filters         c 
**** v1    vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    vsl|       1001 Timestamp       c Resp: 1679028966.350810 0.011757 0.010085
**** v1    vsl|       1001 ReqAcct         c 35 0 35 305 281 586
**** v1    vsl|       1001 End             c 
**** dT    1.624
***  v2    debug|Info: Child (31370) ended
***  v2    debug|Info: Child (31370) said Child dies
***  v2    debug|Debug: Child cleanup complete
***  v2    debug|Info: manager dies
**** dT    1.625
**** v2    STDOUT EOF
**** dT    1.628
**   v2    WAIT4 pid=31281 status=0x0000 (user 0.259649 sys 0.048448)
**   v1    Wait
**** v1    CLI TX|panic.show
**** dT    1.671
***  v1    CLI RX  300
**** v1    CLI RX|Child has not panicked or panic has been cleared
***  v1    debug|Info: manager stopping child
***  v1    debug|Debug: Stopping Child
**** dT    1.768
**** v1    vsl|          0 CLI             - EOF on CLI connection, worker stops
**** dT    1.771
***  v1    debug|Info: Child (31486) ended
***  v1    debug|Info: Child (31486) said Child dies
***  v1    debug|Debug: Child cleanup complete
***  v1    debug|Info: manager dies
**** dT    1.772
**** v1    STDOUT EOF
**** dT    1.868
**   v1    WAIT4 pid=31413 status=0x0000 (user 0.236578 sys 0.053338)
*    top   TEST ./tests/via.vtc FAILED
#    top  TEST ./tests/via.vtc FAILED (1.869) exit=2
FAIL tests/via.vtc (exit status: 2)
gquintard commented 1 year ago

quick PR: https://github.com/nigoroll/libvmod-dynamic/pull/98

nigoroll commented 1 year ago

fixed in af9c51cb53982b42eed6116960015c09171838b0