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<A>::with_capacity_in::hc70a87b055a34e2c (alloc/src/raw_vec.rs:431:25)
#13  0x00007f57daebfe00 alloc::raw_vec::RawVec<T,A>::with_capacity_in::h00dee90c0f60d1a1 (alloc/src/raw_vec.rs:194:20)
#14  0x00007f57daebfe00 alloc::vec::Vec<T,A>::with_capacity_in::h9515dc2b6011d238 (alloc/src/vec/mod.rs:803:20)
#15  0x00007f57daebfe00 alloc::vec::Vec<T>::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

🧪 2141 Tests failed

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

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

DDTrace\Tests\Integrations\Laravel\V5_8\QueueTest::testSimplePushAndProcess
Test code or tested code printed unexpected output: spanLinksTraceId: 69653d4e0000000096f14bc7af102451
tid: 69653d4e00000000
hexProcessTraceId: 96f14bc7af102451
hexProcessSpanId: c162d1561ad74ee4
processTraceId: 10876557896084104273
processSpanId: 13934930364785446628

phpvfscomposer://tests/vendor/phpunit/phpunit/phpunit:106

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: 69654ab1000000006e387c4377c62122
tid: 69654ab100000000
hexProcessTraceId: 6e387c4377c62122
hexProcessSpanId: 962c7db785df411b
processTraceId: 7942234572081996066
processSpanId: 10821162231842947355

View all

ℹ️ Info

❄️ No new flaky tests detected

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

[codecov-commenter]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 61.81%. Comparing base (18c40bc) to head (cbafd8a).
⚠️ Report is 14 commits behind head on master.

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #3562      +/-   ##
==========================================
- Coverage   61.82%   61.81%   -0.02%     
==========================================
  Files         140      140              
  Lines       13281    13281              
  Branches     1758     1758              
==========================================
- Hits         8211     8209       -2     
- Misses       4279     4282       +3     
+ Partials      791      790       -1     

see 1 file with indirect coverage changes

---

Continue to review full report in Codecov by Sentry.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 18c40bc...cbafd8a. Read the comment docs.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
• 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.