Track DD_TRACE_DEBUG=1 errors in integration and web tests

ext/logging.c

@@ -74,16 +74,24 @@ int ddtrace_bgs_logf(const char *fmt, ...) {
 }
 
 static void ddtrace_log_callback(ddog_Log log, ddog_CharSlice msg) {
-    (void)log; // maybe use?
-
-    char *message = (char*)msg.ptr;
-    if (msg.ptr[msg.len]) {
-        message = strndup(msg.ptr, msg.len);
-        php_log_err(message);
-        free(message);
+    const char *name = "debug";
+    uint32_t bits = log.bits & ~ddog_Log_Once.bits;
+    if (bits == (ddog_Log_Deprecated.bits & ~ddog_Log_Once.bits)) {
+        name = "deprecated";
+    } else if (bits == ddog_Log_Warn.bits) {
+        name = "warning";
+    } else if (bits == ddog_Log_Info.bits) {
+        name = "info";
+    } else if (bits == ddog_Log_Startup.bits) {
+        name = "startup";
     } else {
-        php_log_err(message);
+        name = "error";
     }
+
+    char *message;
+    asprintf(&message, "[ddtrace] [%s] %.*s", name, (int)msg.len, msg.ptr);
+    php_log_err(message);
+    free(message);
 }
 
 

ext/serializer.c

@@ -1568,6 +1568,11 @@ void ddtrace_error_cb(DDTRACE_ERROR_CB_PARAMETERS) {
     // On fatal error we explicitly bail out.
     bool is_fatal_error = orig_type & (E_ERROR | E_CORE_ERROR | E_COMPILE_ERROR | E_USER_ERROR);
     if (zai_sandbox_active) {
+        // Do not track silenced errors like via @ operator
+        if (!is_fatal_error && (orig_type & EG(error_reporting)) == 0) {
+            return;
+        }
+
         clear_last_error();
         PG(last_error_type) = orig_type & E_ALL;
 #if PHP_VERSION_ID < 80000

src/Integrations/Integrations/Mysqli/MysqliCommon.php

@@ -15,7 +15,8 @@ class MysqliCommon
      */
     public static function extractHostInfo($mysqli)
     {
-        if (!isset($mysqli->host_info) || !is_string($mysqli->host_info)) {
+        // silence "Property access is not allowed yet" for PHP <= 7.3
+        if (@(!isset($mysqli->host_info) || !is_string($mysqli->host_info))) {
             return [];
         }
         $hostInfo = $mysqli->host_info;

src/Integrations/Integrations/Psr18/Psr18Integration.php

@@ -51,6 +51,8 @@ function (SpanData $span, $args, $retval) use ($integration) {
                 }
             }
         );
+
+        return Integration::LOADED;
     }
 
     public function addRequestInfo(SpanData $span, $request)

tests/Common/TracerTestTrait.php

@@ -21,6 +21,11 @@ class FakeSpan extends Span
 {
     public $startTime;
     public $duration;
+
+    public function __destruct()
+    {
+        // Silence destructor warning about unclosed spans for fake spans
+    }
 }
 
 trait TracerTestTrait

tests/Integrations/AMQP/AMQPTest.php

@@ -901,7 +901,7 @@ public function testDistributedTracing()
         );
 
         // Assess that user headers weren't lost
-        $this->assertSame("", $output);
+        $this->assertSame("", trim(preg_replace("(.*\[ddtrace].*)", "", $output)));
 
         $sendTraces = $sendTraces[0][0]; // There is a root span
         // Spans: send.php -> basic_publish -> queue_declare -> connect
@@ -942,7 +942,7 @@ public function testDistributedTracingIsNotPropagatedIfDisabled()
         );
 
         // Assess that user headers weren't lost
-        $this->assertSame("", $output);
+        $this->assertSame("", trim(preg_replace("(.*\[ddtrace].*)", "", $output)));
 
         $sendTraces = $sendTraces[0][0]; // There is a root span
         // Spans: send.php -> basic_publish -> queue_declare -> connect

tests/Integrations/Laravel/V8_x/RouteCachingTest.php

@@ -136,12 +136,12 @@ public function testRouteNameNormalization()
     private function routeCache()
     {
         $appRoot = \dirname(\dirname(self::getAppIndexScript()));
-        `cd $appRoot && php artisan route:cache`;
+        `cd $appRoot && DD_TRACE_CLI_ENABLED=0 php artisan route:cache`;
     }
 
     private function routeClear()
     {
         $appRoot = \dirname(\dirname(self::getAppIndexScript()));
-        `cd $appRoot && php artisan route:clear`;
+        `cd $appRoot && DD_TRACE_CLI_ENABLED=0 php artisan route:clear`;
     }
 }

