experiment: detect re-entrancy in ddtrace_serialize_closed_spans

[morrisonlevi]

Description

We have crashes that deal with serializing meta information. After many hours spent including with different AI models, I think something "odd" or weird must be going on. Thus far I haven't been able to detect any basic cases of bad refcounting or anything like that. Sometimes it happens on request shutdown, other times during the request.

For instance, we have some crashes caused by using DDTrace\\close_span() from the Laravel integration. I don't know if Laravel or its Integration are specifically triggering this or if it's just popular, but many of these crashes are coming from the Laravel integration (but again, not all).

• Since closing the spans can run user-provided code, if some closure triggers a flush, it might be possible to re-enter serialization code.
• There's also the fact that it can allocate, which can cause GC to run, which can close objects, and possibly again trigger serialization.

We don't see re-entrancy in the crash frames, but the idea is that it would re-enter and succeed, but when the original resumes, the data has been freed or something and then crashes.

Honestly, this is a bit of guessing, but I wanted to experiment to see if this can trigger.

Crash Exhibit 1

``` #0 0x00007f57e1a86ce1 raise #1 0x00007f57e1a70537 abort #2 0x00007f57db35e5fa panic_abort::__rust_start_panic::abort::hcc2c508cedf538e0 (src/lib.rs:48:17) #3 0x00007f57db35e5e9 __rust_start_panic (src/lib.rs:43:5) #4 0x00007f57db4f19c9 rust_panic (std/src/panicking.rs:862:25) #5 0x00007f57db4f71aa std::panicking::rust_panic_with_hook::h370ee1901241e459 (std/src/panicking.rs:826:5) #6 0x00007f57db4f6f65 std::panicking::begin_panic_handler::{{closure}}::heabfe92676d6d073 (std/src/panicking.rs:667:13) #7 0x00007f57db4f6ef9 std::sys::backtrace::__rust_end_short_backtrace::h6e22d229d4fdf49e (src/sys/backtrace.rs:170:18) #8 0x00007f57db4f6eec rust_begin_unwind (std/src/panicking.rs:665:5) #9 0x00007f57dadc1faf core::panicking::panic_fmt::hfae270fab21da3e6 (src/panicking.rs:76:14) #10 0x00007f57daebf6d6 alloc::raw_vec::capacity_overflow::h25658ea0665c4276 (alloc/src/raw_vec.rs:25:5) #11 0x00007f57daebfe00 alloc::raw_vec::handle_error::hbb06bb12d3c67d2d (alloc/src/raw_vec.rs:792:29) #12 0x00007f57daebfe00 alloc::raw_vec::RawVecInner::with_capacity_in::hc70a87b055a34e2c (alloc/src/raw_vec.rs:431:25) #13 0x00007f57daebfe00 alloc::raw_vec::RawVec::with_capacity_in::h00dee90c0f60d1a1 (alloc/src/raw_vec.rs:194:20) #14 0x00007f57daebfe00 alloc::vec::Vec::with_capacity_in::h9515dc2b6011d238 (alloc/src/vec/mod.rs:803:20) #15 0x00007f57daebfe00 alloc::vec::Vec::with_capacity::h5b3bb1e47d6848f6 (alloc/src/vec/mod.rs:483:9) #16 0x00007f57daebfe00 alloc::string::String::with_capacity::hfd3cf8f3f85356f9 (alloc/src/string.rs:490:23) #17 0x00007f57daebfe00 alloc::string::String::from_utf8_lossy::hbe7debe62a378898 (alloc/src/string.rs:651:23) #18 0x00007f57dae90c4e ddtrace_php::bytes::convert_zend_to_bytes_string::h8ea54bdc94d707fb (components-rs/bytes.rs:122:15) #19 0x00007f57dae90c4e ddog_add_span_meta_zstr (components-rs/bytes.rs:180:9) #20 0x00007f57dae4c4e8 dd_serialize_array_recursively (ext/serializer.c:972) #21 0x00007f57dae4fb64 dd_serialize_array_meta_recursively (ext/serializer.c:978) #22 0x00007f57dae4fb64 _serialize_meta (ext/serializer.c:1250) #23 0x00007f57dae4fb64 ddtrace_serialize_span_to_rust_span (ext/serializer.c:1847) #24 0x00007f57dae58265 ddtrace_serialize_closed_spans (ext/span.c:1111) #25 0x00007f57dae58352 ddtrace_serialize_closed_spans_with_cycle (ext/span.c:1141) #26 0x00007f57dae27622 ddtrace_flush_tracer (ext/auto_flush.c:27) #27 0x00007f57dae26811 dd_force_shutdown_tracing (ext/ddtrace.c:1819) #28 0x00007f57dae26a37 zm_deactivate_ddtrace (ext/ddtrace.c:1866) #29 0x00007f57dfb56fd4 zend_deactivate_modules #30 0x00007f57dfaf0155 php_request_shutdown #31 0x00007f57dfbd9fb7 php_handler #32 0x000055b625826980 ap_run_handler #33 0x000055b625826f76 ap_invoke_handler #34 0x000055b62583ed2e ap_internal_redirect #35 0x000055b62583f814 ap_process_async_request #36 0x000055b62583fbce ap_process_request #37 0x000055b6258306e0 ap_run_process_connection #38 0x000055b625806830 ap_run_mpm #39 0x000055b6257fe148 main #40 0x00007f57e1a71d0a __libc_start_main #41 0x000055b6257fe25a _start ```

