search

nigoroll / libvmod-dynamic

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

Use after free in layer_reolad.vtc from Debug messages #112

Closed stevendore closed 6 months ago

stevendore commented 6 months ago

When running layer_reolad.vtc with ASAN CFLAGS, ASAN finds a heap-use-after-free in dom_destroy(). This is found using latest Varnish Cache and latest libvmod dynamic. The issue could be hidden by allocating the fallback director after the dynamic director, this results in the director/domain being freed in the "right" order.

Steps to reproduce:

  1. Configure varnish with --enable-asan and then before make set enviorment vairables ASAN_OPTIONS=abort_on_error=1,detect_odr_violation=1,detect_leaks=1,detect_stack_use_after_return=1,detect_invalid_pointer_pairs=1,handle_segv=0,handle_sigbus=0,use_sigaltstack=0,disable_coredump=0 and LSAN_OPTIONS=abort_on_error=1,use_sigaltstack=0,suppressions=${path_to}/varnish-cache/tools/lsan.suppr
  2. configure libvmod-dynamic with CFLAGS='-fsanitize=address' ./configure and export the same SAN options as Varnish
  3. run make check

Collapsible VTC Log:

toggle view log ``` **** dT 0.000 * top TEST ./tests/layer_reload.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/home/swojcik/code/libvmod-dynamic/src **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def vmod_dynamic=dynamic from "/home/swojcik/code/libvmod-dynamic/src/.libs/libvmod_dynamic.so" **** top extmacro def localhost=127.0.0.1 **** top extmacro def bad_backend=127.0.0.1:41381 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top macro def testdir=/home/swojcik/code/libvmod-dynamic/src/./tests **** top macro def tmpdir=/tmp/vtc.2872792.2223da65 **** top macro def vtcid=vtc.2872792.2223da65 ** top === varnishtest "Reloading after creating backend in init" * top VTEST Reloading after creating backend in init ** top === feature cmd "getent hosts example.com" **** dT 0.024 ** top === shell { **** top shell_cmd|exec 2>&1 ; **** top shell_cmd|\tcat >/tmp/vtc.2872792.2223da65/f1 <<-EOF **** top shell_cmd|\tvcl 4.1; **** top shell_cmd|\timport dynamic from "/home/swojcik/code/libvmod-dynamic/src/.libs/libvmod_dynamic.so"; **** top shell_cmd|\timport directors; **** top shell_cmd| **** top shell_cmd|\tbackend none none; **** top shell_cmd| **** top shell_cmd|\tsub vcl_init { **** top shell_cmd|\t\tnew dir = directors.fallback(); **** top shell_cmd|\t\tnew res = dynamic.resolver(); **** top shell_cmd|\t\tnew dyn = dynamic.director(domain_usage_timeout = 0.1s, resolver = res.use()); **** top shell_cmd|\t\tdir.add_backend(dyn.backend(host={"example.com"}, port={"80"}) ); **** top shell_cmd|\t} **** top shell_cmd|\tEOF **** dT 0.028 **** top shell_status = 0x0000 ** top === varnish v1 -cliok "vcl.load vcl1 ${tmpdir}/f1" **** dT 0.033 ** v1 Launch *** v1 CMD: cd ${pwd} && exec varnishd -d -n /tmp/vtc.2872792.2223da65/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 38685' -P /tmp/vtc.2872792.2223da65/v1/varnishd.pid *** v1 CMD: cd /home/swojcik/code/libvmod-dynamic/src && exec varnishd -d -n /tmp/vtc.2872792.2223da65/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 38685' -P /tmp/vtc.2872792.2223da65/v1/varnishd.pid **** dT 0.034 *** v1 PID: 2872812 **** v1 macro def v1_pid=2872812 **** v1 macro def v1_name=/tmp/vtc.2872792.2223da65/v1 **** dT 0.054 *** v1 debug|Debug: Version: varnish-trunk revision d77da13b9baf268196075bda0808d0d2e8721470 *** v1 debug|Debug: Platform: Linux,6.5.0-17-generic,x86_64,-jnone,-sdefault,-sdefault,-hcritbit *** v1 debug|200 317 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|Linux,6.5.0-17-generic,x86_64,-jnone,-sdefault,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision d77da13b9baf268196075bda0808d0d2e8721470 *** 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.153 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 4 **** dT 0.154 *** v1 CLI RX 107 **** v1 CLI RX|ygvcsiionoelhdqmokrfteicbjzhrzuc **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth 90608ea81d2bbbfa7774fd79c416390009fbabba31979c1a26762f0a0fe266fd **** dT 0.155 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Linux,6.5.0-17-generic,x86_64,-jnone,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision d77da13b9baf268196075bda0808d0d2e8721470 **** 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.156 **** v1 CLI TX|vcl.load vcl1 /tmp/vtc.2872792.2223da65/f1 **** dT 0.256 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.356 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.456 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.556 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.657 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.757 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.832 *** v1 CLI RX 200 **** v1 CLI RX|Message from VCC-compiler: **** v1 CLI RX|----------------------------------------------------- **** v1 CLI RX|Suppressions used: **** v1 CLI RX| count bytes template **** v1 CLI RX| 2 136 HSH_config **** v1 CLI RX| 9 360 vcc_ **** v1 CLI RX|----------------------------------------------------- **** v1 CLI RX| **** v1 CLI RX|Message from dlopen: **** v1 CLI RX|----------------------------------------------------- **** v1 CLI RX|Suppressions used: **** v1 CLI RX| count bytes template **** v1 CLI RX| 2 136 HSH_config **** v1 CLI RX|----------------------------------------------------- **** v1 CLI RX| **** v1 CLI RX|VCL compiled. ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.use vcl1" **** v1 CLI TX|vcl.use vcl1 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 CLI 200 ** top === varnish v1 -cliok "start" **** v1 CLI TX|start **** dT 0.857 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.875 *** v1 debug|Debug: Child (2872880) Started **** dT 0.900 *** v1 debug|Child launched OK **** dT 0.913 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.load vcl2 ${tmpdir}/f1" *** v1 debug|Info: Child (2872880) said Child starts **** v1 CLI TX|vcl.load vcl2 /tmp/vtc.2872792.2223da65/f1 **** dT 0.957 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1708618810.078643/vgc.so 1auto **** v1 vsl| 0 Timestamp - vmod-dynamic vcl1.dyn(example.com:80) Lookup: 1708618810.794116 0.000000 0.000000 **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1708618810.078643/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:45489 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45489 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45489 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45489 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45489 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:45489 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:45489 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:45489 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 Timestamp - vmod-dynamic vcl1.dyn(example.com:80) Results: 1708618810.802496 0.008379 0.008379 **** v1 vsl| 0 Error - vmod-dynamic vcl1 dyn example.com:80 getdns 901 (Queries for the name yielded all negative responses) **** dT 1.057 **** v1 vsl| 0 VCL_Log - vmod-dynamic vcl1 dyn example.com:80 timeout **** v1 vsl| 0 Timestamp - vmod-dynamic vcl1.dyn(example.com:80) Lookup: 1708618810.881813 0.000000 0.000000 **** v1 vsl| 0 Timestamp - vmod-dynamic vcl1.dyn(example.com:80) Results: 1708618810.887776 0.005963 0.005963 **** v1 vsl| 0 Error - vmod-dynamic vcl1 dyn example.com:80 getdns 901 (Queries for the name yielded all negative responses) **** dT 1.568 *** v1 CLI RX 200 **** v1 CLI RX|Message from VCC-compiler: **** v1 CLI RX|----------------------------------------------------- **** v1 CLI RX|Suppressions used: **** v1 CLI RX| count bytes template **** v1 CLI RX| 2 136 HSH_config **** v1 CLI RX| 9 360 vcc_ **** v1 CLI RX|----------------------------------------------------- **** v1 CLI RX| **** v1 CLI RX|Message from dlopen: **** v1 CLI RX|----------------------------------------------------- **** v1 CLI RX|Suppressions used: **** v1 CLI RX| count bytes template **** v1 CLI RX| 2 136 HSH_config **** v1 CLI RX|----------------------------------------------------- **** v1 CLI RX| ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.use vcl2" **** v1 CLI TX|vcl.use vcl2 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.discard vcl1" **** v1 CLI TX|vcl.discard vcl1 **** dT 1.658 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1708618810.794719/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1708618810.794719/vgc.so" as "vcl2" **** v1 vsl| 0 Timestamp - vmod-dynamic vcl2.dyn(example.com:80) Lookup: 1708618811.449167 0.000000 0.000000 **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 Timestamp - vmod-dynamic vcl2.dyn(example.com:80) Results: 1708618811.457072 0.007905 0.007905 **** v1 vsl| 0 Error - vmod-dynamic vcl2 dyn example.com:80 getdns 901 (Queries for the name yielded all negative responses) **** v1 vsl| 0 CLI - Rd vcl.state vcl1 0cold **** v1 vsl| 0 Timestamp - vmod-dynamic vcl1.dyn(example.com:80) Done: 1708618811.494451 0.000000 0.000000 **** v1 vsl| 0 VCL_Log - vmod-dynamic vcl1 dyn example.com:80 deleted (expired) **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.discard vcl1 **** dT 1.758 **** v1 vsl| 0 VCL_Log - vmod-dynamic vcl2 dyn example.com:80 timeout **** v1 vsl| 0 Timestamp - vmod-dynamic vcl2.dyn(example.com:80) Lookup: 1708618811.542969 0.000000 0.000000 **** v1 vsl| 0 Timestamp - vmod-dynamic vcl2.dyn(example.com:80) Results: 1708618811.547853 0.004884 0.004884 **** v1 vsl| 0 Error - vmod-dynamic vcl2 dyn example.com:80 getdns 901 (Queries for the name yielded all negative responses) **** dT 2.790 *** v1 debug|Error: Child (2872880) not responding to CLI, killed it. *** v1 CLI RX 200 ** v1 CLI 200 * top RESETTING after ./tests/layer_reload.vtc ** v1 Wait **** v1 CLI TX|backend.list *** v1 debug|Info: Child (2872880) said ================================================================= *** v1 debug|Info: Child (2872880) said ==2872880==ERROR: AddressSanitizer: heap-use-after-free on address 0x6120000119c4 at pc 0x7fad9b650290 bp 0x7ffe80f849a0 sp 0x7ffe80f84990 *** v1 debug|Info: Child (2872880) said READ of size 4 at 0x6120000119c4 thread T0 *** v1 debug|Info: Child (2872880) said #0 0x7fad9b65028f in dom_destroy (vmod_cache/_vmod_dynamic.29b766e616262ab0ef9252419367ce48fbf642168ba34fc382b1742a77dac5c4+0x1f28f) *** v1 debug|Info: Child (2872880) said #1 0x561c4abfd611 in vcldir_retire cache/cache_vrt_vcl.c:287 *** v1 debug|Info: Child (2872880) said #2 0x561c4abfd611 in vcldir_deref cache/cache_vrt_vcl.c:305 *** v1 debug|Info: Child (2872880) said #3 0x561c4ac00754 in VRT_Assign_Backend cache/cache_vrt_vcl.c:343 *** v1 debug|Info: Child (2872880) said #4 0x7fad998559ef in vdir_release /home/swojcik/code/varnish-cache/vmod/vmod_directors.c:99 *** v1 debug|Info: Child (2872880) said #5 0x561c4ac00420 in VRT_DelDirector cache/cache_vrt_vcl.c:321 *** v1 debug|Info: Child (2872880) said #6 0x7fad9ca2fd0b in VGC_Discard /tmp/vtc.2872792.2223da65/v1/vcl_vcl1.1708618810.078643/vgc.c:4194 *** v1 debug|Info: Child (2872880) said #7 0x7fad9ca2fd0b in VGC_Event /tmp/vtc.2872792.2223da65/v1/vcl_vcl1.1708618810.078643/vgc.c:4287 *** v1 debug|Info: Child (2872880) said #8 0x561c4abdb6e5 in vcl_send_event cache/cache_vcl.c:255 *** v1 debug|Info: Child (2872880) said #9 0x561c4abdf9e2 in VCL_Poll cache/cache_vcl.c:736 *** v1 debug|Info: Child (2872880) said #10 0x561c4abe01c4 in vcl_cli_discard cache/cache_vcl.c:903 *** v1 debug|Info: Child (2872880) said #11 0x561c4acd567f in cls_dispatch /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:273 *** v1 debug|Info: Child (2872880) said #12 0x561c4acd567f in cls_exec /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:324 *** v1 debug|Info: Child (2872880) said #13 0x561c4acd6335 in cls_feed /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:412 *** v1 debug|Info: Child (2872880) said #14 0x561c4acd6335 in VCLS_Poll /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:617 *** v1 debug|Info: Child (2872880) said #15 0x561c4ab66923 in CLI_Run cache/cache_cli.c:110 *** v1 debug|Info: Child (2872880) said #16 0x561c4abac4d9 in child_main cache/cache_main.c:467 *** v1 debug|Info: Child (2872880) said #17 0x561c4ac482df in mgt_launch_child mgt/mgt_child.c:402 *** v1 debug|Info: Child (2872880) said #18 0x561c4acd567f in cls_dispatch /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:273 *** v1 debug|Info: Child (2872880) said #19 0x561c4acd567f in cls_exec /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:324 *** v1 debug|Info: Child (2872880) said #20 0x561c4acd6335 in cls_feed /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:412 *** v1 debug|Info: Child (2872880) said #21 0x561c4acd6335 in VCLS_Poll /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:617 *** v1 debug|Info: Child (2872880) said #22 0x561c4acda316 in VEV_Once /home/swojcik/code/varnish-cache/lib/libvarnish/vev.c:466 *** v1 debug|Info: Child (2872880) said #23 0x561c4acda687 in VEV_Loop /home/swojcik/code/varnish-cache/lib/libvarnish/vev.c:354 *** v1 debug|Info: Child (2872880) said #24 0x561c4ab47691 in main mgt/mgt_main.c:995 *** v1 debug|Info: Child (2872880) said #25 0x7fadb3829d8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58 *** v1 debug|Info: Child (2872880) said #26 0x7fadb3829e3f in __libc_start_main_impl ../csu/libc-start.c:392 *** v1 debug|Info: Child (2872880) said #27 0x561c4ab48834 in _start (/opt/varnish/os-main-asan/sbin/varnishd+0x11f834) *** v1 debug|Info: Child (2872880) said *** v1 debug|Info: Child (2872880) said 0x6120000119c4 is located 260 bytes inside of 264-byte region [0x6120000118c0,0x6120000119c8) *** v1 debug|Info: Child (2872880) said freed by thread T0 here: *** v1 debug|Info: Child (2872880) said #0 0x7fadb40b4537 in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:127 *** v1 debug|Info: Child (2872880) said #1 0x7fad9b6540ff in vmod_director__fini (vmod_cache/_vmod_dynamic.29b766e616262ab0ef9252419367ce48fbf642168ba34fc382b1742a77dac5c4+0x230ff) *** v1 debug|Info: Child (2872880) said #2 0x7fad9ca2fcdd in VGC_Discard /tmp/vtc.2872792.2223da65/v1/vcl_vcl1.1708618810.078643/vgc.c:4186 *** v1 debug|Info: Child (2872880) said #3 0x7fad9ca2fcdd in VGC_Event /tmp/vtc.2872792.2223da65/v1/vcl_vcl1.1708618810.078643/vgc.c:4287 *** v1 debug|Info: Child (2872880) said #4 0x561c4abdb6e5 in vcl_send_event cache/cache_vcl.c:255 *** v1 debug|Info: Child (2872880) said #5 0x561c4abdf9e2 in VCL_Poll cache/cache_vcl.c:736 *** v1 debug|Info: Child (2872880) said #6 0x561c4abe01c4 in vcl_cli_discard cache/cache_vcl.c:903 *** v1 debug|Info: Child (2872880) said #7 0x561c4acd567f in cls_dispatch /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:273 *** v1 debug|Info: Child (2872880) said #8 0x561c4acd567f in cls_exec /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:324 *** v1 debug|Info: Child (2872880) said #9 0x561c4acd6335 in cls_feed /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:412 *** v1 debug|Info: Child (2872880) said #10 0x561c4acd6335 in VCLS_Poll /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:617 *** v1 debug|Info: Child (2872880) said #11 0x561c4ab66923 in CLI_Run cache/cache_cli.c:110 *** v1 debug|Info: Child (2872880) said #12 0x561c4abac4d9 in child_main cache/cache_main.c:467 *** v1 debug|Info: Child (2872880) said #13 0x561c4ac482df in mgt_launch_child mgt/mgt_child.c:402 *** v1 debug|Info: Child (2872880) said #14 0x561c4acd567f in cls_dispatch /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:273 *** v1 debug|Info: Child (2872880) said #15 0x561c4acd567f in cls_exec /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:324 *** v1 debug|Info: Child (2872880) said #16 0x561c4acd6335 in cls_feed /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:412 *** v1 debug|Info: Child (2872880) said #17 0x561c4acd6335 in VCLS_Poll /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:617 *** v1 debug|Info: Child (2872880) said #18 0x561c4acda316 in VEV_Once /home/swojcik/code/varnish-cache/lib/libvarnish/vev.c:466 *** v1 debug|Info: Child (2872880) said #19 0x561c4acda687 in VEV_Loop /home/swojcik/code/varnish-cache/lib/libvarnish/vev.c:354 *** v1 debug|Info: Child (2872880) said #20 0x561c4ab47691 in main mgt/mgt_main.c:995 *** v1 debug|Info: Child (2872880) said #21 0x7fadb3829d8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58 *** v1 debug|Info: Child (2872880) said *** v1 debug|Info: Child (2872880) said previously allocated by thread T0 here: *** v1 debug|Info: Child (2872880) said #0 0x7fadb40b4a57 in __interceptor_calloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:154 *** v1 debug|Info: Child (2872880) said #1 0x7fad9b65293d in vmod_director__init (vmod_cache/_vmod_dynamic.29b766e616262ab0ef9252419367ce48fbf642168ba34fc382b1742a77dac5c4+0x2193d) *** v1 debug|Info: Child (2872880) said #2 0x7fad9ca294c3 in VGC_function_vcl_init /tmp/vtc.2872792.2223da65/v1/vcl_vcl1.1708618810.078643/vgc.c:3862 *** v1 debug|Info: Child (2872880) said #3 0x561c4abdb6e5 in vcl_send_event cache/cache_vcl.c:255 *** v1 debug|Info: Child (2872880) said #4 0x561c4abdded6 in vcl_load cache/cache_vcl.c:696 *** v1 debug|Info: Child (2872880) said #5 0x561c4abdded6 in vcl_cli_load cache/cache_vcl.c:843 *** v1 debug|Info: Child (2872880) said #6 0x561c4acd567f in cls_dispatch /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:273 *** v1 debug|Info: Child (2872880) said #7 0x561c4acd567f in cls_exec /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:324 *** v1 debug|Info: Child (2872880) said #8 0x561c4acd6335 in cls_feed /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:412 *** v1 debug|Info: Child (2872880) said #9 0x561c4acd6335 in VCLS_Poll /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:617 *** v1 debug|Info: Child (2872880) said #10 0x561c4ab66923 in CLI_Run cache/cache_cli.c:110 *** v1 debug|Info: Child (2872880) said #11 0x561c4abac4d9 in child_main cache/cache_main.c:467 *** v1 debug|Info: Child (2872880) said #12 0x561c4ac482df in mgt_launch_child mgt/mgt_child.c:402 *** v1 debug|Info: Child (2872880) said #13 0x561c4acd567f in cls_dispatch /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:273 *** v1 debug|Info: Child (2872880) said #14 0x561c4acd567f in cls_exec /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:324 *** v1 debug|Info: Child (2872880) said #15 0x561c4acd6335 in cls_feed /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:412 *** v1 debug|Info: Child (2872880) said #16 0x561c4acd6335 in VCLS_Poll /home/swojcik/code/varnish-cache/lib/libvarnish/vcli_serve.c:617 *** v1 debug|Info: Child (2872880) said #17 0x561c4acda316 in VEV_Once /home/swojcik/code/varnish-cache/lib/libvarnish/vev.c:466 *** v1 debug|Info: Child (2872880) said #18 0x561c4acda687 in VEV_Loop /home/swojcik/code/varnish-cache/lib/libvarnish/vev.c:354 *** v1 debug|Info: Child (2872880) said #19 0x561c4ab47691 in main mgt/mgt_main.c:995 *** v1 debug|Info: Child (2872880) said #20 0x7fadb3829d8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58 *** v1 debug|Info: Child (2872880) said *** v1 debug|Info: Child (2872880) said SUMMARY: AddressSanitizer: heap-use-after-free (vmod_cache/_vmod_dynamic.29b766e616262ab0ef9252419367ce48fbf642168ba34fc382b1742a77dac5c4+0x1f28f) in dom_destroy *** v1 debug|Info: Child (2872880) said Shadow bytes around the buggy address: *** v1 debug|Info: Child (2872880) said 0x0c247fffa2e0: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said 0x0c247fffa2f0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said 0x0c247fffa300: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said 0x0c247fffa310: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said 0x0c247fffa320: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said =>0x0c247fffa330: fd fd fd fd fd fd fd fd[fd]fa fa fa fa fa fa fa *** v1 debug|Info: Child (2872880) said 0x0c247fffa340: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said 0x0c247fffa350: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said 0x0c247fffa360: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said 0x0c247fffa370: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said 0x0c247fffa380: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd *** v1 debug|Info: Child (2872880) said Shadow byte legend (one shadow byte represents 8 application bytes): *** v1 debug|Info: Child (2872880) said Addressable: 00 *** v1 debug|Info: Child (2872880) said Partially addressable: 01 02 03 04 05 06 07 *** v1 debug|Info: Child (2872880) said Heap left redzone: fa *** v1 debug|Info: Child (2872880) said Freed heap region: fd *** v1 debug|Info: Child (2872880) said Stack left redzone: f1 *** v1 debug|Info: Child (2872880) said Stack mid redzone: f2 *** v1 debug|Info: Child (2872880) said Stack right redzone: f3 *** v1 debug|Info: Child (2872880) said Stack after return: f5 *** v1 debug|Info: Child (2872880) said Stack use after scope: f8 *** v1 debug|Info: Child (2872880) said Global redzone: f9 *** v1 debug|Info: Child (2872880) said Global init order: f6 *** v1 debug|Info: Child (2872880) said Poisoned by user: f7 *** v1 debug|Info: Child (2872880) said Container overflow: fc *** v1 debug|Info: Child (2872880) said Array cookie: ac *** v1 debug|Info: Child (2872880) said Intra object redzone: bb *** v1 debug|Info: Child (2872880) said ASan internal: fe *** v1 debug|Info: Child (2872880) said Left alloca redzone: ca *** v1 debug|Info: Child (2872880) said Right alloca redzone: cb *** v1 debug|Info: Child (2872880) said Shadow gap: cc *** v1 debug|Info: Child (2872880) said ==2872880==ABORTING *** v1 debug|Error: Child (2872880) died signal=6 (core dumped) *** v1 debug|Error: Child (2872880) Panic at: Thu, 22 Feb 2024 16:20:12 GMT *** v1 debug|Wrong turn at cache/cache_main.c:328: *** v1 debug|Signal 6 (Aborted) received at 0x3e8002bd630 si_code -6 *** v1 debug|version = varnish-trunk revision d77da13b9baf268196075bda0808d0d2e8721470, vrt api = 18.1 *** v1 debug|ident = Linux,6.5.0-17-generic,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,epoll *** v1 debug|now = 324499.612377 (mono), 1708618811.590555 (real) *** v1 debug|Backtrace: *** v1 debug| ip=0x561c4abb7dc4 sp=0x7fadafd93b10 *** v1 debug| ip=0x561c4accff78 sp=0x7fadafd93d40 *** v1 debug| ip=0x561c4ababb1e sp=0x7fadafd93d90 *** v1 debug| ip=0x7fadb3842520 sp=0x7fadafd94380 <__sigaction+0x50> *** v1 debug| ip=0x7fadb38969fc sp=0x7ffe80f839d0 *** v1 debug| ip=0x7fadb3842476 sp=0x7ffe80f83a90 *** v1 debug| ip=0x7fadb38287f3 sp=0x7ffe80f83aa0 *** v1 debug| ip=0x7fadb40d2712 sp=0x7ffe80f83be0 <_ZN11__sanitizer5AbortEv+0x32> *** v1 debug| ip=0x7fadb40de2cc sp=0x7ffe80f83c90 <_ZN11__sanitizer3DieEv+0x4c> *** v1 debug| ip=0x7fadb40bd77c sp=0x7ffe80f83cb0 <_ZN6__asan19ScopedInErrorReportD1Ev+0x1ac> *** v1 debug| ip=0x7fadb40bd015 sp=0x7ffe80f83d00 <_ZN6__asan18ReportGenericErrorEmmmmbmjb+0x125> *** v1 debug| ip=0x7fadb40bdd3b sp=0x7ffe80f84980 <__asan_report_load4+0x3b> *** v1 debug| ip=0x7fad9b650290 sp=0x7ffe80f849b0 *** v1 debug| ip=0x561c4abfd612 sp=0x7ffe80f84a50 *** v1 debug| ip=0x561c4ac00755 sp=0x7ffe80f84a90 *** v1 debug| ip=0x7fad998559f0 sp=0x7ffe80f84ad0 *** v1 debug| ip=0x561c4ac00421 sp=0x7ffe80f84b20 *** v1 debug| ip=0x7fad9ca2fd0c sp=0x7ffe80f84b40 *** v1 debug| ip=0x561c4abdb6e6 sp=0x7ffe80f84b60 *** v1 debug| ip=0x561c4abdf9e3 sp=0x7ffe80f84c30 *** v1 debug| ip=0x561c4abe01c5 sp=0x7ffe80f84d10 *** v1 debug| ip=0x561c4acd5680 sp=0x7ffe80f84db0 *** v1 debug| ip=0x561c4acd6336 sp=0x7ffe80f84e20 *** v1 debug| ip=0x561c4ab66924 sp=0x7ffe80f87040 *** v1 debug| ip=0x561c4abac4da sp=0x7ffe80f87060 *** v1 debug| ip=0x561c4ac482e0 sp=0x7ffe80f871d0 *** v1 debug| ip=0x561c4acd5680 sp=0x7ffe80f87310 *** v1 debug| ip=0x561c4acd6336 sp=0x7ffe80f87380 *** v1 debug| ip=0x561c4acda317 sp=0x7ffe80f895a0 *** v1 debug| ip=0x561c4acda688 sp=0x7ffe80f89600 *** v1 debug| ip=0x561c4ab47692 sp=0x7ffe80f89620 *** v1 debug| ip=0x7fadb3829d90 sp=0x7ffe80f899d0 <__libc_init_first+0x90> *** v1 debug| ip=0x7fadb3829e40 sp=0x7ffe80f89a70 <__libc_start_main+0x80> *** v1 debug| ip=0x561c4ab48835 sp=0x7ffe80f89ac0 <_start+0x25> *** v1 debug|errno = 25 (Inappropriate ioctl for device) *** v1 debug|argv = { *** v1 debug| [0] = \"varnishd\", *** v1 debug| [1] = \"-d\", *** v1 debug| [2] = \"-n\", *** v1 debug| [3] = \"/tmp/vtc.2872792.2223da65/v1\", *** v1 debug| [4] = \"-i\", *** v1 debug| [5] = \"v1\", *** v1 debug| [6] = \"-p\", *** v1 debug| [7] = \"debug=+vcl_keep\", *** v1 debug| [8] = \"-p\", *** v1 debug| [9] = \"debug=+vmod_so_keep\", *** v1 debug| [10] = \"-p\", *** v1 debug| [11] = \"debug=+vsm_keep\", *** v1 debug| [12] = \"-l\", *** v1 debug| [13] = \"2m\", *** v1 debug| [14] = \"-p\", *** v1 debug| [15] = \"auto_restart=off\", *** v1 debug| [16] = \"-p\", *** v1 debug| [17] = \"syslog_cli_traffic=off\", *** v1 debug| [18] = \"-p\", *** v1 debug| [19] = \"thread_pool_min=10\", *** v1 debug| [20] = \"-p\", *** v1 debug| [21] = \"debug=+vtc_mode\", *** v1 debug| [22] = \"-p\", *** v1 debug| [23] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\", *** v1 debug| [24] = \"-p\", *** v1 debug| [25] = \"h2_initial_window_size=1m\", *** v1 debug| [26] = \"-p\", *** v1 debug| [27] = \"h2_rx_window_low_water=64k\", *** v1 debug| [28] = \"-a\", *** v1 debug| [29] = \"127.0.0.1:0\", *** v1 debug| [30] = \"-M\", *** v1 debug| [31] = \"127.0.0.1 38685\", *** v1 debug| [32] = \"-P\", *** v1 debug| [33] = \"/tmp/vtc.2872792.2223da65/v1/varnishd.pid\", *** v1 debug|} *** v1 debug|pthread.self = 0x7fadb3ee7040 *** v1 debug|pthread.name = (cache-main) *** v1 debug|pthread.attr = { *** v1 debug| guard = 0, *** v1 debug| stack_bottom = 0x7ffe8078d000, *** v1 debug| stack_top = 0x7ffe80f8a000, *** v1 debug| stack_size = 8376320, *** v1 debug|} *** v1 debug|thr.req = NULL *** v1 debug|thr.busyobj = NULL *** v1 debug|thr.worker = NULL *** v1 debug|vmods = { *** v1 debug| dynamic = {0x60b0000005c0, Varnish trunk d77da13b9baf268196075bda0808d0d2e8721470, 18.1}, *** v1 debug| directors = {0x60b000000720, Varnish trunk d77da13b9baf268196075bda0808d0d2e8721470, 0.0}, *** v1 debug|}, *** v1 debug|pools = { *** v1 debug| pool = 0x612000000040 { *** v1 debug| nidle = 9, *** v1 debug| nthr = 10, *** v1 debug| lqueue = 0 *** v1 debug| }, *** v1 debug| pool = 0x6120000001c0 { *** v1 debug| nidle = 9, *** v1 debug| nthr = 10, *** v1 debug| lqueue = 0 *** v1 debug| }, *** v1 debug|}, *** v1 debug| *** v1 debug| *** v1 debug|Debug: Child cleanup complete **** dT 2.791 *** v1 CLI RX 101 **** v1 CLI RX|Unknown request in manager process (child not running). **** v1 CLI RX|Type 'help' for more info. ** v1 Stop **** v1 CLI TX|stop **** dT 2.833 *** v1 CLI RX 300 **** v1 CLI RX|Child in state stopped *** v1 wait-stopped **** v1 CLI TX|status **** dT 2.877 *** v1 CLI RX 200 **** v1 CLI RX|Child in state stopped **** v1 CLI TX|panic.show **** dT 2.925 *** v1 CLI RX 200 **** v1 CLI RX|Panic at: Thu, 22 Feb 2024 16:20:12 GMT **** v1 CLI RX|Wrong turn at cache/cache_main.c:328: **** v1 CLI RX|Signal 6 (Aborted) received at 0x3e8002bd630 si_code -6 **** v1 CLI RX|version = varnish-trunk revision d77da13b9baf268196075bda0808d0d2e8721470, vrt api = 18.1 **** v1 CLI RX|ident = Linux,6.5.0-17-generic,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,epoll **** v1 CLI RX|now = 324499.612377 (mono), 1708618811.590555 (real) **** v1 CLI RX|Backtrace: **** v1 CLI RX| ip=0x561c4abb7dc4 sp=0x7fadafd93b10 **** v1 CLI RX| ip=0x561c4accff78 sp=0x7fadafd93d40 **** v1 CLI RX| ip=0x561c4ababb1e sp=0x7fadafd93d90 **** v1 CLI RX| ip=0x7fadb3842520 sp=0x7fadafd94380 <__sigaction+0x50> **** v1 CLI RX| ip=0x7fadb38969fc sp=0x7ffe80f839d0 **** v1 CLI RX| ip=0x7fadb3842476 sp=0x7ffe80f83a90 **** v1 CLI RX| ip=0x7fadb38287f3 sp=0x7ffe80f83aa0 **** v1 CLI RX| ip=0x7fadb40d2712 sp=0x7ffe80f83be0 <_ZN11__sanitizer5AbortEv+0x32> **** v1 CLI RX| ip=0x7fadb40de2cc sp=0x7ffe80f83c90 <_ZN11__sanitizer3DieEv+0x4c> **** v1 CLI RX| ip=0x7fadb40bd77c sp=0x7ffe80f83cb0 <_ZN6__asan19ScopedInErrorReportD1Ev+0x1ac> **** v1 CLI RX| ip=0x7fadb40bd015 sp=0x7ffe80f83d00 <_ZN6__asan18ReportGenericErrorEmmmmbmjb+0x125> **** v1 CLI RX| ip=0x7fadb40bdd3b sp=0x7ffe80f84980 <__asan_report_load4+0x3b> **** v1 CLI RX| ip=0x7fad9b650290 sp=0x7ffe80f849b0 **** v1 CLI RX| ip=0x561c4abfd612 sp=0x7ffe80f84a50 **** v1 CLI RX| ip=0x561c4ac00755 sp=0x7ffe80f84a90 **** v1 CLI RX| ip=0x7fad998559f0 sp=0x7ffe80f84ad0 **** v1 CLI RX| ip=0x561c4ac00421 sp=0x7ffe80f84b20 **** v1 CLI RX| ip=0x7fad9ca2fd0c sp=0x7ffe80f84b40 **** v1 CLI RX| ip=0x561c4abdb6e6 sp=0x7ffe80f84b60 **** v1 CLI RX| ip=0x561c4abdf9e3 sp=0x7ffe80f84c30 **** v1 CLI RX| ip=0x561c4abe01c5 sp=0x7ffe80f84d10 **** v1 CLI RX| ip=0x561c4acd5680 sp=0x7ffe80f84db0 **** v1 CLI RX| ip=0x561c4acd6336 sp=0x7ffe80f84e20 **** v1 CLI RX| ip=0x561c4ab66924 sp=0x7ffe80f87040 **** v1 CLI RX| ip=0x561c4abac4da sp=0x7ffe80f87060 **** v1 CLI RX| ip=0x561c4ac482e0 sp=0x7ffe80f871d0 **** v1 CLI RX| ip=0x561c4acd5680 sp=0x7ffe80f87310 **** v1 CLI RX| ip=0x561c4acd6336 sp=0x7ffe80f87380 **** v1 CLI RX| ip=0x561c4acda317 sp=0x7ffe80f895a0 **** v1 CLI RX| ip=0x561c4acda688 sp=0x7ffe80f89600 **** v1 CLI RX| ip=0x561c4ab47692 sp=0x7ffe80f89620 **** v1 CLI RX| ip=0x7fadb3829d90 sp=0x7ffe80f899d0 <__libc_init_first+0x90> **** v1 CLI RX| ip=0x7fadb3829e40 sp=0x7ffe80f89a70 <__libc_start_main+0x80> **** v1 CLI RX| ip=0x561c4ab48835 sp=0x7ffe80f89ac0 <_start+0x25> **** v1 CLI RX|errno = 25 (Inappropriate ioctl for device) **** v1 CLI RX|argv = { **** v1 CLI RX| [0] = \"varnishd\", **** v1 CLI RX| [1] = \"-d\", **** v1 CLI RX| [2] = \"-n\", **** v1 CLI RX| [3] = \"/tmp/vtc.2872792.2223da65/v1\", **** v1 CLI RX| [4] = \"-i\", **** v1 CLI RX| [5] = \"v1\", **** v1 CLI RX| [6] = \"-p\", **** v1 CLI RX| [7] = \"debug=+vcl_keep\", **** v1 CLI RX| [8] = \"-p\", **** v1 CLI RX| [9] = \"debug=+vmod_so_keep\", **** v1 CLI RX| [10] = \"-p\", **** v1 CLI RX| [11] = \"debug=+vsm_keep\", **** v1 CLI RX| [12] = \"-l\", **** v1 CLI RX| [13] = \"2m\", **** v1 CLI RX| [14] = \"-p\", **** v1 CLI RX| [15] = \"auto_restart=off\", **** v1 CLI RX| [16] = \"-p\", **** v1 CLI RX| [17] = \"syslog_cli_traffic=off\", **** v1 CLI RX| [18] = \"-p\", **** v1 CLI RX| [19] = \"thread_pool_min=10\", **** v1 CLI RX| [20] = \"-p\", **** v1 CLI RX| [21] = \"debug=+vtc_mode\", **** v1 CLI RX| [22] = \"-p\", **** v1 CLI RX| [23] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\", **** v1 CLI RX| [24] = \"-p\", **** v1 CLI RX| [25] = \"h2_initial_window_size=1m\", **** v1 CLI RX| [26] = \"-p\", **** v1 CLI RX| [27] = \"h2_rx_window_low_water=64k\", **** v1 CLI RX| [28] = \"-a\", **** v1 CLI RX| [29] = \"127.0.0.1:0\", **** v1 CLI RX| [30] = \"-M\", **** v1 CLI RX| [31] = \"127.0.0.1 38685\", **** v1 CLI RX| [32] = \"-P\", **** v1 CLI RX| [33] = \"/tmp/vtc.2872792.2223da65/v1/varnishd.pid\", **** v1 CLI RX|} **** v1 CLI RX|pthread.self = 0x7fadb3ee7040 **** v1 CLI RX|pthread.name = (cache-main) **** v1 CLI RX|pthread.attr = { **** v1 CLI RX| guard = 0, **** v1 CLI RX| stack_bottom = 0x7ffe8078d000, **** v1 CLI RX| stack_top = 0x7ffe80f8a000, **** v1 CLI RX| stack_size = 8376320, **** v1 CLI RX|} **** v1 CLI RX|thr.req = NULL **** v1 CLI RX|thr.busyobj = NULL **** v1 CLI RX|thr.worker = NULL **** v1 CLI RX|vmods = { **** v1 CLI RX| dynamic = {0x60b0000005c0, Varnish trunk d77da13b9baf268196075bda0808d0d2e8721470, 18.1}, **** v1 CLI RX| directors = {0x60b000000720, Varnish trunk d77da13b9baf268196075bda0808d0d2e8721470, 0.0}, **** v1 CLI RX|}, **** v1 CLI RX|pools = { **** v1 CLI RX| pool = 0x612000000040 { **** v1 CLI RX| nidle = 9, **** v1 CLI RX| nthr = 10, **** v1 CLI RX| lqueue = 0 **** v1 CLI RX| }, **** v1 CLI RX| pool = 0x6120000001c0 { **** v1 CLI RX| nidle = 9, **** v1 CLI RX| nthr = 10, **** v1 CLI RX| lqueue = 0 **** v1 CLI RX| }, **** v1 CLI RX|}, **** v1 CLI RX| **** v1 CLI RX| ---- v1 Unexpected panic * top failure during reset * diag 0.0 2606:2800:220:1:248:1893:25c8:1946 example.com * diag 0.0 ----------------------------------------------------- * diag 0.0 Suppressions used: * diag 0.0 count bytes template * diag 0.0 7 1491 parse_string * diag 0.0 ----------------------------------------------------- * diag 0.0 # top TEST ./tests/layer_reload.vtc FAILED (3.042) exit=2 FAIL tests/layer_reload.vtc (exit status: 2) ```
nigoroll commented 6 months ago

Thank you for the excellent bug report! I can reproduce the asan report and am looking at it.