From 8b7df34b8a7a657ed4e674f44897bc09f1c14361 Mon Sep 17 00:00:00 2001 From: Bob Weinand Date: Mon, 20 Nov 2023 00:12:03 +0100 Subject: [PATCH] Add tracing for curl_multi_exec() (#2347) * Add tracing for curl_multi_exec() Fixes #1156. Signed-off-by: Bob Weinand * Also track curl_multi_info_read for curl_multi_exec errors Signed-off-by: Bob Weinand * Fix CI * Fix memory leak Signed-off-by: Bob Weinand * Try fixing test flakiness Signed-off-by: Bob Weinand * Reflection doesn't like calling functions with references on PHP 7.0 --------- Signed-off-by: Bob Weinand --- ext/compatibility.h | 10 + ext/ddtrace.c | 98 +++++++- ext/ddtrace.h | 1 + ext/ddtrace.stub.php | 22 +- ext/ddtrace_arginfo.h | 16 +- ext/handlers_curl.c | 28 ++- ext/handlers_curl_php7.c | 29 ++- ext/hook/uhook.c | 9 +- ext/integrations/integrations.c | 2 + .../Integrations/Curl/CurlIntegration.php | 226 ++++++++++++++---- .../Integrations/Curl/CurlIntegrationTest.php | 59 +++++ .../Guzzle/V5/GuzzleIntegrationTest.php | 4 +- .../Guzzle/V6/GuzzleIntegrationTest.php | 17 +- tests/internal-api-stress-test.php | 3 +- .../exceptions/exceptions.c | 18 +- .../exceptions/exceptions.h | 2 + 16 files changed, 470 insertions(+), 74 deletions(-) diff --git a/ext/compatibility.h b/ext/compatibility.h index 2b8669f7ac..af93acb357 100644 --- a/ext/compatibility.h +++ b/ext/compatibility.h @@ -116,6 +116,8 @@ static inline zend_string *php_base64_encode_str(const zend_string *str) { #define GC_ADD_FLAGS(c, flag) GC_FLAGS(c) |= flag #define GC_DEL_FLAGS(c, flag) GC_FLAGS(c) &= ~(flag) +#define rc_dtor_func zval_dtor_func + static inline HashTable *zend_new_array(uint32_t nSize) { HashTable *ht = (HashTable *)emalloc(sizeof(HashTable)); zend_hash_init(ht, nSize, dummy, ZVAL_PTR_DTOR, 0); @@ -292,6 +294,14 @@ static zend_always_inline void zend_array_release(zend_array *array) #define ZEND_ATOL(s) atol((s)) #endif #define ZEND_ACC_READONLY 0 + +static zend_always_inline zend_result add_next_index_object(zval *arg, zend_object *obj) { + zval tmp; + + ZVAL_OBJ(&tmp, obj); + return zend_hash_next_index_insert(Z_ARRVAL_P(arg), &tmp) ? SUCCESS : FAILURE; +} + #endif #if PHP_VERSION_ID < 80200 diff --git a/ext/ddtrace.c b/ext/ddtrace.c index a855615ba7..4f98367974 100644 --- a/ext/ddtrace.c +++ b/ext/ddtrace.c @@ -1017,6 +1017,13 @@ static void dd_clean_globals(void) { zend_hash_destroy(&DDTRACE_G(tracestate_unknown_dd_keys)); zend_hash_destroy(&DDTRACE_G(propagated_root_span_tags)); + if (DDTRACE_G(curl_multi_injecting_spans)) { + if (GC_DELREF(DDTRACE_G(curl_multi_injecting_spans)) == 0) { + rc_dtor_func((zend_refcounted *) DDTRACE_G(curl_multi_injecting_spans)); + } + DDTRACE_G(curl_multi_injecting_spans) = NULL; + } + if (DDTRACE_G(dd_origin)) { zend_string_release(DDTRACE_G(dd_origin)); DDTRACE_G(dd_origin) = NULL; @@ -1792,15 +1799,15 @@ PHP_FUNCTION(dd_trace_internal_fn) { /* {{{ proto int DDTrace\close_spans_until(DDTrace\SpanData) */ PHP_FUNCTION(DDTrace_close_spans_until) { - zval *untilzv = NULL; + zval *spanzv = NULL; - if (zend_parse_parameters_ex(ddtrace_quiet_zpp(), ZEND_NUM_ARGS(), "O!", &untilzv, ddtrace_ce_span_data) == + if (zend_parse_parameters_ex(ddtrace_quiet_zpp(), ZEND_NUM_ARGS(), "O!", &spanzv, ddtrace_ce_span_data) == FAILURE) { LOG_LINE_ONCE(Error, "DDTrace\\close_spans_until() expects null or a SpanData object"); RETURN_FALSE; } - int closed_spans = ddtrace_close_userland_spans_until(untilzv ? OBJ_SPANDATA(Z_OBJ_P(untilzv)) : NULL); + int closed_spans = ddtrace_close_userland_spans_until(spanzv ? OBJ_SPANDATA(Z_OBJ_P(spanzv)) : NULL); if (closed_spans == -1) { RETURN_FALSE; @@ -1961,6 +1968,17 @@ PHP_FUNCTION(DDTrace_start_trace_span) { dd_start_span(INTERNAL_FUNCTION_PARAM_PASSTHRU); } +static void dd_set_span_finish_time(ddtrace_span_data *span, double finish_time_seconds) { + // we do not expose the monotonic time here, so do not use it as reference time to calculate difference + uint64_t start_time = span->start; + uint64_t finish_time = (uint64_t)(finish_time_seconds * 1000000000); + if (finish_time < start_time) { + dd_trace_stop_span_time(span); + } else { + span->duration = finish_time - start_time; + } +} + /* {{{ proto string DDTrace\close_span() */ PHP_FUNCTION(DDTrace_close_span) { double finish_time_seconds = 0; @@ -1976,19 +1994,36 @@ PHP_FUNCTION(DDTrace_close_span) { RETURN_NULL(); } - // we do not expose the monotonic time here, so do not use it as reference time to calculate difference - uint64_t start_time = top_span->start; - uint64_t finish_time = (uint64_t)(finish_time_seconds * 1000000000); - if (finish_time < start_time) { - dd_trace_stop_span_time(top_span); - } else { - top_span->duration = finish_time - start_time; - } + dd_set_span_finish_time(top_span, finish_time_seconds); ddtrace_close_span(top_span); RETURN_NULL(); } +/* {{{ proto string DDTrace\update_span_duration() */ +PHP_FUNCTION(DDTrace_update_span_duration) { + double finish_time_seconds = 0; + zval *spanzv = NULL; + if (zend_parse_parameters(ZEND_NUM_ARGS(), "O|d", &spanzv, ddtrace_ce_span_data, &finish_time_seconds) != SUCCESS) { + RETURN_FALSE; + } + + ddtrace_span_data *span = OBJ_SPANDATA(Z_OBJ_P(spanzv)); + + if (span->duration == 0) { + LOG(Error, "Cannot update the span duration of an unfinished span."); + RETURN_NULL(); + } + + if (span->duration == DDTRACE_DROPPED_SPAN || span->duration == DDTRACE_SILENTLY_DROPPED_SPAN) { + RETURN_NULL(); + } + + dd_set_span_finish_time(span, finish_time_seconds); + + RETURN_NULL(); +} + /* {{{ proto string DDTrace\active_stack() */ PHP_FUNCTION(DDTrace_active_stack) { if (zend_parse_parameters_ex(ddtrace_quiet_zpp(), ZEND_NUM_ARGS(), "")) { @@ -2428,15 +2463,18 @@ PHP_FUNCTION(DDTrace_get_priority_sampling) { PHP_FUNCTION(DDTrace_get_sanitized_exception_trace) { zend_object *ex; + zend_long skip = 0; - ZEND_PARSE_PARAMETERS_START_EX(ddtrace_quiet_zpp(), 1, 1) + ZEND_PARSE_PARAMETERS_START_EX(ddtrace_quiet_zpp(), 1, 2) Z_PARAM_OBJ_OF_CLASS(ex, zend_ce_throwable) + Z_PARAM_OPTIONAL + Z_PARAM_LONG(skip) ZEND_PARSE_PARAMETERS_END_EX({ LOG_LINE_ONCE(Error, "unexpected parameter for DDTrace\\get_sanitized_exception_trace, the first argument must be a Throwable"); RETURN_FALSE; }); - RETURN_STR(zai_get_trace_without_args_from_exception(ex)); + RETURN_STR(zai_get_trace_without_args_from_exception_skip_frames(ex, skip)); } PHP_FUNCTION(DDTrace_startup_logs) { @@ -2473,6 +2511,40 @@ PHP_FUNCTION(DDTrace_extract_ip_from_headers) { RETURN_ARR(Z_ARR(meta)); } +PHP_FUNCTION(DDTrace_curl_multi_exec_get_request_spans) { + zval *array; + + ZEND_PARSE_PARAMETERS_START(1, 1) + Z_PARAM_ZVAL(array) + ZEND_PARSE_PARAMETERS_END(); + + if (Z_TYPE_P(array) == IS_REFERENCE) { + zend_reference *ref = Z_REF_P(array); + +#if PHP_VERSION_ID < 70400 + array = &ref->val; + zval_ptr_dtor(array); + array_init(array); +#else + array = zend_try_array_init(array); + if (!array) { + RETURN_THROWS(); + } +#endif + + if (get_DD_TRACE_ENABLED()) { + if (DDTRACE_G(curl_multi_injecting_spans) && GC_DELREF(DDTRACE_G(curl_multi_injecting_spans)) == 0) { + rc_dtor_func((zend_refcounted *) DDTRACE_G(curl_multi_injecting_spans)); + } + + GC_ADDREF(ref); + DDTRACE_G(curl_multi_injecting_spans) = ref; + } + } + + RETURN_NULL(); +} + static const zend_module_dep ddtrace_module_deps[] = {ZEND_MOD_REQUIRED("json") ZEND_MOD_REQUIRED("standard") ZEND_MOD_END}; diff --git a/ext/ddtrace.h b/ext/ddtrace.h index a41366eed1..48150a23d1 100644 --- a/ext/ddtrace.h +++ b/ext/ddtrace.h @@ -92,6 +92,7 @@ ZEND_BEGIN_MODULE_GLOBALS(ddtrace) ddtrace_trace_id distributed_trace_id; uint64_t distributed_parent_trace_id; zend_string *dd_origin; + zend_reference *curl_multi_injecting_spans; char *cgroup_file; ddog_QueueId telemetry_queue_id; diff --git a/ext/ddtrace.stub.php b/ext/ddtrace.stub.php index 9b88a09fda..01b33fd366 100644 --- a/ext/ddtrace.stub.php +++ b/ext/ddtrace.stub.php @@ -403,11 +403,19 @@ function start_span(float $startTime = 0): SpanData|false {} /** * Close the currently active user-span on the top of the stack * - * @param float $finishTime Finish time in seconds. + * @param float $finishTime Finish time in seconds. Defaults to now if zero. * @return false|null 'false' if unexpected parameters were given, else 'null' */ function close_span(float $finishTime = 0): false|null {} + /** + * Update the duration of an already closed span + * + * @param SpanData $span The span to update. + * @param float $finishTime Finish time in seconds. Defaults to now if zero. + */ + function update_span_duration(SpanData $span, float $finishTime = 0): null {} + /** * Start a new trace * @@ -467,9 +475,11 @@ function get_priority_sampling(bool $global = false): int|null {} * Sanitize an exception * * @param \Exception|\Throwable $exception + * @param int $skipFrames The number of frames to be dropped from the start. E.g. to hide the fact that we're + * in a hook function. * @return string */ - function get_sanitized_exception_trace(\Exception|\Throwable $exception): string {} + function get_sanitized_exception_trace(\Exception|\Throwable $exception, int $skipFrames = 0): string {} /** * Update datadog headers for distributed tracing for new spans. Also applies this information to the current trace, @@ -569,6 +579,14 @@ function set_distributed_tracing_context( * Closes all spans and force-send finished traces to the agent */ function flush(): void {} + + /** + * Registers an array to be populated with spans for each request during the next curl_multi_exec() call. + * + * @internal + * @param list{\CurlHandle, SpanData}[] $array An array which will be populated with curl handles and spans. + */ + function curl_multi_exec_get_request_spans(&$array): void {} } namespace DDTrace\System { diff --git a/ext/ddtrace_arginfo.h b/ext/ddtrace_arginfo.h index 6563d45b5d..0d0ed49079 100644 --- a/ext/ddtrace_arginfo.h +++ b/ext/ddtrace_arginfo.h @@ -1,5 +1,5 @@ /* This is a generated file, edit the .stub.php file instead. - * Stub hash: 85f2b3a4b45cb7685e5ec115eefa59ae7f20cd79 */ + * Stub hash: 1d07ca443c39ea7a0a831b062bb0efe4baf69b0f */ ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_DDTrace_trace_method, 0, 3, _IS_BOOL, 0) ZEND_ARG_TYPE_INFO(0, className, IS_STRING, 0) @@ -56,6 +56,11 @@ ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_DDTrace_close_span, 0, 0, IS_FAL ZEND_ARG_TYPE_INFO_WITH_DEFAULT_VALUE(0, finishTime, IS_DOUBLE, 0, "0") ZEND_END_ARG_INFO() +ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_DDTrace_update_span_duration, 0, 1, IS_NULL, 1) + ZEND_ARG_OBJ_INFO(0, span, DDTrace\\SpanData, 0) + ZEND_ARG_TYPE_INFO_WITH_DEFAULT_VALUE(0, finishTime, IS_DOUBLE, 0, "0") +ZEND_END_ARG_INFO() + ZEND_BEGIN_ARG_WITH_RETURN_OBJ_INFO_EX(arginfo_DDTrace_start_trace_span, 0, 0, DDTrace\\SpanData, 0) ZEND_ARG_TYPE_INFO_WITH_DEFAULT_VALUE(0, startTime, IS_DOUBLE, 0, "0") ZEND_END_ARG_INFO() @@ -81,6 +86,7 @@ ZEND_END_ARG_INFO() ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_DDTrace_get_sanitized_exception_trace, 0, 1, IS_STRING, 0) ZEND_ARG_OBJ_TYPE_MASK(0, exception, Exception|Throwable, 0, NULL) + ZEND_ARG_TYPE_INFO_WITH_DEFAULT_VALUE(0, skipFrames, IS_LONG, 0, "0") ZEND_END_ARG_INFO() ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_DDTrace_consume_distributed_tracing_headers, 0, 1, IS_VOID, 0) @@ -118,6 +124,10 @@ ZEND_END_ARG_INFO() ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_DDTrace_flush, 0, 0, IS_VOID, 0) ZEND_END_ARG_INFO() +ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_DDTrace_curl_multi_exec_get_request_spans, 0, 1, IS_VOID, 0) + ZEND_ARG_INFO(1, array) +ZEND_END_ARG_INFO() + ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_DDTrace_System_container_id, 0, 0, IS_STRING, 1) ZEND_END_ARG_INFO() @@ -269,6 +279,7 @@ ZEND_FUNCTION(DDTrace_active_span); ZEND_FUNCTION(DDTrace_root_span); ZEND_FUNCTION(DDTrace_start_span); ZEND_FUNCTION(DDTrace_close_span); +ZEND_FUNCTION(DDTrace_update_span_duration); ZEND_FUNCTION(DDTrace_start_trace_span); ZEND_FUNCTION(DDTrace_active_stack); ZEND_FUNCTION(DDTrace_create_stack); @@ -286,6 +297,7 @@ ZEND_FUNCTION(DDTrace_logs_correlation_trace_id); ZEND_FUNCTION(DDTrace_current_context); ZEND_FUNCTION(DDTrace_set_distributed_tracing_context); ZEND_FUNCTION(DDTrace_flush); +ZEND_FUNCTION(DDTrace_curl_multi_exec_get_request_spans); ZEND_FUNCTION(DDTrace_System_container_id); ZEND_FUNCTION(DDTrace_Config_integration_analytics_enabled); ZEND_FUNCTION(DDTrace_Config_integration_analytics_sample_rate); @@ -346,6 +358,7 @@ static const zend_function_entry ext_functions[] = { ZEND_NS_FALIAS("DDTrace", root_span, DDTrace_root_span, arginfo_DDTrace_root_span) ZEND_NS_FALIAS("DDTrace", start_span, DDTrace_start_span, arginfo_DDTrace_start_span) ZEND_NS_FALIAS("DDTrace", close_span, DDTrace_close_span, arginfo_DDTrace_close_span) + ZEND_NS_FALIAS("DDTrace", update_span_duration, DDTrace_update_span_duration, arginfo_DDTrace_update_span_duration) ZEND_NS_FALIAS("DDTrace", start_trace_span, DDTrace_start_trace_span, arginfo_DDTrace_start_trace_span) ZEND_NS_FALIAS("DDTrace", active_stack, DDTrace_active_stack, arginfo_DDTrace_active_stack) ZEND_NS_FALIAS("DDTrace", create_stack, DDTrace_create_stack, arginfo_DDTrace_create_stack) @@ -363,6 +376,7 @@ static const zend_function_entry ext_functions[] = { ZEND_NS_FALIAS("DDTrace", current_context, DDTrace_current_context, arginfo_DDTrace_current_context) ZEND_NS_FALIAS("DDTrace", set_distributed_tracing_context, DDTrace_set_distributed_tracing_context, arginfo_DDTrace_set_distributed_tracing_context) ZEND_NS_FALIAS("DDTrace", flush, DDTrace_flush, arginfo_DDTrace_flush) + ZEND_NS_FALIAS("DDTrace", curl_multi_exec_get_request_spans, DDTrace_curl_multi_exec_get_request_spans, arginfo_DDTrace_curl_multi_exec_get_request_spans) ZEND_NS_FALIAS("DDTrace\\System", container_id, DDTrace_System_container_id, arginfo_DDTrace_System_container_id) ZEND_NS_FALIAS("DDTrace\\Config", integration_analytics_enabled, DDTrace_Config_integration_analytics_enabled, arginfo_DDTrace_Config_integration_analytics_enabled) ZEND_NS_FALIAS("DDTrace\\Config", integration_analytics_sample_rate, DDTrace_Config_integration_analytics_sample_rate, arginfo_DDTrace_Config_integration_analytics_sample_rate) diff --git a/ext/handlers_curl.c b/ext/handlers_curl.c index 9426117aab..d0b640ac9e 100644 --- a/ext/handlers_curl.c +++ b/ext/handlers_curl.c @@ -125,8 +125,32 @@ static void dd_multi_inject_headers(zend_object *mh) { if (handles && zend_hash_num_elements(handles) > 0) { zend_object *ch; - ZEND_HASH_FOREACH_PTR(handles, ch) { dd_inject_distributed_tracing_headers(ch); } - ZEND_HASH_FOREACH_END(); + ZEND_HASH_FOREACH_PTR(handles, ch) { + if (DDTRACE_G(curl_multi_injecting_spans) && Z_TYPE(DDTRACE_G(curl_multi_injecting_spans)->val) == IS_ARRAY) { + ddtrace_span_data *span = ddtrace_open_span(DDTRACE_INTERNAL_SPAN); + dd_inject_distributed_tracing_headers(ch); + ddtrace_close_span(span); + span->duration = 1; + + SEPARATE_ARRAY(&DDTRACE_G(curl_multi_injecting_spans)->val); + + zval data; + array_init(&data); + GC_ADDREF(ch); + add_next_index_object(&data, ch); + add_next_index_object(&data, &span->std); + zend_hash_next_index_insert(Z_ARR(DDTRACE_G(curl_multi_injecting_spans)->val), &data); + } else { + dd_inject_distributed_tracing_headers(ch); + } + } ZEND_HASH_FOREACH_END(); + + if (DDTRACE_G(curl_multi_injecting_spans)) { + if (GC_DELREF(DDTRACE_G(curl_multi_injecting_spans)) == 0) { + rc_dtor_func((zend_refcounted *) DDTRACE_G(curl_multi_injecting_spans)); + } + DDTRACE_G(curl_multi_injecting_spans) = NULL; + } zend_weakrefs_hash_del(&dd_multi_handles, mh); } diff --git a/ext/handlers_curl_php7.c b/ext/handlers_curl_php7.c index b1a1ee99dd..fb29f376b9 100644 --- a/ext/handlers_curl_php7.c +++ b/ext/handlers_curl_php7.c @@ -157,6 +157,26 @@ static int dd_inject_distributed_tracing_headers(zval *ch) { return ZEND_HASH_APPLY_REMOVE; } +static int dd_inject_distributed_tracing_headers_multi(zval *ch) { + if (DDTRACE_G(curl_multi_injecting_spans) && Z_TYPE(DDTRACE_G(curl_multi_injecting_spans)->val) == IS_ARRAY) { + ddtrace_span_data *span = ddtrace_open_span(DDTRACE_INTERNAL_SPAN); + int ret = dd_inject_distributed_tracing_headers(ch); + ddtrace_close_span(span); + span->duration = 1; + + SEPARATE_ARRAY(&DDTRACE_G(curl_multi_injecting_spans)->val); + + zval data; + array_init(&data); + Z_ADDREF_P(ch); + add_next_index_zval(&data, ch); + add_next_index_object(&data, &span->std); + zend_hash_next_index_insert(Z_ARR(DDTRACE_G(curl_multi_injecting_spans)->val), &data); + return ret; + } + return dd_inject_distributed_tracing_headers(ch); +} + static bool dd_is_valid_curl_resource(zval *ch) { if (le_curl) { void *resource = zend_fetch_resource(Z_RES_P(ch), NULL, le_curl); @@ -268,9 +288,16 @@ static void dd_multi_inject_headers(zval *mh) { } if (handles && zend_hash_num_elements(handles) > 0) { - zend_hash_apply(handles, dd_inject_distributed_tracing_headers); + zend_hash_apply(handles, dd_inject_distributed_tracing_headers_multi); dd_multi_reset(mh); } + + if (DDTRACE_G(curl_multi_injecting_spans)) { + if (GC_DELREF(DDTRACE_G(curl_multi_injecting_spans)) == 0) { + rc_dtor_func((zend_refcounted *) DDTRACE_G(curl_multi_injecting_spans)); + } + DDTRACE_G(curl_multi_injecting_spans) = NULL; + } } ZEND_FUNCTION(ddtrace_curl_close) { diff --git a/ext/hook/uhook.c b/ext/hook/uhook.c index d53266688c..c9f9556d5c 100644 --- a/ext/hook/uhook.c +++ b/ext/hook/uhook.c @@ -166,7 +166,7 @@ void dd_uhook_report_sandbox_error(zend_execute_data *execute_data, zend_object }) } -static void dd_uhook_call_hook(zend_execute_data *execute_data, zend_object *closure, dd_hook_data *hook_data) { +static bool dd_uhook_call_hook(zend_execute_data *execute_data, zend_object *closure, dd_hook_data *hook_data) { zval closure_zv, hook_data_zv; ZVAL_OBJ(&closure_zv, closure); ZVAL_OBJ(&hook_data_zv, &hook_data->std); @@ -182,6 +182,7 @@ static void dd_uhook_call_hook(zend_execute_data *execute_data, zend_object *clo } zai_sandbox_close(&sandbox); zval_ptr_dtor(&rv); + return Z_TYPE(rv) != IS_FALSE; } static bool dd_uhook_match_filepath(zend_string *file, zend_string *source) { @@ -268,6 +269,8 @@ static void dd_uhook_end(zend_ulong invocation, zend_execute_data *execute_data, dd_trace_stop_span_time(span); } + bool keep_span = true; + if (def->end && !def->running && get_DD_TRACE_ENABLED()) { zval tmp; @@ -307,7 +310,7 @@ static void dd_uhook_end(zend_ulong invocation, zend_execute_data *execute_data, def->running = true; dyn->hook_data->retval_ptr = retval; - dd_uhook_call_hook(execute_data, def->end, dyn->hook_data); + keep_span = dd_uhook_call_hook(execute_data, def->end, dyn->hook_data); dyn->hook_data->retval_ptr = NULL; def->running = false; } @@ -316,7 +319,7 @@ static void dd_uhook_end(zend_ulong invocation, zend_execute_data *execute_data, dyn->hook_data->span = NULL; // e.g. spans started in limited mode are never properly started if (span->start) { - ddtrace_clear_execute_data_span(invocation, true); + ddtrace_clear_execute_data_span(invocation, keep_span); if (dyn->hook_data->prior_stack) { ddtrace_switch_span_stack(dyn->hook_data->prior_stack); OBJ_RELEASE(&dyn->hook_data->prior_stack->std); diff --git a/ext/integrations/integrations.c b/ext/integrations/integrations.c index ed56c57034..d282a730fd 100644 --- a/ext/integrations/integrations.c +++ b/ext/integrations/integrations.c @@ -160,6 +160,8 @@ void ddtrace_integrations_minit(void) { DD_SET_UP_DEFERRED_LOADING_BY_FUNCTION(DDTRACE_INTEGRATION_CURL, "curl_exec", "DDTrace\\Integrations\\Curl\\CurlIntegration"); + DD_SET_UP_DEFERRED_LOADING_BY_FUNCTION(DDTRACE_INTEGRATION_CURL, "curl_multi_exec", + "DDTrace\\Integrations\\Curl\\CurlIntegration"); DD_SET_UP_DEFERRED_LOADING_BY_METHOD(DDTRACE_INTEGRATION_DRUPAL, "Drupal\\Core\\DrupalKernel", "__construct", "DDTrace\\Integrations\\Drupal\\DrupalIntegration"); diff --git a/src/Integrations/Integrations/Curl/CurlIntegration.php b/src/Integrations/Integrations/Curl/CurlIntegration.php index 2cc5959581..4d2f3ca655 100644 --- a/src/Integrations/Integrations/Curl/CurlIntegration.php +++ b/src/Integrations/Integrations/Curl/CurlIntegration.php @@ -2,12 +2,14 @@ namespace DDTrace\Integrations\Curl; +use DDTrace\HookData; use DDTrace\Http\Urls; use DDTrace\Integrations\HttpClientIntegrationHelper; use DDTrace\Integrations\Integration; use DDTrace\SpanData; use DDTrace\Tag; use DDTrace\Type; +use DDTrace\Util\ObjectKVStore; /** * @param \DDTrace\SpanData $span @@ -48,13 +50,7 @@ public function init() // the ddtrace extension will handle distributed headers 'instrument_when_limited' => 0, 'posthook' => function (SpanData $span, $args, $retval) use ($integration) { - $span->name = $span->resource = 'curl_exec'; - $span->type = Type::HTTP_CLIENT; - $span->service = 'curl'; - Integration::handleInternalSpanServiceName($span, CurlIntegration::NAME); - $integration->addTraceAnalyticsIfEnabled($span); - $span->meta[Tag::COMPONENT] = CurlIntegration::NAME; - $span->meta[Tag::SPAN_KIND] = Tag::SPAN_KIND_VALUE_CLIENT; + $integration->setup_curl_span($span); if (!isset($args[0])) { return; @@ -65,59 +61,205 @@ public function init() $span->meta[Tag::ERROR_MSG] = \curl_error($ch); $span->meta[Tag::ERROR_TYPE] = 'curl error'; if (PHP_VERSION_ID >= 70000) { - $span->meta[Tag::ERROR_STACK] = \DDTrace\get_sanitized_exception_trace(new \Exception()); + $span->meta[Tag::ERROR_STACK] = \DDTrace\get_sanitized_exception_trace(new \Exception(), 1); } } - $info = \curl_getinfo($ch); - $sanitizedUrl = \DDTrace\Util\Normalizer::urlSanitize($info['url']); - $normalizedPath = \DDTrace\Util\Normalizer::uriNormalizeOutgoingPath($info['url']); - $host = Urls::hostname($sanitizedUrl); - $span->meta[Tag::NETWORK_DESTINATION_NAME] = $host; - unset($info['url']); + CurlIntegration::set_curl_attributes($span, \curl_getinfo($ch)); + }, + ]); - if (\DDTrace\Util\Runtime::getBoolIni("datadog.trace.http_client_split_by_domain")) { - $span->service = Urls::hostnameForTag($sanitizedUrl); + if (\PHP_MAJOR_VERSION > 5) { + $lastMh = [0, null]; + \DDTrace\install_hook('curl_multi_exec', function (HookData $hook) use ($integration, &$lastMh) { + if (\count($hook->args) >= 2) { + $data = null; + if (\PHP_MAJOR_VERSION > 7) { + $data = ObjectKVStore::get($hook->args[0], "span"); + } elseif ($lastMh[0] == (int)$hook->args[0]) { + $data = $lastMh[1]; + $lastMh = [0, null]; + } + if ($data) { + $hook->data = $data; + return; + } } - $span->resource = $normalizedPath; - - /* Special case the Datadog Standard Attributes - * See https://docs.datadoghq.com/logs/processing/attributes_naming_convention/ - */ - if (!array_key_exists(Tag::HTTP_URL, $span->meta)) { - $span->meta[Tag::HTTP_URL] = $sanitizedUrl; + $span = $hook->span(); + if (\count($hook->args) >= 2) { + \DDTrace\curl_multi_exec_get_request_spans($spans); + $hook->data = [$span, &$spans, true]; + if (\PHP_MAJOR_VERSION > 7) { + ObjectKVStore::put($hook->args[0], "span", [$span, &$spans]); + } } - if (\PHP_MAJOR_VERSION > 5) { - $span->peerServiceSources = HttpClientIntegrationHelper::PEER_SERVICE_SOURCES; + $span->name = 'curl_multi_exec'; + $span->resource = 'curl_multi_exec'; + $span->service = "curl"; + $span->type = Type::HTTP_CLIENT; + Integration::handleInternalSpanServiceName($span, CurlIntegration::NAME); + $span->meta[Tag::COMPONENT] = CurlIntegration::NAME; + $span->peerServiceSources = HttpClientIntegrationHelper::PEER_SERVICE_SOURCES; + }, function (HookData $hook) use ($integration, &$lastMh) { + if (empty($hook->data) || $hook->exception) { + return; } - addSpanDataTagFromCurlInfo($span, $info, Tag::HTTP_STATUS_CODE, 'http_code'); + $span = $hook->data[0]; + $spans = &$hook->data[1]; - addSpanDataTagFromCurlInfo($span, $info, 'network.client.ip', 'local_ip'); - addSpanDataTagFromCurlInfo($span, $info, 'network.client.port', 'local_port'); + if (!$spans) { + // Drop the span if nothing was handled here + if (\PHP_MAJOR_VERSION == 8) { + ObjectKVStore::put($hook->args[0], "span", null); + } + return false; + } - addSpanDataTagFromCurlInfo($span, $info, 'network.destination.ip', 'primary_ip'); - addSpanDataTagFromCurlInfo($span, $info, 'network.destination.port', 'primary_port'); + if ($spans && $spans[0][1]->name != "curl_exec") { + foreach ($spans as $requestSpan) { + list(, $requestSpan) = $requestSpan; + $integration->setup_curl_span($requestSpan); + } + } - addSpanDataTagFromCurlInfo($span, $info, 'network.bytes_read', 'size_download'); - addSpanDataTagFromCurlInfo($span, $info, 'network.bytes_written', 'size_upload'); + $saveSpans = $hook->args[1]; - // Add the rest to a 'curl.' object - foreach ($info as $key => $val) { - // Datadog doesn't support arrays in tags - if (\is_scalar($val) && $val !== '') { - // Datadog sets durations in nanoseconds - convert from seconds - if (\substr_compare($key, '_time', -5) === 0) { - $val *= 1000000000; + if (!$hook->args[1]) { + // finished + foreach ($spans as $requestSpan) { + list($ch, $requestSpan) = $requestSpan; + $info = curl_getinfo($ch); + if ($info["connect_time"] <= 0) { + $saveSpans = true; + if (!isset($error_trace)) { + $error_trace = \DDTrace\get_sanitized_exception_trace(new \Exception(), 1); + } + if (!isset($requestSpan->meta[Tag::ERROR_MSG])) { + $requestSpan->meta[Tag::ERROR_MSG] = "CURL request failure"; + } + $requestSpan->meta[Tag::ERROR_TYPE] = 'curl error'; + $requestSpan->meta[Tag::ERROR_STACK] = $error_trace; + } + CurlIntegration::set_curl_attributes($requestSpan, $info); + if (isset($info["total_time"])) { + $endTime = $info["total_time"] + $requestSpan->getStartTime() / 1e9; + \DDTrace\update_span_duration($requestSpan, $endTime); } - $span->meta["curl.{$key}"] = $val; } } - }, - ]); + + // If there's an error we retain it for a possible future curl_multi_info_read + if ($saveSpans) { + if (\PHP_MAJOR_VERSION == 7) { + $lastMh = [(int)$hook->args[0], [$span, &$spans]]; + } + } elseif (\PHP_MAJOR_VERSION == 8) { + ObjectKVStore::put($hook->args[0], "span", null); + } + + if (!isset($hook->data[2])) { + \DDTrace\update_span_duration($span); + } + + if ($hook->returned != CURLM_OK) { + if (!isset($error_trace)) { + $error_trace = \DDTrace\get_sanitized_exception_trace(new \Exception(), 1); + } + $requestSpan->meta[Tag::ERROR_MSG] = curl_multi_strerror($hook->returned); + $requestSpan->meta[Tag::ERROR_TYPE] = 'curl_multi error'; + $requestSpan->meta[Tag::ERROR_STACK] = $error_trace; + } + }); + + \DDTrace\install_hook('curl_multi_info_read', null, function (HookData $hook) use (&$lastMh) { + if (count($hook->args) < 1 || !isset($hook->returned["handle"])) { + return; + } + if (!isset($hook->returned["result"]) || $hook->returned["result"] == CURLE_OK) { + return; + } + + $handle = $hook->returned["handle"]; + + if (\PHP_MAJOR_VERSION > 7) { + $data = ObjectKVStore::get($hook->args[0], "span"); + } elseif ($lastMh[0] == (int)$hook->args[0]) { + $data = $lastMh[1]; + } + + list(, $spans) = $data; + foreach ($spans as $requestSpan) { + list($ch, $requestSpan) = $requestSpan; + if ($ch === $handle) { + $requestSpan->meta[Tag::ERROR_MSG] = curl_strerror($hook->returned["result"]); + } + } + }); + } return Integration::LOADED; } + + public function setup_curl_span($span) { + $span->name = $span->resource = 'curl_exec'; + $span->type = Type::HTTP_CLIENT; + $span->service = 'curl'; + Integration::handleInternalSpanServiceName($span, CurlIntegration::NAME); + $this->addTraceAnalyticsIfEnabled($span); + $span->meta[Tag::COMPONENT] = CurlIntegration::NAME; + $span->meta[Tag::SPAN_KIND] = Tag::SPAN_KIND_VALUE_CLIENT; + } + + public static function set_curl_attributes($span, $info) { + $sanitizedUrl = \DDTrace\Util\Normalizer::urlSanitize($info['url']); + $normalizedPath = \DDTrace\Util\Normalizer::uriNormalizeOutgoingPath($info['url']); + $host = Urls::hostname($sanitizedUrl); + $span->meta[Tag::NETWORK_DESTINATION_NAME] = $host; + unset($info['url']); + + if (\DDTrace\Util\Runtime::getBoolIni("datadog.trace.http_client_split_by_domain")) { + $span->service = Urls::hostnameForTag($sanitizedUrl); + } + + $span->resource = $normalizedPath; + + /* Special case the Datadog Standard Attributes + * See https://docs.datadoghq.com/logs/processing/attributes_naming_convention/ + */ + if (!array_key_exists(Tag::HTTP_URL, $span->meta)) { + $span->meta[Tag::HTTP_URL] = $sanitizedUrl; + } + + if (\PHP_MAJOR_VERSION > 5) { + $span->peerServiceSources = HttpClientIntegrationHelper::PEER_SERVICE_SOURCES; + } + + addSpanDataTagFromCurlInfo($span, $info, Tag::HTTP_STATUS_CODE, 'http_code'); + + addSpanDataTagFromCurlInfo($span, $info, 'network.client.ip', 'local_ip'); + addSpanDataTagFromCurlInfo($span, $info, 'network.client.port', 'local_port'); + + addSpanDataTagFromCurlInfo($span, $info, 'network.destination.ip', 'primary_ip'); + addSpanDataTagFromCurlInfo($span, $info, 'network.destination.port', 'primary_port'); + + addSpanDataTagFromCurlInfo($span, $info, 'network.bytes_read', 'size_download'); + addSpanDataTagFromCurlInfo($span, $info, 'network.bytes_written', 'size_upload'); + + // Add the rest to a 'curl.' object + foreach ($info as $key => $val) { + // Datadog doesn't support arrays in tags + if (\is_scalar($val) && $val !== '') { + // Datadog sets durations in nanoseconds - convert from seconds + if (\substr_compare($key, '_time', -5) === 0) { + $val *= 1000000000; + } + $span->meta["curl.{$key}"] = $val; + } + } + + return $info; + } } diff --git a/tests/Integrations/Curl/CurlIntegrationTest.php b/tests/Integrations/Curl/CurlIntegrationTest.php index aa8ca0ac2c..f9b65d0d6a 100644 --- a/tests/Integrations/Curl/CurlIntegrationTest.php +++ b/tests/Integrations/Curl/CurlIntegrationTest.php @@ -561,6 +561,65 @@ public function testHttpHeadersIsCorrectlySetAgain() }); } + public function testMulti() + { + $traces = $this->isolateTracer(function () { + $ch1 = curl_init(self::URL . '/status/200'); + curl_setopt($ch1, CURLOPT_RETURNTRANSFER, true); + $ch2 = curl_init(self::URL_NOT_EXISTS); + curl_setopt($ch2, CURLOPT_RETURNTRANSFER, true); + + $mh = curl_multi_init(); + curl_multi_add_handle($mh, $ch1); + curl_multi_add_handle($mh, $ch2); + + do { + $status = curl_multi_exec($mh, $active); + if ($active) { + curl_multi_select($mh); + } + while (false !== curl_multi_info_read($mh)); + } while ($active && $status == CURLM_OK); + + $response = curl_multi_getcontent($ch1); + $this->assertSame('', $response); + $response = curl_multi_getcontent($ch2); + $this->assertSame('', $response); + curl_multi_close($mh); + }); + + $this->assertFlameGraph($traces, [ + SpanAssertion::build('curl_multi_exec', 'curl', 'http', 'curl_multi_exec') + ->withExactTags([ + Tag::COMPONENT => 'curl', + ])->withChildren([ + SpanAssertion::build('curl_exec', 'curl', 'http', 'http://httpbin_integration/status/?') + ->setTraceAnalyticsCandidate() + ->withExactTags([ + 'http.url' => self::URL . '/status/200', + 'http.status_code' => '200', + 'span.kind' => 'client', + 'network.destination.name' => 'httpbin_integration', + Tag::COMPONENT => 'curl', + ]) + ->withExistingTagsNames(self::commonCurlInfoTags()) + ->skipTagsLike('/^curl\..*/'), + SpanAssertion::build('curl_exec', 'curl', 'http', 'http://__i_am_not_real__.invalid/') + ->setTraceAnalyticsCandidate() + ->withExactTags([ + 'http.url' => 'http://__i_am_not_real__.invalid/', + 'http.status_code' => '0', + 'span.kind' => 'client', + 'network.destination.name' => '__i_am_not_real__.invalid', + Tag::COMPONENT => 'curl', + ]) + ->withExistingTagsNames(self::commonCurlInfoTags()) + ->skipTagsLike('/^curl\..*/') + ->setError('curl error', "Couldn't resolve host name", true), + ]), + ]); + } + /** * @dataProvider dataProviderTestTraceAnalytics */ diff --git a/tests/Integrations/Guzzle/V5/GuzzleIntegrationTest.php b/tests/Integrations/Guzzle/V5/GuzzleIntegrationTest.php index 4ba7afab05..fc9d8ff927 100644 --- a/tests/Integrations/Guzzle/V5/GuzzleIntegrationTest.php +++ b/tests/Integrations/Guzzle/V5/GuzzleIntegrationTest.php @@ -256,8 +256,8 @@ function ($execute) use (&$headers1, &$headers2) { * without an event loop. * @see https://github.com/guzzle/guzzle/issues/1439 */ - self::assertDistributedTracingSpan($traces[0][2], $headers1['headers']); - self::assertDistributedTracingSpan($traces[0][1], $headers2['headers']); + self::assertDistributedTracingSpan($traces[0][6], $headers1['headers']); + self::assertDistributedTracingSpan($traces[0][3], $headers2['headers']); } private static function assertDistributedTracingSpan($span, $headers) diff --git a/tests/Integrations/Guzzle/V6/GuzzleIntegrationTest.php b/tests/Integrations/Guzzle/V6/GuzzleIntegrationTest.php index dd4e7f81e9..dfbabade75 100644 --- a/tests/Integrations/Guzzle/V6/GuzzleIntegrationTest.php +++ b/tests/Integrations/Guzzle/V6/GuzzleIntegrationTest.php @@ -252,10 +252,19 @@ function ($execute) use (&$found) { * $curl->tick() is called. */ $rootSpan = $traces[0][0]; - self::assertSame( - $rootSpan['span_id'], - $data['headers']['X-Datadog-Parent-Id'] - ); + try { + $parentSpan = $traces[0][3]; + self::assertSame( + $parentSpan['span_id'], + $data['headers']['X-Datadog-Parent-Id'] + ); + } catch (\Throwable $t) { + $parentSpan = $traces[0][2]; + self::assertSame( + $parentSpan['span_id'], + $data['headers']['X-Datadog-Parent-Id'] + ); + } self::assertSame( $rootSpan['trace_id'], $data['headers']['X-Datadog-Trace-Id'] diff --git a/tests/internal-api-stress-test.php b/tests/internal-api-stress-test.php index 38639039cb..3dbf459d98 100644 --- a/tests/internal-api-stress-test.php +++ b/tests/internal-api-stress-test.php @@ -147,7 +147,8 @@ function runOneIteration() $functions = array_filter($ext->getFunctions(), function ($f) { return $f->name != "dd_trace_internal_fn" && !strpos($f->name, "Testing") - && $f->name != "dd_trace_disable_in_request"; + && $f->name != "dd_trace_disable_in_request" + && (PHP_VERSION_ID >= 70100 || $f->name != 'DDTrace\curl_multi_exec_get_request_spans'); }); $props = array_filter( diff --git a/zend_abstract_interface/exceptions/exceptions.c b/zend_abstract_interface/exceptions/exceptions.c index 548b37aab8..bc6d437d05 100644 --- a/zend_abstract_interface/exceptions/exceptions.c +++ b/zend_abstract_interface/exceptions/exceptions.c @@ -41,7 +41,7 @@ zend_string *zai_exception_message(zend_object *ex) { /* Modeled after Exception::getTraceAsString: * @see https://heap.space/xref/PHP-8.0/Zend/zend_exceptions.c#getTraceAsString */ -zend_string *zai_get_trace_without_args(zend_array *trace) { +zend_string *zai_get_trace_without_args_skip_frames(zend_array *trace, int skip) { if (!trace) { // should never happen; TODO: fail in CI return zend_string_init_interned(ZEND_STRL("[broken trace]"), 1); @@ -51,6 +51,10 @@ zend_string *zai_get_trace_without_args(zend_array *trace) { smart_str str = {0}; uint32_t num = 0; ZEND_HASH_FOREACH_VAL(trace, frame) { + if (skip-- > 0) { + continue; + } + smart_str_appendc(&str, '#'); smart_str_append_long(&str, num++); smart_str_appendc(&str, ' '); @@ -118,7 +122,11 @@ zend_string *zai_get_trace_without_args(zend_array *trace) { return str.s; } -zend_string *zai_get_trace_without_args_from_exception(zend_object *ex) { +zend_string *zai_get_trace_without_args(zend_array *trace) { + return zai_get_trace_without_args_skip_frames(trace, 0); +} + +zend_string *zai_get_trace_without_args_from_exception_skip_frames(zend_object *ex, int skip) { if (!ex) { return ZSTR_EMPTY_ALLOC(); // should never happen; TODO: fail in CI } @@ -129,5 +137,9 @@ zend_string *zai_get_trace_without_args_from_exception(zend_object *ex) { return ZSTR_EMPTY_ALLOC(); // should never happen in PHP 8 as the property is typed and always initialized } - return zai_get_trace_without_args(Z_ARR_P(trace)); + return zai_get_trace_without_args_skip_frames(Z_ARR_P(trace), skip); } + +zend_string *zai_get_trace_without_args_from_exception(zend_object *ex) { + return zai_get_trace_without_args_from_exception_skip_frames(ex, 0); +} \ No newline at end of file diff --git a/zend_abstract_interface/exceptions/exceptions.h b/zend_abstract_interface/exceptions/exceptions.h index 24c472ed07..bcbe6d7520 100644 --- a/zend_abstract_interface/exceptions/exceptions.h +++ b/zend_abstract_interface/exceptions/exceptions.h @@ -53,5 +53,7 @@ static inline zval *zai_exception_read_property(zend_object *object, zend_string zend_string *zai_exception_message(zend_object *ex); // fallback string if message invalid zend_string *zai_get_trace_without_args(zend_array *trace); zend_string *zai_get_trace_without_args_from_exception(zend_object *ex); +zend_string *zai_get_trace_without_args_skip_frames(zend_array *trace, int skip); +zend_string *zai_get_trace_without_args_from_exception_skip_frames(zend_object *ex, int skip); #endif // ZAI_EXCEPTIONS_H