Crash Exhibit 2

``` #0 0x000055e4c23521bf _zend_mm_alloc #1 0x00007f301caa8777 alloc_prof_orig_alloc (allocation/allocation_le83.rs:381:28) #2 0x00007f301caa85e2 alloc_prof_malloc (allocation/allocation_le83.rs:352:15) #3 0x000055e4c2378d27 zend_long_to_str #4 0x00007f301d57b4ec ddtrace_convert_to_string (ext/compat_string.c:92) #5 0x00007f301d59f650 dd_serialize_array_recursively (ext/serializer.c:971) #6 0x00007f301d5a41e0 dd_serialize_array_meta_recursively (ext/serializer.c:978) #7 0x00007f301d5a41e0 _serialize_meta (ext/serializer.c:1250) #8 0x00007f301d5a41e0 ddtrace_serialize_span_to_rust_span (ext/serializer.c:1847) #9 0x00007f301d5ad589 ddtrace_serialize_closed_spans (ext/span.c:1111) #10 0x00007f301d577e15 ddtrace_flush_tracer (ext/auto_flush.c:29) #11 0x00007f301d5ab900 dd_close_entry_span_of_stack (ext/span.c:840) #12 0x00007f301d5accd5 ddtrace_close_span (ext/span.c:912) #13 0x00007f301d56bdd9 zif_DDTrace_close_span (ext/ddtrace.c:3127) #14 0x00007f301caa78e5 execute_internal (src/wall_time.rs:79:18) #15 0x000055e4c23726ec zend_call_function #16 0x00007f301d5584c6 zend_call_function_wrapper (sandbox/call.c:29) #17 0x00007f301d55857f zai_sandbox_try_call (sandbox/call.c:104) #18 0x00007f301d558836 zai_sandbox_call (sandbox/call.c:118) #19 0x00007f301d5b4dd5 dd_uhook_call_hook (ext/hook/uhook.c:246) #20 0x00007f301d5b5435 dd_uhook_end (ext/hook/uhook.c:482) #21 0x00007f301d556211 zai_hook_finish (hook/hook.c:1122) #22 0x00007f301d54701b zai_hook_safe_finish (php8/interceptor.c:56) #23 0x00007f301d547183 zai_interceptor_observer_end_handler (php8/interceptor.c:176) #24 0x000055e4c2424c9e zend_observer_fcall_end #25 0x000055e4c23ee391 execute_ex #26 0x000055e4c23f7d64 zend_execute #27 0x000055e4c2382106 zend_execute_scripts #28 0x000055e4c2311a84 php_execute_script #29 0x00007f30216a3305 __libc_start_main #30 0x000055e4c204aae1 _start ```

Reviewer checklist

• Test coverage seems ok.
• Appropriate labels assigned.

[datadog-official]

⚠️ Tests

✨ Fix all issues with Cursor

⚠️ Warnings

❄️ 1 New flaky test detected

ext/soap/tests/bugs/bug61525.phpt (Bug #61525 (SOAP functions require at least one space after HTTP header colon)) from php.ext.soap.tests.bugs (Datadog) (Fix with Cursor)

002+ 
004+ 
006+ 
008+ 
010+ 
012+ 
014+ 
016+ 
     int(7)

🧪 2141 Tests failed

testSearchPhpBinaries from integration.DDTrace\Tests\Integration\PHPInstallerTest (Datadog) (Fix with Cursor)

DDTrace\Tests\Integration\PHPInstallerTest::testSearchPhpBinaries
Test code or tested code printed unexpected output: Searching for available php binaries, this operation might take a while.

    testSimplePushAndProcess from laravel-58-test.DDTrace\Tests\Integrations\Laravel\V5_8\QueueTest (Fix with Cursor)

testSimplePushAndProcess from laravel-8x-test.DDTrace\Tests\Integrations\Laravel\V8_x\QueueTest (Datadog) (Fix with Cursor)

DDTrace\Tests\Integrations\Laravel\V8_x\QueueTest::testSimplePushAndProcess
Test code or tested code printed unexpected output: spanLinksTraceId: 6963e948000000001467dd45cd2e5453
tid: 6963e94800000000
hexProcessTraceId: 1467dd45cd2e5453
hexProcessSpanId: f2955ec4ac7b6df5
processTraceId: 1470387095224603731
processSpanId: 17479981727508819445

View all

_{This comment will be updated automatically if new data arrives.
🔗 Commit SHA: 908573d | Docs | Datadog PR Page | Was this helpful? Give us feedback!}