uplex-varnish/libvmod-file
7
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

synth.vtc causes a panic in vcl_call_method() when CFLAGS includes -O0 #2

New issue
Closed
opened 2024-10-16 15:48:03 +00:00 by geoff · 4 comments
geoff commented 2024-10-16 15:48:03 +00:00 (Migrated from code.uplex.de)
Copy link

The synth.vtc test has been failing with a panic when the VMOD is built so that CFLAGS includes -O0. I noticed it when running the coverage target, which among other things sets -O0, but the problem evidently isn't caused by the gcov stuff, just the -O setting.

(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, 
    signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1  0x00007f86996a9e9f in __pthread_kill_internal (signo=6, 
    threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  0x00007f869965afb2 in __GI_raise (sig=sig@entry=6)
    at ../sysdeps/posix/raise.c:26
#3  0x00007f8699645472 in __GI_abort () at ./stdlib/abort.c:79
#4  0x000055936e929e7e in pan_ic (func=<optimized out>, file=<optimized out>, 
    line=<optimized out>, cond=<optimized out>, kind=<optimized out>)
    at cache/cache_panic.c:860
#5  0x000055936e9d94d5 in VAS_Fail (
    func=func@entry=0x55936ea02fa0 <__func__.16> "vcl_call_method", 
    file=file@entry=0x55936ea022a0 "cache/cache_vrt_vcl.c", 
    line=line@entry=649, 
    cond=cond@entry=0x55936ea023f7 "aws == WS_Snapshot(wrk->aws)", 
    kind=kind@entry=VAS_ASSERT) at vas.c:67
#6  0x000055936e97e960 in vcl_call_method (wrk=wrk@entry=0x7f86995b4b90, 
    req=req@entry=0x7f868c066020, bo=bo@entry=0x0, specific=<optimized out>, 
    method=method@entry=512, func=0x7f86994c7190, track_call=0)
    at cache/cache_vrt_vcl.c:649
#7  0x000055936e981d59 in VCL_synth_method (vcl=<optimized out>, 
    wrk=wrk@entry=0x7f86995b4b90, req=req@entry=0x7f868c066020, 
    bo=bo@entry=0x0, specific=<optimized out>)
    at ../../include/tbl/vcl_returns.h:203
#8  0x000055936e963782 in cnt_synth (wrk=0x7f86995b4b90, req=0x7f868c066020)
    at cache/cache_req_fsm.c:335
#9  0x000055936e9640a8 in CNT_Request (req=req@entry=0x7f868c066020)
    at cache/cache_req_fsm.c:1187
#10 0x000055936e98e6e2 in HTTP1_Session (req=0x7f868c066020, 
    wrk=0x7f86995b4b90) at http1/cache_http1_fsm.c:392
#11 http1_req (wrk=0x7f86995b4b90, arg=0x7f868c066020)
    at http1/cache_http1_fsm.c:87
#12 0x000055936e983422 in Pool_Work_Thread (wrk=0x7f86995b4b90, 
    pp=0x7f869680e140) at cache/cache_wrk.c:496
#13 WRK_Thread (qp=0x7f869680e140, stacksize=<optimized out>, 
    thread_workspace=<optimized out>) at cache/cache_wrk.c:157
#14 0x000055936e9839d4 in pool_thread (priv=0x7f869580e160)
    at cache/cache_wrk.c:529
#15 0x00007f86996a8144 in start_thread (arg=<optimized out>)
    at ./nptl/pthread_create.c:442
#16 0x00007f86997287dc in clone3 ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
(gdb) f 6
#6  0x000055936e97e960 in vcl_call_method (wrk=wrk@entry=0x7f86995b4b90, 
    req=req@entry=0x7f868c066020, bo=bo@entry=0x0, specific=<optimized out>, 
    method=method@entry=512, func=0x7f86994c7190, track_call=0)
    at cache/cache_vrt_vcl.c:649
649		assert(aws == WS_Snapshot(wrk->aws));
(gdb) printf "%p\n", aws
0x7f8699a4d000
(gdb) p wrk->aws 
$1 = {{magic = 905626964, id = "wrk", s = 0x7f86995b42f0 "YMK\214", 
    f = 0x7f86995b42f0 "YMK\214", r = 0x0, 
    e = 0x7f86995b4ae8 "\025\025\025\025\025\025\025\025"}}

The assertion is here, where the comments say:

	/*
	 * VCL/Vmods are not allowed to make permanent allocations from
	 * wrk->aws, but they can reserve and return from it.
	 */

The aws variable is read from WS_Snapshot(wrk->aws) before calling the VMOD method, and then checked with this assertion afterward.

This is a peculiar problem, because it only happens when the VMOD's .synth() method is tested, which not only does not reserve any workspace, it doesn't use any workspace at all, at least not directly in the VMOD code.

This is the panic message part of the VTC log (for some reason, the panic is there twice). The full log is in the attachment: synth.log