tests/Integrations/PCNTL/PCNTLTest.php

@@ -104,6 +104,7 @@ public function testAccessingTracerAfterForkIsUnproblematic()
                 'DD_TRACE_CLI_ENABLED' => 'true',
                 'DD_TRACE_SHUTDOWN_TIMEOUT' => 5000,
                 'DD_TRACE_GENERATE_ROOT_SPAN' => 'true',
+                'DD_TRACE_DEBUG' => 'false',
             ],
             [],
             "",

tests/WebServer.php

@@ -74,6 +74,8 @@ final class WebServer
         'datadog.trace.client_ip_header_disabled' => 'true',
     ];
 
+    private $errorLogSize = 0;
+
     /**
      * Persisted apache instance for the lifetime of the testsuite - we use reload instead of restart to apply changes.
      * The primary use case is verifying repeated MINIT+MSHUTDOWN invocations within a same process.
@@ -104,6 +106,8 @@ public function setRoadrunner($version)
 
     public function start()
     {
+        $this->errorLogSize = (int)@filesize($this->defaultInis['error_log']);
+
         if ($this->roadrunnerVersion) {
             $this->sapi = new RoadrunnerServer(
                 $this->roadrunnerVersion,
@@ -222,8 +226,15 @@ public function mergeInis($inis)
      */
     public function checkErrors()
     {
-        if (!$this->sapi) {
-            return null;
+        $diff = @file_get_contents($this->defaultInis['error_log'], false, null, $this->errorLogSize);
+        $out = "";
+        foreach (explode("\n", $diff) as $line) {
+            if (preg_match("(\[ddtrace] \[(error|warn|deprecated)])", $line)) {
+                $out .= $line;
+            }
+        }
+        if ($out) {
+            return $out . ($this->sapi ? $this->sapi->checkErrors() : "");
         }
         return $this->sapi->checkErrors();
     }

tests/ext/background-sender/agent_headers.phpt

@@ -40,7 +40,7 @@ echo 'Done.' . PHP_EOL;
 
 ?>
 --EXPECTF--
-Flushing trace of size 1 to send-queue for http://request-replayer:80
+[ddtrace] [info] Flushing trace of size 1 to send-queue for http://request-replayer:80
 
 content-type: application/msgpack
 datadog-meta-lang: php
@@ -50,4 +50,4 @@ datadog-meta-tracer-version: %s
 x-datadog-trace-count: 1
 
 Done.
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/background-sender/agent_headers_container_id.phpt

@@ -38,10 +38,10 @@ echo 'Done.' . PHP_EOL;
 
 ?>
 --EXPECTF--
-Flushing trace of size 1 to send-queue for http://request-replayer:80
+[ddtrace] [info] Flushing trace of size 1 to send-queue for http://request-replayer:80
 
 datadog-container-id: 9d5b23edb1ba181e8910389a99906598d69ac9a0ead109ee55730cc416d95f7f
 datadog-meta-lang: php
 
 Done.
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/background-sender/agent_headers_container_id_empty.phpt

@@ -38,9 +38,9 @@ echo 'Done.' . PHP_EOL;
 
 ?>
 --EXPECTF--
-Flushing trace of size 1 to send-queue for http://request-replayer:80
+[ddtrace] [info] Flushing trace of size 1 to send-queue for http://request-replayer:80
 
 datadog-meta-lang: php
 
 Done.
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/background-sender/agent_headers_container_id_fargate.phpt

@@ -37,10 +37,10 @@ echo 'Done.' . PHP_EOL;
 
 ?>
 --EXPECTF--
-Flushing trace of size 1 to send-queue for http://request-replayer:80
+[ddtrace] [info] Flushing trace of size 1 to send-queue for http://request-replayer:80
 
 datadog-container-id: 34dc0b5e626f2c5c4c5170e34b10e765-1234567890
 datadog-meta-lang: php
 
 Done.
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/background-sender/agent_headers_ignore_userland.phpt

@@ -45,4 +45,4 @@ bool(true)
 datadog-meta-lang: php
 
 Done.
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/background-sender/agent_sampling.phpt

@@ -48,10 +48,10 @@ echo "Specific sampling: {$get_sampling()}\n";
 
 ?>
 --EXPECTF--
-Flushing trace of size 1 to send-queue for http://request-replayer:80
+[ddtrace] [info] Flushing trace of size 1 to send-queue for http://request-replayer:80
 Initial sampling: 1
-Flushing trace of size 1 to send-queue for http://request-replayer:80
+[ddtrace] [info] Flushing trace of size 1 to send-queue for http://request-replayer:80
 Generic sampling: 0
-Flushing trace of size 1 to send-queue for http://request-replayer:80
+[ddtrace] [info] Flushing trace of size 1 to send-queue for http://request-replayer:80
 Specific sampling: 1
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/close_spans_until.phpt

@@ -30,4 +30,4 @@ int(2)
 int(2)
 int(1)
 int(0)
-Flushing trace of size 7 to send-queue for %s
+[ddtrace] [info] Flushing trace of size 7 to send-queue for %s

tests/ext/dd_trace_serialize_msgpack_error.phpt

@@ -13,15 +13,15 @@ array_map(function ($data) {
 ]);
 ?>
 --EXPECTF--
-Serialize values must be of type array, string, int, float, bool or null
+[ddtrace] [warning] Serialize values must be of type array, string, int, float, bool or null
 array(1) {
   [0]=>
   object(stdClass)#%d (0) {
   }
 }
 bool(false)
 
