search

nigoroll / libvmod-dynamic

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

unit test issues tests/service/basic #111

Closed halittiryaki closed 6 months ago

halittiryaki commented 6 months ago

tests/service/basic always fails. any ideas why?

here is the log output:

113.2 FAIL: tests/service/basic
113.2 =========================
113.2 
113.2 **** dT    0.000
113.2 *    top   TEST ./tests/service/basic.vtc starting
113.2 **** top   extmacro def pkg_version=7.4.2
113.2 **** top   extmacro def pkg_branch=7.4
113.2 **** top   extmacro def pwd=/usr/src/libvmod-dynamic/src
113.2 **** top   extmacro def date(...)
113.2 **** top   extmacro def string(...)
113.2 **** top   extmacro def vmod_dynamic=dynamic from "/usr/src/libvmod-dynamic/src/.libs/libvmod_dynamic.so"
113.2 **** top   extmacro def localhost=127.0.0.1
113.2 **** top   extmacro def bad_backend=127.0.0.1:34783
113.2 **** top   extmacro def listen_addr=127.0.0.1:0
113.2 **** top   extmacro def bad_ip=192.0.2.255
113.2 **** top   macro def testdir=/usr/src/libvmod-dynamic/src/./tests/service
113.2 **** top   macro def tmpdir=/tmp/vtc.6616.0c8774d2
113.2 **** top   macro def vtcid=vtc.6616.0c8774d2
113.2 **   top   === varnishtest "service smoke test"
113.2 *    top   VTEST service smoke test
113.2 **   top   === feature cmd {dig @b.root-servers.net. a.root-servers.net. >/...
113.2 **** dT    0.162
113.2 **   top   === varnish v1 -vcl {
113.2 **** dT    0.163
113.2 **   v1    Launch
113.2 ***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtc.6616.0c8774d2/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,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 32961' -P /tmp/vtc.6616.0c8774d2/v1/varnishd.pid 
113.2 ***  v1    CMD: cd /usr/src/libvmod-dynamic/src && exec varnishd  -d -n /tmp/vtc.6616.0c8774d2/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,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 32961' -P /tmp/vtc.6616.0c8774d2/v1/varnishd.pid 
113.2 ***  v1    PID: 6625
113.2 **** v1    macro def v1_pid=6625
113.2 **** v1    macro def v1_name=/tmp/vtc.6616.0c8774d2/v1
113.2 **** dT    0.170
113.2 ***  v1    debug|Debug: Version: varnish-7.4.2 revision cd1d10ab53a6f6115b2b4f3b2a1da94c1f749f80
113.2 ***  v1    debug|Debug: Platform: Linux,6.1.21.2-microsoft-standard-WSL2+,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
113.2 ***  v1    debug|200 334     
113.2 ***  v1    debug|-----------------------------
113.2 ***  v1    debug|Varnish Cache CLI 1.0
113.2 ***  v1    debug|-----------------------------
113.2 ***  v1    debug|Linux,6.1.21.2-microsoft-standard-WSL2+,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
113.2 ***  v1    debug|varnish-7.4.2 revision cd1d10ab53a6f6115b2b4f3b2a1da94c1f749f80
113.2 ***  v1    debug|
113.2 ***  v1    debug|Type 'help' for command list.
113.2 ***  v1    debug|Type 'quit' to close CLI session.
113.2 ***  v1    debug|Type 'start' to launch worker process.
113.2 ***  v1    debug|
113.2 **** dT    0.270
113.2 **** v1    CLIPOLL 1 0x1 0x0 0x0
113.2 ***  v1    CLI connection fd = 5
113.2 ***  v1    CLI RX  107
113.2 **** v1    CLI RX|drotryltqdjwwoecnnqazieftftfdooh
113.2 **** v1    CLI RX|
113.2 **** v1    CLI RX|Authentication required.
113.2 **** v1    CLI TX|auth b5df73e06088d59c977725d021704506e8320db5b28ea9b8bd8dd729867e78c6
113.2 ***  v1    CLI RX  200
113.2 **** v1    CLI RX|-----------------------------
113.2 **** v1    CLI RX|Varnish Cache CLI 1.0
113.2 **** v1    CLI RX|-----------------------------
113.2 **** v1    CLI RX|Linux,6.1.21.2-microsoft-standard-WSL2+,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
113.2 **** v1    CLI RX|varnish-7.4.2 revision cd1d10ab53a6f6115b2b4f3b2a1da94c1f749f80
113.2 **** v1    CLI RX|
113.2 **** v1    CLI RX|Type 'help' for command list.
113.2 **** v1    CLI RX|Type 'quit' to close CLI session.
113.2 **** v1    CLI RX|Type 'start' to launch worker process.
113.2 **** v1    CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
113.2 **** v1    CLI TX|vcl 4.1;
113.2 **** v1    CLI TX|
113.2 **** v1    CLI TX|\timport dynamic from "/usr/src/libvmod-dynamic/src/.libs/libvmod_dynamic.so";
113.2 **** v1    CLI TX|
113.2 **** v1    CLI TX|\tbackend proforma none;
113.2 **** v1    CLI TX|
113.2 **** v1    CLI TX|\tsub vcl_init {
113.2 **** v1    CLI TX|\t\tnew r1 = dynamic.resolver();
113.2 **** v1    CLI TX|\t\tnew d1 = dynamic.director(
113.2 **** v1    CLI TX|\t\t    resolver = r1.use());
113.2 **** v1    CLI TX|\t\td1.debug(true);
113.2 **** v1    CLI TX|\t}
113.2 **** v1    CLI TX|
113.2 **** v1    CLI TX|\tsub vcl_recv {
113.2 **** v1    CLI TX|\t\tset req.backend_hint =
113.2 **** v1    CLI TX|\t\t    d1.service("_test._tcp.vmod-dynamic.uplex.de");
113.2 **** v1    CLI TX|\t\tset req.http.Host = "varnish-cache.org";
113.2 **** v1    CLI TX|\t}
113.2 **** v1    CLI TX|
113.2 **** v1    CLI TX|\tsub vcl_backend_fetch {
113.2 **** v1    CLI TX|\t\tset bereq.first_byte_timeout = 1s;
113.2 **** v1    CLI TX|\t\tset bereq.connect_timeout = 1s;
113.2 **** v1    CLI TX|\t}
113.2 **** v1    CLI TX|
113.2 **** v1    CLI TX|\tsub vcl_backend_response {
113.2 **** v1    CLI TX|\t\tset beresp.http.backend = beresp.backend;
113.2 **** v1    CLI TX|\t}
113.2 **** v1    CLI TX|
113.2 **** v1    CLI TX|\tsub vcl_backend_error {
113.2 **** v1    CLI TX|\t\tset beresp.http.backend = beresp.backend;
113.2 **** v1    CLI TX|\t}
113.2 **** v1    CLI TX|
113.2 **** v1    CLI TX|%XJEIFLH|)Xspa8P
113.2 **** dT    0.371
113.2 ***  v1    vsl|No VSL chunk found (child not started ?)
113.2 **** dT    0.471
113.2 ***  v1    vsl|No VSL chunk found (child not started ?)
113.2 **** dT    0.571
113.2 ***  v1    vsl|No VSL chunk found (child not started ?)
113.2 **** dT    0.662
113.2 ***  v1    CLI RX  200
113.2 **** v1    CLI RX|VCL compiled.
113.2 **** v1    CLI TX|vcl.use vcl1
113.2 **** dT    0.663
113.2 ***  v1    CLI RX  200
113.2 **** v1    CLI RX|VCL 'vcl1' now active
113.2 **   v1    Start
113.2 **** v1    CLI TX|start
113.2 **** dT    0.671
113.2 ***  v1    vsl|No VSL chunk found (child not started ?)
113.2 **** dT    0.706
113.2 ***  v1    debug|Debug: Child (6639) Started
113.2 **** dT    0.730
113.2 ***  v1    debug|Child launched OK
113.2 **** dT    0.736
113.2 ***  v1    CLI RX  200
113.2 ***  v1    debug|Info: Child (6639) said Child starts
113.2 ***  v1    wait-running
113.2 **** v1    CLI TX|status
113.2 **** dT    0.772
113.2 **** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1708082841.201980/vgc.so 1auto
113.2 **** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1708082841.201980/vgc.so" as "vcl1"
113.2 **** v1    vsl|          0 CLI             - Rd vcl.use "vcl1"
113.2 **** v1    vsl|          0 CLI             - Wr 200 0 
113.2 **** v1    vsl|          0 CLI             - Rd start
113.2 **** v1    vsl|          0 Debug           - sockopt: Setting SO_LINGER for a0=127.0.0.1:38125
113.2 **** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:38125
113.2 **** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:38125
113.2 **** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:38125
113.2 **** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:38125
113.2 **** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:38125
113.2 **** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:38125
113.2 **** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:38125
113.2 **** v1    vsl|          0 CLI             - Wr 200 0 
113.2 **** dT    0.785
113.2 ***  v1    CLI RX  200
113.2 **** v1    CLI RX|Child in state running
113.2 **** v1    CLI TX|debug.listen_address
113.2 **** dT    0.835
113.2 ***  v1    CLI RX  200
113.2 **** v1    CLI RX|a0 127.0.0.1 38125
113.2 **** v1    CLI TX|debug.xid 1000
113.2 **** dT    0.872
113.2 **** v1    vsl|          0 CLI             - Rd debug.listen_address 
113.2 **** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 38125
113.2 
113.2 **** dT    0.885
113.2 ***  v1    CLI RX  200
113.2 **** v1    CLI RX|XID is 1000 chunk 1
113.2 **** v1    CLI TX|debug.listen_address
113.2 **** dT    0.935
113.2 ***  v1    CLI RX  200
113.2 **** v1    CLI RX|a0 127.0.0.1 38125
113.2 **   v1    Listen on 127.0.0.1 38125
113.2 **** v1    macro def v1_addr=127.0.0.1
113.2 **** v1    macro def v1_port=38125
113.2 **** v1    macro def v1_sock=127.0.0.1:38125
113.2 **** v1    macro def v1_a0_addr=127.0.0.1
113.2 **** v1    macro def v1_a0_port=38125
113.2 **** v1    macro def v1_a0_sock=127.0.0.1:38125
113.2 **   top   === varnish v1 -cli "backend.list"
113.2 **** v1    CLI TX|backend.list
113.2 **** dT    0.972
113.2 **** v1    vsl|          0 CLI             - Rd debug.xid 1000 
113.2 **** v1    vsl|          0 CLI             - Wr 200 19 XID is 1000 chunk 1
113.2 **** v1    vsl|          0 CLI             - Rd debug.listen_address 
113.2 **** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 38125
113.2 
113.2 **** dT    0.985
113.2 ***  v1    CLI RX  200
113.2 **** v1    CLI RX|Backend name   Admin    Probe    Health    Last change
113.2 **   v1    CLI 200 <backend.list>
113.2 **   top   === client c1 {
113.2 **   c1    Starting client
113.2 **   c1    Waiting for client
113.2 **   c1    Started on 127.0.0.1:38125 (1 iterations)
113.2 ***  c1    Connect to 127.0.0.1:38125
113.2 ***  c1    connected fd 15 from 127.0.0.1 55250 to 127.0.0.1:38125
113.2 **   c1    === txreq
113.2 **** c1    txreq|GET / HTTP/1.1\r
113.2 **** c1    txreq|Host: 127.0.0.1\r
113.2 **** c1    txreq|User-Agent: c1\r
113.2 **** c1    txreq|\r
113.2 **   c1    === rxresp
113.2 **** dT    0.992
113.2 **** c1    rxhdrlen = 0
113.2 ---- c1    HTTP header is incomplete
113.2 *    top   RESETTING after ./tests/service/basic.vtc
113.2 **   v1    Wait
113.2 **** v1    CLI TX|panic.show
113.2 ***  v1    debug|Error: Child (6639) died signal=11
113.2 **** dT    0.993
113.2 ***  v1    debug|Debug: Child cleanup complete
113.2 **** dT    1.035
113.2 ***  v1    CLI RX  300
113.2 **** v1    CLI RX|Child has not panicked or panic has been cleared
113.2 ***  v1    debug|Info: manager stopping child
113.2 ***  v1    debug|Info: manager dies
113.2 **** dT    1.038
113.2 **** v1    STDOUT EOF
113.2 **** dT    1.072
113.2 **** v1    vsl|          0 CLI             - Rd backend.list 
113.2 **** v1    vsl|          0 CLI             - Wr 200 55 Backend name   Admin    Probe    Health    Last change
113.2 
113.2 **** v1    vsl|       1000 Begin           c sess 0 HTTP/1
113.2 **** v1    vsl|       1000 SessOpen        c 127.0.0.1 55250 a0 127.0.0.1 38125 1708082841.917190 22
113.2 **** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:38125
113.2 **** v1    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:38125
113.2 **** v1    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:38125
113.2 **** v1    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:38125
113.2 **** v1    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:38125
113.2 **** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:38125
113.2 **** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:38125
113.2 **** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:38125
113.2 **** v1    vsl|       1000 Link            c req 1001 rxreq
113.2 **** v1    vsl|          0 Debug           - vmod-dynamic vcl1 d1 _test._tcp.vmod-dynamic.uplex.de event 1
113.2 **** v1    vsl|          0 Debug           - vmod-dynamic vcl1 d1 _test._tcp.vmod-dynamic.uplex.de event 1
113.2 **** v1    vsl|          0 Timestamp       - vmod-dynamic vcl1.d1(srv _test._tcp.vmod-dynamic.uplex.de) Lookup: 1708082841.917460 0.000000 0.000000
113.2 **** v1    vsl|          0 Debug           - vmod-dynamic vcl1 d1 _test._tcp.vmod-dynamic.uplex.de wait-active
113.2 **   v1    WAIT4 pid=6625 status=0x4000 (user 0.332437 sys 0.094343)
113.2 *    v1    Expected exit: 0x0 signal: 0 core: 0
113.2 ---- v1    Bad exit status: 0x4000 exit 0x40 signal 0 core 0
113.2 *    top   failure during reset
113.2 #    top  TEST ./tests/service/basic.vtc FAILED (1.073) exit=2
113.2 FAIL tests/service/basic.vtc (exit status: 2)
halittiryaki commented 6 months ago

only the stub resolver works, though I am able to resolve SRV records with:

getdns_query -S ...

halittiryaki commented 6 months ago

seems to be an issue on alpine in a container env. the getdns lib somehow does not work with the vmod as excpected. however, the same build process with debian works normally.