Add tracing for curl_multi_exec() (#2347)

* Add tracing for curl_multi_exec() Fixes #1156. Signed-off-by: Bob Weinand <[email protected]> * Also track curl_multi_info_read for curl_multi_exec errors Signed-off-by: Bob Weinand <[email protected]> * Fix CI * Fix memory leak Signed-off-by: Bob Weinand <[email protected]> * Try fixing test flakiness Signed-off-by: Bob Weinand <[email protected]> * Reflection doesn't like calling functions with references on PHP 7.0 --------- Signed-off-by: Bob Weinand <[email protected]>
DataDog · Nov 19, 2023 · 8b7df34 · 8b7df34
1 parent d80306e
commit 8b7df34
Show file tree

Hide file tree

Showing 16 changed files with 470 additions and 74 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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) {