-Serialize values must be of type array, string, int, float, bool or null
+[ddtrace] [warning] Serialize values must be of type array, string, int, float, bool or null
 array(2) {
   [0]=>
   string(3) "bar"
@@ -30,4 +30,4 @@ array(2) {
 }
 bool(false)
 
-Flushing trace of size 1 to send-queue for %s
+[ddtrace] [info] Flushing trace of size 1 to send-queue for %s

tests/ext/dropped_spans_have_negative_duration.phpt

@@ -18,4 +18,4 @@ var_dump($outerSpan->getDuration());
 --EXPECTF--
 int(1)
 int(-1)
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/extract_ip_addr.phpt

@@ -108,16 +108,16 @@ x_forwarded_for: [2001::1]:1111
 string(7) "2001::1"
 
 x_forwarded_for: bad_value, 1.1.1.1
-Not recognized as IP address: "bad_value"
-Not recognized as IP address: "bad_value"
+[ddtrace] [error] Not recognized as IP address: "bad_value"
+[ddtrace] [error] Not recognized as IP address: "bad_value"
 string(7) "1.1.1.1"
 
 x_real_ip: 2.2.2.2
 string(7) "2.2.2.2"
 
 x_real_ip: 2.2.2.2, 3.3.3.3
-Not recognized as IP address: "2.2.2.2, 3.3.3.3"
-Not recognized as IP address: "2.2.2.2, 3.3.3.3"
+[ddtrace] [error] Not recognized as IP address: "2.2.2.2, 3.3.3.3"
+[ddtrace] [error] Not recognized as IP address: "2.2.2.2, 3.3.3.3"
 NULL
 
 x_real_ip: 127.0.0.1
@@ -157,16 +157,16 @@ x_forwarded: for="2001:abcf::1"
 string(12) "2001:abcf::1"
 
 x_forwarded: for=some_host
-Not recognized as IP address: "some_host"
-Not recognized as IP address: "some_host"
+[ddtrace] [error] Not recognized as IP address: "some_host"
+[ddtrace] [error] Not recognized as IP address: "some_host"
 NULL
 
 x_forwarded: for=127.0.0.1, FOR=1.1.1.1
 string(7) "1.1.1.1"
 
 x_forwarded: for="\"foobar";proto=http,FOR="1.1.1.1"
-Not recognized as IP address: "\"foobar"
-Not recognized as IP address: "\"foobar"
+[ddtrace] [error] Not recognized as IP address: "\"foobar"
+[ddtrace] [error] Not recognized as IP address: "\"foobar"
 string(7) "1.1.1.1"
 
 x_forwarded: for="8.8.8.8:2222",
@@ -191,8 +191,8 @@ fastly_client_ip: 2.2.2.2
 string(7) "2.2.2.2"
 
 fastly_client_ip: 2.2.2.2, 3.3.3.3
-Not recognized as IP address: "2.2.2.2, 3.3.3.3"
-Not recognized as IP address: "2.2.2.2, 3.3.3.3"
+[ddtrace] [error] Not recognized as IP address: "2.2.2.2, 3.3.3.3"
+[ddtrace] [error] Not recognized as IP address: "2.2.2.2, 3.3.3.3"
 NULL
 
 fastly_client_ip: 127.0.0.1
@@ -226,8 +226,8 @@ cf_connecting_ip: 2.2.2.2
 string(7) "2.2.2.2"
 
 cf_connecting_ip: 2.2.2.2, 3.3.3.3
-Not recognized as IP address: "2.2.2.2, 3.3.3.3"
-Not recognized as IP address: "2.2.2.2, 3.3.3.3"
+[ddtrace] [error] Not recognized as IP address: "2.2.2.2, 3.3.3.3"
+[ddtrace] [error] Not recognized as IP address: "2.2.2.2, 3.3.3.3"
 NULL
 
 cf_connecting_ip: 127.0.0.1

tests/ext/flush-autofinish.phpt

@@ -16,7 +16,7 @@ var_dump(DDTrace\active_span() != null);
 
 ?>
 --EXPECTF--
-Flushing trace of size 2 to send-queue for %s
+[ddtrace] [info] Flushing trace of size 2 to send-queue for %s
 bool(true)
 bool(true)
-Flushing trace of size 1 to send-queue for %s
+[ddtrace] [info] Flushing trace of size 1 to send-queue for %s

tests/ext/force_flush_traces.phpt

@@ -42,6 +42,6 @@ var_dump(dd_trace_serialize_closed_spans()); // Spans should be flushed, so this
 --EXPECTF--
 tracing process
 process
-Flushing trace of size 3 to send-queue for %s
+[ddtrace] [info] Flushing trace of size 3 to send-queue for %s
 kill
 %r\n*(Killed\n*)?(Termsig=9)?%r

tests/ext/includes/fake_tracer.inc

@@ -36,7 +36,7 @@ class Tracer
         }, dd_trace_serialize_closed_spans());
 
         // Reporting
