Skip to content

Commit f6a18cd

Browse files
committed
debug(ci): add fflush(stderr) to all debug traces
The previous debug push showed only the first message, likely due to stderr pipe buffering in the Varnish child process. Adding fflush(stderr) after every fprintf to guarantee immediate output and identify the exact hang point on x86_64 CI.
1 parent 762bd54 commit f6a18cd

3 files changed

Lines changed: 15 additions & 0 deletions

File tree

src/proxy_wasm.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -180,6 +180,7 @@ pw_proxy_send_local_response(void *env, wasmtime_caller_t *caller,
180180
results[0].kind = WASMTIME_I32;
181181
fprintf(stderr, "VMOD-WASM-DEBUG: send_local_response called status=%d\n",
182182
args[0].of.i32);
183+
fflush(stderr);
183184

184185
/*
185186
* ABI: proxy_send_local_response(

src/proxy_wasm_headers.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -95,6 +95,7 @@ pw_proxy_get_header_map_value(void *env, wasmtime_caller_t *caller,
9595
results[0].kind = WASMTIME_I32;
9696
fprintf(stderr, "VMOD-WASM-DEBUG: get_header_map_value map=%d\n",
9797
args[0].of.i32);
98+
fflush(stderr);
9899

99100
hp = pw_get_header_map(ctx, args[0].of.i32);
100101
if (hp == NULL) {

src/wasm_engine.c

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -752,6 +752,7 @@ proxy_wasm_execute(struct vwasm_engine *engine,
752752
clock_gettime(CLOCK_MONOTONIC, &ts_start);
753753
fprintf(stderr, "VMOD-WASM-DEBUG: proxy_wasm_execute enter module=%s phase=%d fuel=%llu\n",
754754
module_name, phase, (unsigned long long)fuel_limit);
755+
fflush(stderr);
755756
store = wasmtime_store_new(engine->engine, &proxy_ctx, NULL);
756757
if (store == NULL)
757758
return (-1);
@@ -765,10 +766,12 @@ proxy_wasm_execute(struct vwasm_engine *engine,
765766

766767
/* Instantiate from pre-validated instance */
767768
fprintf(stderr, "VMOD-WASM-DEBUG: instantiating...\n");
769+
fflush(stderr);
768770
error = wasmtime_instance_pre_instantiate(entry->instance_pre,
769771
context, &instance, &trap);
770772
fprintf(stderr, "VMOD-WASM-DEBUG: instantiate done err=%p trap=%p\n",
771773
(void *)error, (void *)trap);
774+
fflush(stderr);
772775
if (error != NULL) {
773776
log_error(ctx, error, module_name, "instantiate");
774777
goto cleanup;
@@ -800,8 +803,10 @@ proxy_wasm_execute(struct vwasm_engine *engine,
800803

801804
/* Call _initialize if exported */
802805
fprintf(stderr, "VMOD-WASM-DEBUG: calling _initialize\n");
806+
fflush(stderr);
803807
call_wasm_void(context, &instance, "_initialize", NULL, 0);
804808
fprintf(stderr, "VMOD-WASM-DEBUG: _initialize done\n");
809+
fflush(stderr);
805810

806811
/* 1. Create root context */
807812
args[0].kind = WASMTIME_I32;
@@ -811,26 +816,31 @@ proxy_wasm_execute(struct vwasm_engine *engine,
811816
call_wasm_void(context, &instance,
812817
"proxy_on_context_create", args, 2);
813818
fprintf(stderr, "VMOD-WASM-DEBUG: root context created\n");
819+
fflush(stderr);
814820

815821
/* 2. VM start */
816822
args[0].kind = WASMTIME_I32;
817823
args[0].of.i32 = (int32_t)proxy_ctx.root_context_id;
818824
args[1].kind = WASMTIME_I32;
819825
args[1].of.i32 = (int32_t)vm_config_len;
820826
fprintf(stderr, "VMOD-WASM-DEBUG: calling proxy_on_vm_start vm_config_len=%zu\n", vm_config_len);
827+
fflush(stderr);
821828
call_wasm_func(context, &instance,
822829
"proxy_on_vm_start", args, 2, NULL);
823830
fprintf(stderr, "VMOD-WASM-DEBUG: vm_start done\n");
831+
fflush(stderr);
824832

825833
/* 3. Configure */
826834
args[0].kind = WASMTIME_I32;
827835
args[0].of.i32 = (int32_t)proxy_ctx.root_context_id;
828836
args[1].kind = WASMTIME_I32;
829837
args[1].of.i32 = (int32_t)plugin_config_len;
830838
fprintf(stderr, "VMOD-WASM-DEBUG: calling proxy_on_configure plugin_config_len=%zu\n", plugin_config_len);
839+
fflush(stderr);
831840
call_wasm_func(context, &instance,
832841
"proxy_on_configure", args, 2, NULL);
833842
fprintf(stderr, "VMOD-WASM-DEBUG: configure done\n");
843+
fflush(stderr);
834844

835845
/* 4. Create stream context */
836846
args[0].kind = WASMTIME_I32;
@@ -840,6 +850,7 @@ proxy_wasm_execute(struct vwasm_engine *engine,
840850
call_wasm_void(context, &instance,
841851
"proxy_on_context_create", args, 2);
842852
fprintf(stderr, "VMOD-WASM-DEBUG: stream context created\n");
853+
fflush(stderr);
843854

844855
/* 5. Call phase-specific headers callback */
845856
if (phase == VWASM_PHASE_REQUEST) {
@@ -860,6 +871,7 @@ proxy_wasm_execute(struct vwasm_engine *engine,
860871
action = 0;
861872
fprintf(stderr, "VMOD-WASM-DEBUG: calling %s num_headers=%d\n",
862873
phase_headers_fn, num_headers);
874+
fflush(stderr);
863875
if (call_wasm_func(context, &instance,
864876
phase_headers_fn, args, 3, &action) != 0) {
865877
fprintf(stderr, "VMOD-WASM-DEBUG: %s FAILED\n", phase_headers_fn);
@@ -868,6 +880,7 @@ proxy_wasm_execute(struct vwasm_engine *engine,
868880
}
869881
fprintf(stderr, "VMOD-WASM-DEBUG: %s returned action=%d local_response=%d\n",
870882
phase_headers_fn, action, proxy_ctx.local_response_set);
883+
fflush(stderr);
871884

872885
/* Check if module called send_local_response */
873886
if (proxy_ctx.local_response_set) {

0 commit comments

Comments
 (0)