***  v1    debug|Error: Child (1845907) died signal=6 (core dumped)
***  v1    debug|Error: Child (1845907) Panic at: Wed, 16 Oct 2024 14:33:49 GMT
***  v1    debug|Assert error in vcl_call_method(), cache/cache_vrt_vcl.c line 649:
***  v1    debug|  Condition(aws == WS_Snapshot(wrk->aws)) not true.
***  v1    debug|version = varnish-7.5.0 revision eef25264e5ca5f96a77129308edb83ccf84cb1b1, vrt api = 19.0
***  v1    debug|ident = Linux,6.1.0-26-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,epoll
***  v1    debug|now = 245904.745299 (mono), 1729089229.483392 (real)
***  v1    debug|Backtrace:
***  v1    debug|  0x55936e95bb7e: varnishd(+0x5bb7e) [0x55936e95bb7e]
***  v1    debug|  0x55936e9d94d5: varnishd(VAS_Fail+0x45) [0x55936e9d94d5]
***  v1    debug|  0x55936e97e960: varnishd(+0x7e960) [0x55936e97e960]
***  v1    debug|  0x55936e981d59: varnishd(VCL_synth_method+0x69) [0x55936e981d59]
***  v1    debug|  0x55936e963782: varnishd(+0x63782) [0x55936e963782]
***  v1    debug|  0x55936e9640a8: varnishd(CNT_Request+0xd8) [0x55936e9640a8]
***  v1    debug|  0x55936e98e6e2: varnishd(+0x8e6e2) [0x55936e98e6e2]
***  v1    debug|  0x55936e983422: varnishd(+0x83422) [0x55936e983422]
***  v1    debug|  0x55936e9839d4: varnishd(+0x839d4) [0x55936e9839d4]
***  v1    debug|  0x7f86996a8144: /lib/x86_64-linux-gnu/libc.so.6(+0x89144) [0x7f86996a8144]
***  v1    debug|  0x7f86997287dc: /lib/x86_64-linux-gnu/libc.so.6(+0x1097dc) [0x7f86997287dc]
***  v1    debug|argv = {
***  v1    debug|  [0] = \"varnishd\",
***  v1    debug|  [1] = \"-d\",
***  v1    debug|  [2] = \"-n\",
***  v1    debug|  [3] = \"/tmp/vtc.1845883.013b6cbb/v1\",
***  v1    debug|  [4] = \"-i\",
***  v1    debug|  [5] = \"v1\",
***  v1    debug|  [6] = \"-p\",
***  v1    debug|  [7] = \"vcl_path=/home/geoff/Develop/varnish/vmods/libvmod-file/vcl:/usr/local/share/varnish/vcl\",
***  v1    debug|  [8] = \"-p\",
***  v1    debug|  [9] = \"vmod_path=/home/geoff/Develop/varnish/vmods/libvmod-file/src/.libs:/usr/local/lib/varnish/vmods:/usr/local/lib/varnish/vmods\",
***  v1    debug|  [10] = \"-p\",
***  v1    debug|  [11] = \"debug=+vcl_keep\",
***  v1    debug|  [12] = \"-p\",
***  v1    debug|  [13] = \"debug=+vmod_so_keep\",
***  v1    debug|  [14] = \"-p\",
***  v1    debug|  [15] = \"debug=+vsm_keep\",
***  v1    debug|  [16] = \"-l\",
***  v1    debug|  [17] = \"2m\",
***  v1    debug|  [18] = \"-p\",
***  v1    debug|  [19] = \"auto_restart=off\",
***  v1    debug|  [20] = \"-p\",
***  v1    debug|  [21] = \"syslog_cli_traffic=off\",
***  v1    debug|  [22] = \"-p\",
***  v1    debug|  [23] = \"thread_pool_min=10\",
***  v1    debug|  [24] = \"-p\",
***  v1    debug|  [25] = \"debug=+vtc_mode\",
***  v1    debug|  [26] = \"-p\",
***  v1    debug|  [27] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\",
***  v1    debug|  [28] = \"-p\",
***  v1    debug|  [29] = \"h2_initial_window_size=1m\",
***  v1    debug|  [30] = \"-p\",
***  v1    debug|  [31] = \"h2_rx_window_low_water=64k\",
***  v1    debug|  [32] = \"-a\",
***  v1    debug|  [33] = \"127.0.0.1:0\",
***  v1    debug|  [34] = \"-M\",
***  v1    debug|  [35] = \"127.0.0.1 37435\",
***  v1    debug|  [36] = \"-P\",
***  v1    debug|  [37] = \"/tmp/vtc.1845883.013b6cbb/v1/varnishd.pid\",
***  v1    debug|}
***  v1    debug|pthread.self = 0x7f86995b56c0
***  v1    debug|pthread.name = (cache-worker)
***  v1    debug|pthread.attr = {
***  v1    debug|  guard = 4096,
***  v1    debug|  stack_bottom = 0x7f86995a2000,
***  v1    debug|  stack_top = 0x7f86995b6000,
***  v1    debug|  stack_size = 81920,
***  v1    debug|}
***  v1    debug|thr.req = 0x7f868c066020 {
***  v1    debug|  vxid = 1001, transport = HTTP/1 {
***  v1    debug|    state = HTTP1::Proc
***  v1    debug|  }
***  v1    debug|  step = Req Step synth
***  v1    debug|  req_body = none,
***  v1    debug|  err_code = 200, err_reason = OK,
***  v1    debug|  restarts = 0, esi_level = 0,
***  v1    debug|  vary_b = (nil), vary_e = (nil),
***  v1    debug|  d_ttl = -1.000000, d_grace = -1.000000,
***  v1    debug|  storage = (nil),
***  v1    debug|  sess = 0x7f868bc0ef20 {
***  v1    debug|    fd = 19, vxid = 1000,
***  v1    debug|    t_open = 1729089229.483291,
***  v1    debug|    t_idle = 1729089229.483291,
***  v1    debug|    ws = 0x7f868bc0ef60 {
***  v1    debug|      id = \"ses\",
***  v1    debug|      {s, f, r, e} = {0x7f868bc0efb8, +96, (nil), +576},
***  v1    debug|    },
***  v1    debug|    transport = HTTP/1 {
***  v1    debug|      state = HTTP1::Proc
***  v1    debug|    }
***  v1    debug|    client = 127.0.0.1 56672 127.0.0.1:38015,
***  v1    debug|    local.endpoint = 127.0.0.1:38015,
***  v1    debug|    local.socket = a0,
***  v1    debug|    local.ip = 127.0.0.1:38015,
***  v1    debug|    remote.ip = 127.0.0.1:56672,
***  v1    debug|    server.ip = 127.0.0.1:38015,
***  v1    debug|    client.ip = 127.0.0.1:56672,
***  v1    debug|  },
***  v1    debug|  worker = 0x7f86995b4b90 {
***  v1    debug|    ws = 0x7f86995b4c18 {
***  v1    debug|      id = \"wrk\",
***  v1    debug|      {s, f, r, e} = {0x7f86995b42f0, +0, (nil), +2040},
***  v1    debug|    },
***  v1    debug|    VCL::method = SYNTH,
***  v1    debug|    VCL::methods = {RECV, HASH, SYNTH},
***  v1    debug|  },
***  v1    debug|  ws = 0x7f868c066180 {
***  v1    debug|    id = \"req\",
***  v1    debug|    {s, f, r, e} = {0x7f868c06b098, +184, (nil), +77664},
***  v1    debug|  },
***  v1    debug|  http_conn = 0x7f868c06b010 {
***  v1    debug|    fd = 19 (@0x7f868bc0ef44),
***  v1    debug|    doclose = null(Not Closing)
***  v1    debug|    ws = 0x7f868c066180 {
***  v1    debug|      [Already dumped, see above]
***  v1    debug|    },
***  v1    debug|    {rxbuf_b, rxbuf_e} = {0x7f868c06b098, 0x7f868c06b0cb},
***  v1    debug|    {pipeline_b, pipeline_e} = {(nil), (nil)},
***  v1    debug|    content_length = -1,
***  v1    debug|    body_status = none,
***  v1    debug|    first_byte_timeout = 0.000000,
***  v1    debug|    between_bytes_timeout = 0.000000,
***  v1    debug|  },
***  v1    debug|  http[req] = 0x7f868c066220 {
***  v1    debug|    ws = 0x7f868c066180 {
***  v1    debug|      [Already dumped, see above]
***  v1    debug|    },
***  v1    debug|    hdrs {
***  v1    debug|      \"GET\",
***  v1    debug|      \"/\",
***  v1    debug|      \"HTTP/1.1\",
***  v1    debug|      \"Host: 127.0.0.1\",
***  v1    debug|      \"User-Agent: c1\",
***  v1    debug|      \"X-Forwarded-For: 127.0.0.1\",
***  v1    debug|      \"Via: 1.1 v1 (Varnish/7.5)\",
***  v1    debug|    },
***  v1    debug|  },
***  v1    debug|  http[resp] = 0x7f868c066b10 {
***  v1    debug|    ws = 0x7f868c066180 {
***  v1    debug|      [Already dumped, see above]
***  v1    debug|    },
***  v1    debug|    hdrs {
***  v1    debug|      \"HTTP/1.1\",
***  v1    debug|      \"200\",
***  v1    debug|      \"OK\",
***  v1    debug|      \"Date: Wed, 16 Oct 2024 14:33:49 GMT\",
***  v1    debug|      \"Server: Varnish\",
***  v1    debug|      \"X-Varnish: 1001\",
***  v1    debug|    },
***  v1    debug|  },
***  v1    debug|  vdc = 0x7f868c06afd0 {
***  v1    debug|    .magic = 0x00000000 EXPECTED: VDP_CTX_MAGIC=0xee501df7
***  v1    debug|  }
***  v1    debug|  vcl[vcl] = 0x7f8698c372a0 {
***  v1    debug|    name = \"vcl1\",
***  v1    debug|    busy = 1,
***  v1    debug|    discard = 0,
***  v1    debug|    state = auto,
***  v1    debug|    temp = warm,
***  v1    debug|    conf = 0x7f86994cd4a0 {
***  v1    debug|      syntax = \"41\",
***  v1    debug|      srcname = {
***  v1    debug|        [0] = \"<vcl.inline>\",
***  v1    debug|        [1] = \"<builtin>\",
***  v1    debug|      },
***  v1    debug|      instances = {
***  v1    debug|        \"backend_err\" = 0x7f8698d8c650,
***  v1    debug|        \"synth\" = 0x7f8698d8c5b0,
***  v1    debug|      },
***  v1    debug|    },
***  v1    debug|  },
***  v1    debug|  vpi = 0x7f86995b42e0 {
***  v1    debug|    handling (VCL::return) = 0x2 (deliver),
***  v1    debug|    ref = 5,
***  v1    debug|    vpi_ref = 0x7f86994ccc80 {
***  v1    debug|      source = 0 (\"<vcl.inline>\"),
***  v1    debug|      offset = 325,
***  v1    debug|      line = 19,
***  v1    debug|      pos = 17,
***  v1    debug|      src = \"set resp.reason = \\\"OK\\\";\"
***  v1    debug|    },
***  v1    debug|  },
***  v1    debug|  flags = {
***  v1    debug|  },
***  v1    debug|  privs = 0x7f868c066210 {
***  v1    debug|  },
***  v1    debug|  top = 0x7f868c06b078 {
***  v1    debug|    req = 0x7f868c066020 {
***  v1    debug|      [Already dumped, see above]
***  v1    debug|    },
***  v1    debug|    privs = 0x7f868c06b090 {
***  v1    debug|    },
***  v1    debug|    vcl[vcl0] = NULL
***  v1    debug|  },
***  v1    debug|},
***  v1    debug|thr.busyobj = NULL
***  v1    debug|thr.worker = 0x7f86995b4b90 {
***  v1    debug|  [Already dumped, see above]
***  v1    debug|},
***  v1    debug|vmods = {
***  v1    debug|  file = {0x7f8698c35240, Varnish 7.5.0 eef25264e5ca5f96a77129308edb83ccf84cb1b1, 19.0},
***  v1    debug|},
***  v1    debug|pools = {
***  v1    debug|  pool = 0x7f869680e140 {
***  v1    debug|    nidle = 8,
***  v1    debug|    nthr = 10,
***  v1    debug|    lqueue = 0
***  v1    debug|  },
***  v1    debug|  pool = 0x7f869680e780 {
***  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    0.750
***  v1    CLI RX  200
**** v1    CLI RX|Panic at: Wed, 16 Oct 2024 14:33:49 GMT
**** v1    CLI RX|Assert error in vcl_call_method(), cache/cache_vrt_vcl.c line 649:
**** v1    CLI RX|  Condition(aws == WS_Snapshot(wrk->aws)) not true.
**** v1    CLI RX|version = varnish-7.5.0 revision eef25264e5ca5f96a77129308edb83ccf84cb1b1, vrt api = 19.0
**** v1    CLI RX|ident = Linux,6.1.0-26-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,epoll
**** v1    CLI RX|now = 245904.745299 (mono), 1729089229.483392 (real)
**** v1    CLI RX|Backtrace:
**** v1    CLI RX|  0x55936e95bb7e: varnishd(+0x5bb7e) [0x55936e95bb7e]
**** v1    CLI RX|  0x55936e9d94d5: varnishd(VAS_Fail+0x45) [0x55936e9d94d5]
**** v1    CLI RX|  0x55936e97e960: varnishd(+0x7e960) [0x55936e97e960]
**** v1    CLI RX|  0x55936e981d59: varnishd(VCL_synth_method+0x69) [0x55936e981d59]
**** v1    CLI RX|  0x55936e963782: varnishd(+0x63782) [0x55936e963782]
**** v1    CLI RX|  0x55936e9640a8: varnishd(CNT_Request+0xd8) [0x55936e9640a8]
**** v1    CLI RX|  0x55936e98e6e2: varnishd(+0x8e6e2) [0x55936e98e6e2]
**** v1    CLI RX|  0x55936e983422: varnishd(+0x83422) [0x55936e983422]
**** v1    CLI RX|  0x55936e9839d4: varnishd(+0x839d4) [0x55936e9839d4]
**** v1    CLI RX|  0x7f86996a8144: /lib/x86_64-linux-gnu/libc.so.6(+0x89144) [0x7f86996a8144]
**** v1    CLI RX|  0x7f86997287dc: /lib/x86_64-linux-gnu/libc.so.6(+0x1097dc) [0x7f86997287dc]
**** 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.1845883.013b6cbb/v1\",
**** v1    CLI RX|  [4] = \"-i\",
**** v1    CLI RX|  [5] = \"v1\",
**** v1    CLI RX|  [6] = \"-p\",
**** v1    CLI RX|  [7] = \"vcl_path=/home/geoff/Develop/varnish/vmods/libvmod-file/vcl:/usr/local/share/varnish/vcl\",
**** v1    CLI RX|  [8] = \"-p\",
**** v1    CLI RX|  [9] = \"vmod_path=/home/geoff/Develop/varnish/vmods/libvmod-file/src/.libs:/usr/local/lib/varnish/vmods:/usr/local/lib/varnish/vmods\",
**** v1    CLI RX|  [10] = \"-p\",
**** v1    CLI RX|  [11] = \"debug=+vcl_keep\",
**** v1    CLI RX|  [12] = \"-p\",
**** v1    CLI RX|  [13] = \"debug=+vmod_so_keep\",
**** v1    CLI RX|  [14] = \"-p\",
**** v1    CLI RX|  [15] = \"debug=+vsm_keep\",
**** v1    CLI RX|  [16] = \"-l\",
**** v1    CLI RX|  [17] = \"2m\",
**** v1    CLI RX|  [18] = \"-p\",
**** v1    CLI RX|  [19] = \"auto_restart=off\",
**** v1    CLI RX|  [20] = \"-p\",
**** v1    CLI RX|  [21] = \"syslog_cli_traffic=off\",
**** v1    CLI RX|  [22] = \"-p\",
**** v1    CLI RX|  [23] = \"thread_pool_min=10\",
**** v1    CLI RX|  [24] = \"-p\",
**** v1    CLI RX|  [25] = \"debug=+vtc_mode\",
**** v1    CLI RX|  [26] = \"-p\",
**** v1    CLI RX|  [27] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\",
**** v1    CLI RX|  [28] = \"-p\",
**** v1    CLI RX|  [29] = \"h2_initial_window_size=1m\",
**** v1    CLI RX|  [30] = \"-p\",
**** v1    CLI RX|  [31] = \"h2_rx_window_low_water=64k\",
**** v1    CLI RX|  [32] = \"-a\",
**** v1    CLI RX|  [33] = \"127.0.0.1:0\",
**** v1    CLI RX|  [34] = \"-M\",
**** v1    CLI RX|  [35] = \"127.0.0.1 37435\",
**** v1    CLI RX|  [36] = \"-P\",
**** v1    CLI RX|  [37] = \"/tmp/vtc.1845883.013b6cbb/v1/varnishd.pid\",
**** v1    CLI RX|}
**** v1    CLI RX|pthread.self = 0x7f86995b56c0
**** v1    CLI RX|pthread.name = (cache-worker)
**** v1    CLI RX|pthread.attr = {
**** v1    CLI RX|  guard = 4096,
**** v1    CLI RX|  stack_bottom = 0x7f86995a2000,
**** v1    CLI RX|  stack_top = 0x7f86995b6000,
**** v1    CLI RX|  stack_size = 81920,
**** v1    CLI RX|}
**** v1    CLI RX|thr.req = 0x7f868c066020 {
**** v1    CLI RX|  vxid = 1001, transport = HTTP/1 {
**** v1    CLI RX|    state = HTTP1::Proc
**** v1    CLI RX|  }
**** v1    CLI RX|  step = Req Step synth
**** v1    CLI RX|  req_body = none,
**** v1    CLI RX|  err_code = 200, err_reason = OK,
**** v1    CLI RX|  restarts = 0, esi_level = 0,
**** v1    CLI RX|  vary_b = (nil), vary_e = (nil),
**** v1    CLI RX|  d_ttl = -1.000000, d_grace = -1.000000,
**** v1    CLI RX|  storage = (nil),
**** v1    CLI RX|  sess = 0x7f868bc0ef20 {
**** v1    CLI RX|    fd = 19, vxid = 1000,
**** v1    CLI RX|    t_open = 1729089229.483291,
**** v1    CLI RX|    t_idle = 1729089229.483291,
**** v1    CLI RX|    ws = 0x7f868bc0ef60 {
**** v1    CLI RX|      id = \"ses\",
**** v1    CLI RX|      {s, f, r, e} = {0x7f868bc0efb8, +96, (nil), +576},
**** v1    CLI RX|    },
**** v1    CLI RX|    transport = HTTP/1 {
**** v1    CLI RX|      state = HTTP1::Proc
**** v1    CLI RX|    }
**** v1    CLI RX|    client = 127.0.0.1 56672 127.0.0.1:38015,
**** v1    CLI RX|    local.endpoint = 127.0.0.1:38015,
**** v1    CLI RX|    local.socket = a0,
**** v1    CLI RX|    local.ip = 127.0.0.1:38015,
**** v1    CLI RX|    remote.ip = 127.0.0.1:56672,
**** v1    CLI RX|    server.ip = 127.0.0.1:38015,
**** v1    CLI RX|    client.ip = 127.0.0.1:56672,
**** v1    CLI RX|  },
**** v1    CLI RX|  worker = 0x7f86995b4b90 {
**** v1    CLI RX|    ws = 0x7f86995b4c18 {
**** v1    CLI RX|      id = \"wrk\",
**** v1    CLI RX|      {s, f, r, e} = {0x7f86995b42f0, +0, (nil), +2040},
**** v1    CLI RX|    },
**** v1    CLI RX|    VCL::method = SYNTH,
**** v1    CLI RX|    VCL::methods = {RECV, HASH, SYNTH},
**** v1    CLI RX|  },
**** v1    CLI RX|  ws = 0x7f868c066180 {
**** v1    CLI RX|    id = \"req\",
**** v1    CLI RX|    {s, f, r, e} = {0x7f868c06b098, +184, (nil), +77664},
**** v1    CLI RX|  },
**** v1    CLI RX|  http_conn = 0x7f868c06b010 {
**** v1    CLI RX|    fd = 19 (@0x7f868bc0ef44),
**** v1    CLI RX|    doclose = null(Not Closing)
**** v1    CLI RX|    ws = 0x7f868c066180 {
**** v1    CLI RX|      [Already dumped, see above]
**** v1    CLI RX|    },
**** v1    CLI RX|    {rxbuf_b, rxbuf_e} = {0x7f868c06b098, 0x7f868c06b0cb},
**** v1    CLI RX|    {pipeline_b, pipeline_e} = {(nil), (nil)},
**** v1    CLI RX|    content_length = -1,
**** v1    CLI RX|    body_status = none,
**** v1    CLI RX|    first_byte_timeout = 0.000000,
**** v1    CLI RX|    between_bytes_timeout = 0.000000,
**** v1    CLI RX|  },
**** v1    CLI RX|  http[req] = 0x7f868c066220 {
**** v1    CLI RX|    ws = 0x7f868c066180 {
**** v1    CLI RX|      [Already dumped, see above]
**** v1    CLI RX|    },
**** v1    CLI RX|    hdrs {
**** v1    CLI RX|      \"GET\",
**** v1    CLI RX|      \"/\",
**** v1    CLI RX|      \"HTTP/1.1\",
**** v1    CLI RX|      \"Host: 127.0.0.1\",
**** v1    CLI RX|      \"User-Agent: c1\",
**** v1    CLI RX|      \"X-Forwarded-For: 127.0.0.1\",
**** v1    CLI RX|      \"Via: 1.1 v1 (Varnish/7.5)\",
**** v1    CLI RX|    },
**** v1    CLI RX|  },
**** v1    CLI RX|  http[resp] = 0x7f868c066b10 {
**** v1    CLI RX|    ws = 0x7f868c066180 {
**** v1    CLI RX|      [Already dumped, see above]
**** v1    CLI RX|    },
**** v1    CLI RX|    hdrs {
**** v1    CLI RX|      \"HTTP/1.1\",
**** v1    CLI RX|      \"200\",
**** v1    CLI RX|      \"OK\",
**** v1    CLI RX|      \"Date: Wed, 16 Oct 2024 14:33:49 GMT\",
**** v1    CLI RX|      \"Server: Varnish\",
**** v1    CLI RX|      \"X-Varnish: 1001\",
**** v1    CLI RX|    },
**** v1    CLI RX|  },
**** v1    CLI RX|  vdc = 0x7f868c06afd0 {
**** v1    CLI RX|    .magic = 0x00000000 EXPECTED: VDP_CTX_MAGIC=0xee501df7
**** v1    CLI RX|  }
**** v1    CLI RX|  vcl[vcl] = 0x7f8698c372a0 {
**** v1    CLI RX|    name = \"vcl1\",
**** v1    CLI RX|    busy = 1,
**** v1    CLI RX|    discard = 0,
**** v1    CLI RX|    state = auto,
**** v1    CLI RX|    temp = warm,
**** v1    CLI RX|    conf = 0x7f86994cd4a0 {
**** v1    CLI RX|      syntax = \"41\",
**** v1    CLI RX|      srcname = {
**** v1    CLI RX|        [0] = \"<vcl.inline>\",
**** v1    CLI RX|        [1] = \"<builtin>\",
**** v1    CLI RX|      },
**** v1    CLI RX|      instances = {
**** v1    CLI RX|        \"backend_err\" = 0x7f8698d8c650,
**** v1    CLI RX|        \"synth\" = 0x7f8698d8c5b0,
**** v1    CLI RX|      },
**** v1    CLI RX|    },
**** v1    CLI RX|  },
**** v1    CLI RX|  vpi = 0x7f86995b42e0 {
**** v1    CLI RX|    handling (VCL::return) = 0x2 (deliver),
**** v1    CLI RX|    ref = 5,
**** v1    CLI RX|    vpi_ref = 0x7f86994ccc80 {
**** v1    CLI RX|      source = 0 (\"<vcl.inline>\"),
**** v1    CLI RX|      offset = 325,
**** v1    CLI RX|      line = 19,
**** v1    CLI RX|      pos = 17,
**** v1    CLI RX|      src = \"set resp.reason = \\\"OK\\\";\"
**** v1    CLI RX|    },
**** v1    CLI RX|  },
**** v1    CLI RX|  flags = {
**** v1    CLI RX|  },
**** v1    CLI RX|  privs = 0x7f868c066210 {
**** v1    CLI RX|  },
**** v1    CLI RX|  top = 0x7f868c06b078 {
**** v1    CLI RX|    req = 0x7f868c066020 {
**** v1    CLI RX|      [Already dumped, see above]
**** v1    CLI RX|    },
**** v1    CLI RX|    privs = 0x7f868c06b090 {
**** v1    CLI RX|    },
**** v1    CLI RX|    vcl[vcl0] = NULL
**** v1    CLI RX|  },
**** v1    CLI RX|},
**** v1    CLI RX|thr.busyobj = NULL
**** v1    CLI RX|thr.worker = 0x7f86995b4b90 {
**** v1    CLI RX|  [Already dumped, see above]
**** v1    CLI RX|},
**** v1    CLI RX|vmods = {
**** v1    CLI RX|  file = {0x7f8698c35240, Varnish 7.5.0 eef25264e5ca5f96a77129308edb83ccf84cb1b1, 19.0},
**** v1    CLI RX|},
**** v1    CLI RX|pools = {
**** v1    CLI RX|  pool = 0x7f869680e140 {
**** v1    CLI RX|    nidle = 8,
**** v1    CLI RX|    nthr = 10,
**** v1    CLI RX|    lqueue = 0
**** v1    CLI RX|  },
**** v1    CLI RX|  pool = 0x7f869680e780 {
**** 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
#    top  TEST ./vtc/synth.vtc FAILED (0.750) exit=2
FAIL vtc/synth.vtc (exit status: 2)
The `synth.vtc` test has been failing with a panic when the VMOD is built so that `CFLAGS` includes `-O0`. I noticed it when running the coverage target, which among other things sets `-O0`, but the problem evidently isn't caused by the gcov stuff, just the `-O` setting. ``` (gdb) bt #0 __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44 #1 0x00007f86996a9e9f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78 #2 0x00007f869965afb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26 #3 0x00007f8699645472 in __GI_abort () at ./stdlib/abort.c:79 #4 0x000055936e929e7e in pan_ic (func=<optimized out>, file=<optimized out>, line=<optimized out>, cond=<optimized out>, kind=<optimized out>) at cache/cache_panic.c:860 #5 0x000055936e9d94d5 in VAS_Fail ( func=func@entry=0x55936ea02fa0 <__func__.16> "vcl_call_method", file=file@entry=0x55936ea022a0 "cache/cache_vrt_vcl.c", line=line@entry=649, cond=cond@entry=0x55936ea023f7 "aws == WS_Snapshot(wrk->aws)", kind=kind@entry=VAS_ASSERT) at vas.c:67 #6 0x000055936e97e960 in vcl_call_method (wrk=wrk@entry=0x7f86995b4b90, req=req@entry=0x7f868c066020, bo=bo@entry=0x0, specific=<optimized out>, method=method@entry=512, func=0x7f86994c7190, track_call=0) at cache/cache_vrt_vcl.c:649 #7 0x000055936e981d59 in VCL_synth_method (vcl=<optimized out>, wrk=wrk@entry=0x7f86995b4b90, req=req@entry=0x7f868c066020, bo=bo@entry=0x0, specific=<optimized out>) at ../../include/tbl/vcl_returns.h:203 #8 0x000055936e963782 in cnt_synth (wrk=0x7f86995b4b90, req=0x7f868c066020) at cache/cache_req_fsm.c:335 #9 0x000055936e9640a8 in CNT_Request (req=req@entry=0x7f868c066020) at cache/cache_req_fsm.c:1187 #10 0x000055936e98e6e2 in HTTP1_Session (req=0x7f868c066020, wrk=0x7f86995b4b90) at http1/cache_http1_fsm.c:392 #11 http1_req (wrk=0x7f86995b4b90, arg=0x7f868c066020) at http1/cache_http1_fsm.c:87 #12 0x000055936e983422 in Pool_Work_Thread (wrk=0x7f86995b4b90, pp=0x7f869680e140) at cache/cache_wrk.c:496 #13 WRK_Thread (qp=0x7f869680e140, stacksize=<optimized out>, thread_workspace=<optimized out>) at cache/cache_wrk.c:157 #14 0x000055936e9839d4 in pool_thread (priv=0x7f869580e160) at cache/cache_wrk.c:529 #15 0x00007f86996a8144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442 #16 0x00007f86997287dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81 (gdb) f 6 #6 0x000055936e97e960 in vcl_call_method (wrk=wrk@entry=0x7f86995b4b90, req=req@entry=0x7f868c066020, bo=bo@entry=0x0, specific=<optimized out>, method=method@entry=512, func=0x7f86994c7190, track_call=0) at cache/cache_vrt_vcl.c:649 649 assert(aws == WS_Snapshot(wrk->aws)); (gdb) printf "%p\n", aws 0x7f8699a4d000 (gdb) p wrk->aws $1 = {{magic = 905626964, id = "wrk", s = 0x7f86995b42f0 "YMK\214", f = 0x7f86995b42f0 "YMK\214", r = 0x0, e = 0x7f86995b4ae8 "\025\025\025\025\025\025\025\025"}} ``` The assertion is [here](https://github.com/varnishcache/varnish-cache/blob/master/bin/varnishd/cache/cache_vrt_vcl.c#L645), where the comments say: ``` /* * VCL/Vmods are not allowed to make permanent allocations from * wrk->aws, but they can reserve and return from it. */ ``` The `aws` variable is read from `WS_Snapshot(wrk->aws)` before calling the VMOD method, and then checked with this assertion afterward. This is a peculiar problem, because it only happens when the VMOD's `.synth()` method is tested, which not only does not reserve any workspace, it doesn't use any workspace at all, at least not directly in the VMOD code. This is the panic message part of the VTC log (for some reason, the panic is there twice). The full log is in the attachment: [synth.log](/uploads/0abc70175d1e9a0585547dc305a0b473/synth.log) ``` *** v1 debug|Error: Child (1845907) died signal=6 (core dumped) *** v1 debug|Error: Child (1845907) Panic at: Wed, 16 Oct 2024 14:33:49 GMT *** v1 debug|Assert error in vcl_call_method(), cache/cache_vrt_vcl.c line 649: *** v1 debug| Condition(aws == WS_Snapshot(wrk->aws)) not true. *** v1 debug|version = varnish-7.5.0 revision eef25264e5ca5f96a77129308edb83ccf84cb1b1, vrt api = 19.0 *** v1 debug|ident = Linux,6.1.0-26-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,epoll *** v1 debug|now = 245904.745299 (mono), 1729089229.483392 (real) *** v1 debug|Backtrace: *** v1 debug| 0x55936e95bb7e: varnishd(+0x5bb7e) [0x55936e95bb7e] *** v1 debug| 0x55936e9d94d5: varnishd(VAS_Fail+0x45) [0x55936e9d94d5] *** v1 debug| 0x55936e97e960: varnishd(+0x7e960) [0x55936e97e960] *** v1 debug| 0x55936e981d59: varnishd(VCL_synth_method+0x69) [0x55936e981d59] *** v1 debug| 0x55936e963782: varnishd(+0x63782) [0x55936e963782] *** v1 debug| 0x55936e9640a8: varnishd(CNT_Request+0xd8) [0x55936e9640a8] *** v1 debug| 0x55936e98e6e2: varnishd(+0x8e6e2) [0x55936e98e6e2] *** v1 debug| 0x55936e983422: varnishd(+0x83422) [0x55936e983422] *** v1 debug| 0x55936e9839d4: varnishd(+0x839d4) [0x55936e9839d4] *** v1 debug| 0x7f86996a8144: /lib/x86_64-linux-gnu/libc.so.6(+0x89144) [0x7f86996a8144] *** v1 debug| 0x7f86997287dc: /lib/x86_64-linux-gnu/libc.so.6(+0x1097dc) [0x7f86997287dc] *** v1 debug|argv = { *** v1 debug| [0] = \"varnishd\", *** v1 debug| [1] = \"-d\", *** v1 debug| [2] = \"-n\", *** v1 debug| [3] = \"/tmp/vtc.1845883.013b6cbb/v1\", *** v1 debug| [4] = \"-i\", *** v1 debug| [5] = \"v1\", *** v1 debug| [6] = \"-p\", *** v1 debug| [7] = \"vcl_path=/home/geoff/Develop/varnish/vmods/libvmod-file/vcl:/usr/local/share/varnish/vcl\", *** v1 debug| [8] = \"-p\", *** v1 debug| [9] = \"vmod_path=/home/geoff/Develop/varnish/vmods/libvmod-file/src/.libs:/usr/local/lib/varnish/vmods:/usr/local/lib/varnish/vmods\", *** v1 debug| [10] = \"-p\", *** v1 debug| [11] = \"debug=+vcl_keep\", *** v1 debug| [12] = \"-p\", *** v1 debug| [13] = \"debug=+vmod_so_keep\", *** v1 debug| [14] = \"-p\", *** v1 debug| [15] = \"debug=+vsm_keep\", *** v1 debug| [16] = \"-l\", *** v1 debug| [17] = \"2m\", *** v1 debug| [18] = \"-p\", *** v1 debug| [19] = \"auto_restart=off\", *** v1 debug| [20] = \"-p\", *** v1 debug| [21] = \"syslog_cli_traffic=off\", *** v1 debug| [22] = \"-p\", *** v1 debug| [23] = \"thread_pool_min=10\", *** v1 debug| [24] = \"-p\", *** v1 debug| [25] = \"debug=+vtc_mode\", *** v1 debug| [26] = \"-p\", *** v1 debug| [27] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\", *** v1 debug| [28] = \"-p\", *** v1 debug| [29] = \"h2_initial_window_size=1m\", *** v1 debug| [30] = \"-p\", *** v1 debug| [31] = \"h2_rx_window_low_water=64k\", *** v1 debug| [32] = \"-a\", *** v1 debug| [33] = \"127.0.0.1:0\", *** v1 debug| [34] = \"-M\", *** v1 debug| [35] = \"127.0.0.1 37435\", *** v1 debug| [36] = \"-P\", *** v1 debug| [37] = \"/tmp/vtc.1845883.013b6cbb/v1/varnishd.pid\", *** v1 debug|} *** v1 debug|pthread.self = 0x7f86995b56c0 *** v1 debug|pthread.name = (cache-worker) *** v1 debug|pthread.attr = { *** v1 debug| guard = 4096, *** v1 debug| stack_bottom = 0x7f86995a2000, *** v1 debug| stack_top = 0x7f86995b6000, *** v1 debug| stack_size = 81920, *** v1 debug|} *** v1 debug|thr.req = 0x7f868c066020 { *** v1 debug| vxid = 1001, transport = HTTP/1 { *** v1 debug| state = HTTP1::Proc *** v1 debug| } *** v1 debug| step = Req Step synth *** v1 debug| req_body = none, *** v1 debug| err_code = 200, err_reason = OK, *** v1 debug| restarts = 0, esi_level = 0, *** v1 debug| vary_b = (nil), vary_e = (nil), *** v1 debug| d_ttl = -1.000000, d_grace = -1.000000, *** v1 debug| storage = (nil), *** v1 debug| sess = 0x7f868bc0ef20 { *** v1 debug| fd = 19, vxid = 1000, *** v1 debug| t_open = 1729089229.483291, *** v1 debug| t_idle = 1729089229.483291, *** v1 debug| ws = 0x7f868bc0ef60 { *** v1 debug| id = \"ses\", *** v1 debug| {s, f, r, e} = {0x7f868bc0efb8, +96, (nil), +576}, *** v1 debug| }, *** v1 debug| transport = HTTP/1 { *** v1 debug| state = HTTP1::Proc *** v1 debug| } *** v1 debug| client = 127.0.0.1 56672 127.0.0.1:38015, *** v1 debug| local.endpoint = 127.0.0.1:38015, *** v1 debug| local.socket = a0, *** v1 debug| local.ip = 127.0.0.1:38015, *** v1 debug| remote.ip = 127.0.0.1:56672, *** v1 debug| server.ip = 127.0.0.1:38015, *** v1 debug| client.ip = 127.0.0.1:56672, *** v1 debug| }, *** v1 debug| worker = 0x7f86995b4b90 { *** v1 debug| ws = 0x7f86995b4c18 { *** v1 debug| id = \"wrk\", *** v1 debug| {s, f, r, e} = {0x7f86995b42f0, +0, (nil), +2040}, *** v1 debug| }, *** v1 debug| VCL::method = SYNTH, *** v1 debug| VCL::methods = {RECV, HASH, SYNTH}, *** v1 debug| }, *** v1 debug| ws = 0x7f868c066180 { *** v1 debug| id = \"req\", *** v1 debug| {s, f, r, e} = {0x7f868c06b098, +184, (nil), +77664}, *** v1 debug| }, *** v1 debug| http_conn = 0x7f868c06b010 { *** v1 debug| fd = 19 (@0x7f868bc0ef44), *** v1 debug| doclose = null(Not Closing) *** v1 debug| ws = 0x7f868c066180 { *** v1 debug| [Already dumped, see above] *** v1 debug| }, *** v1 debug| {rxbuf_b, rxbuf_e} = {0x7f868c06b098, 0x7f868c06b0cb}, *** v1 debug| {pipeline_b, pipeline_e} = {(nil), (nil)}, *** v1 debug| content_length = -1, *** v1 debug| body_status = none, *** v1 debug| first_byte_timeout = 0.000000, *** v1 debug| between_bytes_timeout = 0.000000, *** v1 debug| }, *** v1 debug| http[req] = 0x7f868c066220 { *** v1 debug| ws = 0x7f868c066180 { *** v1 debug| [Already dumped, see above] *** v1 debug| }, *** v1 debug| hdrs { *** v1 debug| \"GET\", *** v1 debug| \"/\", *** v1 debug| \"HTTP/1.1\", *** v1 debug| \"Host: 127.0.0.1\", *** v1 debug| \"User-Agent: c1\", *** v1 debug| \"X-Forwarded-For: 127.0.0.1\", *** v1 debug| \"Via: 1.1 v1 (Varnish/7.5)\", *** v1 debug| }, *** v1 debug| }, *** v1 debug| http[resp] = 0x7f868c066b10 { *** v1 debug| ws = 0x7f868c066180 { *** v1 debug| [Already dumped, see above] *** v1 debug| }, *** v1 debug| hdrs { *** v1 debug| \"HTTP/1.1\", *** v1 debug| \"200\", *** v1 debug| \"OK\", *** v1 debug| \"Date: Wed, 16 Oct 2024 14:33:49 GMT\", *** v1 debug| \"Server: Varnish\", *** v1 debug| \"X-Varnish: 1001\", *** v1 debug| }, *** v1 debug| }, *** v1 debug| vdc = 0x7f868c06afd0 { *** v1 debug| .magic = 0x00000000 EXPECTED: VDP_CTX_MAGIC=0xee501df7 *** v1 debug| } *** v1 debug| vcl[vcl] = 0x7f8698c372a0 { *** v1 debug| name = \"vcl1\", *** v1 debug| busy = 1, *** v1 debug| discard = 0, *** v1 debug| state = auto, *** v1 debug| temp = warm, *** v1 debug| conf = 0x7f86994cd4a0 { *** v1 debug| syntax = \"41\", *** v1 debug| srcname = { *** v1 debug| [0] = \"<vcl.inline>\", *** v1 debug| [1] = \"<builtin>\", *** v1 debug| }, *** v1 debug| instances = { *** v1 debug| \"backend_err\" = 0x7f8698d8c650, *** v1 debug| \"synth\" = 0x7f8698d8c5b0, *** v1 debug| }, *** v1 debug| }, *** v1 debug| }, *** v1 debug| vpi = 0x7f86995b42e0 { *** v1 debug| handling (VCL::return) = 0x2 (deliver), *** v1 debug| ref = 5, *** v1 debug| vpi_ref = 0x7f86994ccc80 { *** v1 debug| source = 0 (\"<vcl.inline>\"), *** v1 debug| offset = 325, *** v1 debug| line = 19, *** v1 debug| pos = 17, *** v1 debug| src = \"set resp.reason = \\\"OK\\\";\" *** v1 debug| }, *** v1 debug| }, *** v1 debug| flags = { *** v1 debug| }, *** v1 debug| privs = 0x7f868c066210 { *** v1 debug| }, *** v1 debug| top = 0x7f868c06b078 { *** v1 debug| req = 0x7f868c066020 { *** v1 debug| [Already dumped, see above] *** v1 debug| }, *** v1 debug| privs = 0x7f868c06b090 { *** v1 debug| }, *** v1 debug| vcl[vcl0] = NULL *** v1 debug| }, *** v1 debug|}, *** v1 debug|thr.busyobj = NULL *** v1 debug|thr.worker = 0x7f86995b4b90 { *** v1 debug| [Already dumped, see above] *** v1 debug|}, *** v1 debug|vmods = { *** v1 debug| file = {0x7f8698c35240, Varnish 7.5.0 eef25264e5ca5f96a77129308edb83ccf84cb1b1, 19.0}, *** v1 debug|}, *** v1 debug|pools = { *** v1 debug| pool = 0x7f869680e140 { *** v1 debug| nidle = 8, *** v1 debug| nthr = 10, *** v1 debug| lqueue = 0 *** v1 debug| }, *** v1 debug| pool = 0x7f869680e780 { *** 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 0.750 *** v1 CLI RX 200 **** v1 CLI RX|Panic at: Wed, 16 Oct 2024 14:33:49 GMT **** v1 CLI RX|Assert error in vcl_call_method(), cache/cache_vrt_vcl.c line 649: **** v1 CLI RX| Condition(aws == WS_Snapshot(wrk->aws)) not true. **** v1 CLI RX|version = varnish-7.5.0 revision eef25264e5ca5f96a77129308edb83ccf84cb1b1, vrt api = 19.0 **** v1 CLI RX|ident = Linux,6.1.0-26-amd64,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,epoll **** v1 CLI RX|now = 245904.745299 (mono), 1729089229.483392 (real) **** v1 CLI RX|Backtrace: **** v1 CLI RX| 0x55936e95bb7e: varnishd(+0x5bb7e) [0x55936e95bb7e] **** v1 CLI RX| 0x55936e9d94d5: varnishd(VAS_Fail+0x45) [0x55936e9d94d5] **** v1 CLI RX| 0x55936e97e960: varnishd(+0x7e960) [0x55936e97e960] **** v1 CLI RX| 0x55936e981d59: varnishd(VCL_synth_method+0x69) [0x55936e981d59] **** v1 CLI RX| 0x55936e963782: varnishd(+0x63782) [0x55936e963782] **** v1 CLI RX| 0x55936e9640a8: varnishd(CNT_Request+0xd8) [0x55936e9640a8] **** v1 CLI RX| 0x55936e98e6e2: varnishd(+0x8e6e2) [0x55936e98e6e2] **** v1 CLI RX| 0x55936e983422: varnishd(+0x83422) [0x55936e983422] **** v1 CLI RX| 0x55936e9839d4: varnishd(+0x839d4) [0x55936e9839d4] **** v1 CLI RX| 0x7f86996a8144: /lib/x86_64-linux-gnu/libc.so.6(+0x89144) [0x7f86996a8144] **** v1 CLI RX| 0x7f86997287dc: /lib/x86_64-linux-gnu/libc.so.6(+0x1097dc) [0x7f86997287dc] **** 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.1845883.013b6cbb/v1\", **** v1 CLI RX| [4] = \"-i\", **** v1 CLI RX| [5] = \"v1\", **** v1 CLI RX| [6] = \"-p\", **** v1 CLI RX| [7] = \"vcl_path=/home/geoff/Develop/varnish/vmods/libvmod-file/vcl:/usr/local/share/varnish/vcl\", **** v1 CLI RX| [8] = \"-p\", **** v1 CLI RX| [9] = \"vmod_path=/home/geoff/Develop/varnish/vmods/libvmod-file/src/.libs:/usr/local/lib/varnish/vmods:/usr/local/lib/varnish/vmods\", **** v1 CLI RX| [10] = \"-p\", **** v1 CLI RX| [11] = \"debug=+vcl_keep\", **** v1 CLI RX| [12] = \"-p\", **** v1 CLI RX| [13] = \"debug=+vmod_so_keep\", **** v1 CLI RX| [14] = \"-p\", **** v1 CLI RX| [15] = \"debug=+vsm_keep\", **** v1 CLI RX| [16] = \"-l\", **** v1 CLI RX| [17] = \"2m\", **** v1 CLI RX| [18] = \"-p\", **** v1 CLI RX| [19] = \"auto_restart=off\", **** v1 CLI RX| [20] = \"-p\", **** v1 CLI RX| [21] = \"syslog_cli_traffic=off\", **** v1 CLI RX| [22] = \"-p\", **** v1 CLI RX| [23] = \"thread_pool_min=10\", **** v1 CLI RX| [24] = \"-p\", **** v1 CLI RX| [25] = \"debug=+vtc_mode\", **** v1 CLI RX| [26] = \"-p\", **** v1 CLI RX| [27] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\", **** v1 CLI RX| [28] = \"-p\", **** v1 CLI RX| [29] = \"h2_initial_window_size=1m\", **** v1 CLI RX| [30] = \"-p\", **** v1 CLI RX| [31] = \"h2_rx_window_low_water=64k\", **** v1 CLI RX| [32] = \"-a\", **** v1 CLI RX| [33] = \"127.0.0.1:0\", **** v1 CLI RX| [34] = \"-M\", **** v1 CLI RX| [35] = \"127.0.0.1 37435\", **** v1 CLI RX| [36] = \"-P\", **** v1 CLI RX| [37] = \"/tmp/vtc.1845883.013b6cbb/v1/varnishd.pid\", **** v1 CLI RX|} **** v1 CLI RX|pthread.self = 0x7f86995b56c0 **** v1 CLI RX|pthread.name = (cache-worker) **** v1 CLI RX|pthread.attr = { **** v1 CLI RX| guard = 4096, **** v1 CLI RX| stack_bottom = 0x7f86995a2000, **** v1 CLI RX| stack_top = 0x7f86995b6000, **** v1 CLI RX| stack_size = 81920, **** v1 CLI RX|} **** v1 CLI RX|thr.req = 0x7f868c066020 { **** v1 CLI RX| vxid = 1001, transport = HTTP/1 { **** v1 CLI RX| state = HTTP1::Proc **** v1 CLI RX| } **** v1 CLI RX| step = Req Step synth **** v1 CLI RX| req_body = none, **** v1 CLI RX| err_code = 200, err_reason = OK, **** v1 CLI RX| restarts = 0, esi_level = 0, **** v1 CLI RX| vary_b = (nil), vary_e = (nil), **** v1 CLI RX| d_ttl = -1.000000, d_grace = -1.000000, **** v1 CLI RX| storage = (nil), **** v1 CLI RX| sess = 0x7f868bc0ef20 { **** v1 CLI RX| fd = 19, vxid = 1000, **** v1 CLI RX| t_open = 1729089229.483291, **** v1 CLI RX| t_idle = 1729089229.483291, **** v1 CLI RX| ws = 0x7f868bc0ef60 { **** v1 CLI RX| id = \"ses\", **** v1 CLI RX| {s, f, r, e} = {0x7f868bc0efb8, +96, (nil), +576}, **** v1 CLI RX| }, **** v1 CLI RX| transport = HTTP/1 { **** v1 CLI RX| state = HTTP1::Proc **** v1 CLI RX| } **** v1 CLI RX| client = 127.0.0.1 56672 127.0.0.1:38015, **** v1 CLI RX| local.endpoint = 127.0.0.1:38015, **** v1 CLI RX| local.socket = a0, **** v1 CLI RX| local.ip = 127.0.0.1:38015, **** v1 CLI RX| remote.ip = 127.0.0.1:56672, **** v1 CLI RX| server.ip = 127.0.0.1:38015, **** v1 CLI RX| client.ip = 127.0.0.1:56672, **** v1 CLI RX| }, **** v1 CLI RX| worker = 0x7f86995b4b90 { **** v1 CLI RX| ws = 0x7f86995b4c18 { **** v1 CLI RX| id = \"wrk\", **** v1 CLI RX| {s, f, r, e} = {0x7f86995b42f0, +0, (nil), +2040}, **** v1 CLI RX| }, **** v1 CLI RX| VCL::method = SYNTH, **** v1 CLI RX| VCL::methods = {RECV, HASH, SYNTH}, **** v1 CLI RX| }, **** v1 CLI RX| ws = 0x7f868c066180 { **** v1 CLI RX| id = \"req\", **** v1 CLI RX| {s, f, r, e} = {0x7f868c06b098, +184, (nil), +77664}, **** v1 CLI RX| }, **** v1 CLI RX| http_conn = 0x7f868c06b010 { **** v1 CLI RX| fd = 19 (@0x7f868bc0ef44), **** v1 CLI RX| doclose = null(Not Closing) **** v1 CLI RX| ws = 0x7f868c066180 { **** v1 CLI RX| [Already dumped, see above] **** v1 CLI RX| }, **** v1 CLI RX| {rxbuf_b, rxbuf_e} = {0x7f868c06b098, 0x7f868c06b0cb}, **** v1 CLI RX| {pipeline_b, pipeline_e} = {(nil), (nil)}, **** v1 CLI RX| content_length = -1, **** v1 CLI RX| body_status = none, **** v1 CLI RX| first_byte_timeout = 0.000000, **** v1 CLI RX| between_bytes_timeout = 0.000000, **** v1 CLI RX| }, **** v1 CLI RX| http[req] = 0x7f868c066220 { **** v1 CLI RX| ws = 0x7f868c066180 { **** v1 CLI RX| [Already dumped, see above] **** v1 CLI RX| }, **** v1 CLI RX| hdrs { **** v1 CLI RX| \"GET\", **** v1 CLI RX| \"/\", **** v1 CLI RX| \"HTTP/1.1\", **** v1 CLI RX| \"Host: 127.0.0.1\", **** v1 CLI RX| \"User-Agent: c1\", **** v1 CLI RX| \"X-Forwarded-For: 127.0.0.1\", **** v1 CLI RX| \"Via: 1.1 v1 (Varnish/7.5)\", **** v1 CLI RX| }, **** v1 CLI RX| }, **** v1 CLI RX| http[resp] = 0x7f868c066b10 { **** v1 CLI RX| ws = 0x7f868c066180 { **** v1 CLI RX| [Already dumped, see above] **** v1 CLI RX| }, **** v1 CLI RX| hdrs { **** v1 CLI RX| \"HTTP/1.1\", **** v1 CLI RX| \"200\", **** v1 CLI RX| \"OK\", **** v1 CLI RX| \"Date: Wed, 16 Oct 2024 14:33:49 GMT\", **** v1 CLI RX| \"Server: Varnish\", **** v1 CLI RX| \"X-Varnish: 1001\", **** v1 CLI RX| }, **** v1 CLI RX| }, **** v1 CLI RX| vdc = 0x7f868c06afd0 { **** v1 CLI RX| .magic = 0x00000000 EXPECTED: VDP_CTX_MAGIC=0xee501df7 **** v1 CLI RX| } **** v1 CLI RX| vcl[vcl] = 0x7f8698c372a0 { **** v1 CLI RX| name = \"vcl1\", **** v1 CLI RX| busy = 1, **** v1 CLI RX| discard = 0, **** v1 CLI RX| state = auto, **** v1 CLI RX| temp = warm, **** v1 CLI RX| conf = 0x7f86994cd4a0 { **** v1 CLI RX| syntax = \"41\", **** v1 CLI RX| srcname = { **** v1 CLI RX| [0] = \"<vcl.inline>\", **** v1 CLI RX| [1] = \"<builtin>\", **** v1 CLI RX| }, **** v1 CLI RX| instances = { **** v1 CLI RX| \"backend_err\" = 0x7f8698d8c650, **** v1 CLI RX| \"synth\" = 0x7f8698d8c5b0, **** v1 CLI RX| }, **** v1 CLI RX| }, **** v1 CLI RX| }, **** v1 CLI RX| vpi = 0x7f86995b42e0 { **** v1 CLI RX| handling (VCL::return) = 0x2 (deliver), **** v1 CLI RX| ref = 5, **** v1 CLI RX| vpi_ref = 0x7f86994ccc80 { **** v1 CLI RX| source = 0 (\"<vcl.inline>\"), **** v1 CLI RX| offset = 325, **** v1 CLI RX| line = 19, **** v1 CLI RX| pos = 17, **** v1 CLI RX| src = \"set resp.reason = \\\"OK\\\";\" **** v1 CLI RX| }, **** v1 CLI RX| }, **** v1 CLI RX| flags = { **** v1 CLI RX| }, **** v1 CLI RX| privs = 0x7f868c066210 { **** v1 CLI RX| }, **** v1 CLI RX| top = 0x7f868c06b078 { **** v1 CLI RX| req = 0x7f868c066020 { **** v1 CLI RX| [Already dumped, see above] **** v1 CLI RX| }, **** v1 CLI RX| privs = 0x7f868c06b090 { **** v1 CLI RX| }, **** v1 CLI RX| vcl[vcl0] = NULL **** v1 CLI RX| }, **** v1 CLI RX|}, **** v1 CLI RX|thr.busyobj = NULL **** v1 CLI RX|thr.worker = 0x7f86995b4b90 { **** v1 CLI RX| [Already dumped, see above] **** v1 CLI RX|}, **** v1 CLI RX|vmods = { **** v1 CLI RX| file = {0x7f8698c35240, Varnish 7.5.0 eef25264e5ca5f96a77129308edb83ccf84cb1b1, 19.0}, **** v1 CLI RX|}, **** v1 CLI RX|pools = { **** v1 CLI RX| pool = 0x7f869680e140 { **** v1 CLI RX| nidle = 8, **** v1 CLI RX| nthr = 10, **** v1 CLI RX| lqueue = 0 **** v1 CLI RX| }, **** v1 CLI RX| pool = 0x7f869680e780 { **** 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 # top TEST ./vtc/synth.vtc FAILED (0.750) exit=2 FAIL vtc/synth.vtc (exit status: 2) ```
geoff commented 2024-10-16 16:27:32 +00:00 (Migrated from code.uplex.de)
Copy link

changed title from synth.vtc causes a panic in {-vcl_call_method()-} when CFLAGS includes -O0 to synth.vtc causes a panic in {+vcl_call_method()+} when CFLAGS includes -O0

changed title from **synth.vtc causes a panic in {-`vcl_call_method()`-} when CFLAGS includes -O0** to **synth.vtc causes a panic in {+vcl_call_method()+} when CFLAGS includes -O0**
geoff commented 2024-10-16 16:43:34 +00:00 (Migrated from code.uplex.de)
Copy link

closed via commit e632d8a6e9

closed via commit e632d8a6e9a0f4cfa161e44977d46d1034adce0e
geoff commented 2024-10-16 16:58:18 +00:00 (Migrated from code.uplex.de)
Copy link

The "fix" here was simply to remove the call to VRT_synth_strands(), create a BLOB instead, and call VRT_synth_blob():

diff --git a/src/vmod_file.c b/src/vmod_file.c
index 5dd464f..41dd9ec 100644
--- a/src/vmod_file.c
+++ b/src/vmod_file.c
@@ -604,8 +604,7 @@ vmod_reader_get(VRT_CTX, struct VPFX(file_reader) *rdr)
 VCL_VOID
 vmod_reader_synth(VRT_CTX, struct VPFX(file_reader) *rdr)
 {
-       const char *p[0];
-       struct strands strands = { 1, p };
+       VCL_BLOB blob;
 
        CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
        CHECK_OBJ_NOTNULL(rdr, FILE_READER_MAGIC);
@@ -622,8 +621,9 @@ vmod_reader_synth(VRT_CTX, struct VPFX(file_reader) *rdr)
 
        AN(rdr->flags & RDR_MAPPED);
        AN(rdr->addr);
-       strands.p[0] = rdr->addr;
-       VRT_synth_page(ctx, &strands);
+       blob = VRT_blob(ctx, "VMOD file blob()", rdr->addr, rdr->info->len - 1,
+                       VMOD_FILE_BLOB_MAGIC);
+       VRT_synth_blob(ctx, blob);
 
        AZ(pthread_rwlock_unlock(rdr->lock));
        return;

But that's more of a workaround that doesn't really explain what the problem was.

I don't see what it was about the VMOD that could have made wrk->aws->f change when this method was called, but only if -O0 was set. It makes me wonder if something strange is going on in VRT_synth_strands(); but that would be more of a Varnish VRT issue than a VMOD issue.

The "fix" here was simply to remove the call to `VRT_synth_strands()`, create a BLOB instead, and call `VRT_synth_blob()`: ```diff diff --git a/src/vmod_file.c b/src/vmod_file.c index 5dd464f..41dd9ec 100644 --- a/src/vmod_file.c +++ b/src/vmod_file.c @@ -604,8 +604,7 @@ vmod_reader_get(VRT_CTX, struct VPFX(file_reader) *rdr) VCL_VOID vmod_reader_synth(VRT_CTX, struct VPFX(file_reader) *rdr) { - const char *p[0]; - struct strands strands = { 1, p }; + VCL_BLOB blob; CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC); CHECK_OBJ_NOTNULL(rdr, FILE_READER_MAGIC); @@ -622,8 +621,9 @@ vmod_reader_synth(VRT_CTX, struct VPFX(file_reader) *rdr) AN(rdr->flags & RDR_MAPPED); AN(rdr->addr); - strands.p[0] = rdr->addr; - VRT_synth_page(ctx, &strands); + blob = VRT_blob(ctx, "VMOD file blob()", rdr->addr, rdr->info->len - 1, + VMOD_FILE_BLOB_MAGIC); + VRT_synth_blob(ctx, blob); AZ(pthread_rwlock_unlock(rdr->lock)); return; ``` But that's more of a workaround that doesn't really explain what the problem was. I don't see what it was about the VMOD that could have made `wrk->aws->f` change when this method was called, but only if `-O0` was set. It makes me wonder if something strange is going on in `VRT_synth_strands()`; but that would be more of a Varnish VRT issue than a VMOD issue.
geoff commented 2024-10-16 17:26:03 +00:00 (Migrated from code.uplex.de)
Copy link

ARGH! A C beginner error was lurking in this code for years now.

Spot the error:

	const char *p[0];
	struct strands strands = { 1, p };

// ...

	strands.p[0] = rdr->addr;
	VRT_synth_page(ctx, &strands);
ARGH! A C beginner error was lurking in this code for years now. Spot the error: ```c const char *p[0]; struct strands strands = { 1, p }; // ... strands.p[0] = rdr->addr; VRT_synth_page(ctx, &strands); ```
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
master
6.6
6.3
v1.0.0
v0.2.3
v0.2.2
v0.2.1
v0.2.0
Labels
Clear labels
No items
No labels
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
uplex-varnish/libvmod-file#2
No description provided.