-        $output = 'Flushing tracer...' . PHP_EOL;
+        $output = '[ddtrace] [info] Flushing tracer...' . PHP_EOL;
         foreach ($valuesStrings as $value) {
             $output .= $value;
         }

tests/ext/includes/fake_tracer_exception.inc

@@ -6,7 +6,7 @@ class Tracer
 {
     public function flush()
     {
-        echo 'Flushing tracer with exception...' . PHP_EOL;
+        echo '[ddtrace] [info] Flushing tracer with exception...' . PHP_EOL;
         throw new \Exception('You should not see this');
     }
 

tests/ext/integrations/curl/distributed_tracing_curl.phpt

@@ -54,7 +54,7 @@ echo 'Done.' . PHP_EOL;
 
 ?>
 --EXPECTF--
-The to be propagated tag '_dd.p.very=looooooooooooooooong' is too long and exceeds the maximum limit of 25 characters and is thus dropped.
+[ddtrace] [error] The to be propagated tag '_dd.p.very=looooooooooooooooong' is too long and exceeds the maximum limit of 25 characters and is thus dropped.
 b3: %s-%s-1
 traceparent: 00-%s-%s
 tracestate: dd=o:phpt-test
@@ -69,4 +69,4 @@ bool(true)
 bool(true)
 string(15) "inject_max_size"
 Done.
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/integrations/curl/distributed_tracing_curl_copy_handle.phpt

@@ -96,4 +96,4 @@ x-datadog-trace-id: %d
 x-foo: after-the-copy
 
 Done.
-Flushing trace of size 5 to send-queue for %s
+[ddtrace] [info] Flushing trace of size 5 to send-queue for %s

tests/ext/integrations/curl/distributed_tracing_curl_drop_dm.phpt

@@ -50,4 +50,4 @@ x-datadog-tags: _dd.p.tid=0000001234567890,_dd.p.usr.id=baz64==,_dd.p.url=http:/
 x-datadog-trace-id: 8687463697196027922
 bool(false)
 Done.
-No finished traces to be sent to the agent
+[ddtrace] [info] No finished traces to be sent to the agent

tests/ext/integrations/curl/distributed_tracing_curl_existing_headers_001.phpt

@@ -66,4 +66,4 @@ x-mas: tree
 x-my-custom-header: foo
 
 Done.
-Flushing trace of size 3 to send-queue for %s
+[ddtrace] [info] Flushing trace of size 3 to send-queue for %s