[BUG] Undefined property: DDTrace\\SpanData::$id when combining accessing active span from user-land after calling \DDTrace\hook_method on dd-trace-php 0.70+

[olsavmic]

Bug description

Hi, after upgrading to DDTrace 0.70+ (0.71 behaves similarly), we're having issues with following setup:

We have a custom pre-hook registered that accesses the root span. The span is a regular Span instance, not a NoopSpan.
This hook works perfectly when it's not combined with user-land spans.

hook_method(
            HttpKernel::class,
            'handleRaw',
            null, // pre-hook
            function ($instance, $scope, $args, $response): void {
                $tracer = GlobalTracer::get();
                $rootSpan = $tracer->getSafeRootSpan();
            },
        );

The issue occurs when calling GlobalTracer::get()->getActiveSpan() from the app itself. We do not manipulate with the retrieved span any further in any of the methods.

The code fails during ScopeManager::reconcileInternalAndUserland() on following lines:

        for ($span = active_span(); $span->id != $currentSpanId; $span = $span->parent) {
   -->         $scope = new Scope($this, new Span($span, new SpanContext(trace_id(), $span->id, $span->parent->id)), true);
            $newScopes[] = $scope;
        }

($span->parent->id is uninitialized on line 866)

When dumping $span->parent, we can see that
$span->parent is instance of SpanData but all fields are uninitialised.

/opt/datadog-php/dd-trace-sources/bridge/_generated_tracer.php:867:
object(DDTrace\SpanData)[2189]
  public 'name' => string 'symfony.kernel.request' (length=22)
  public 'resource' => string 'symfony.kernel.request' (length=22)
  public 'service' => string 'testing-71' (length=10)
  public 'type' => *uninitialized*
  public 'meta' => 
    array (size=1)
      'env' => string 'olsavmic' (length=8)
  public 'metrics' => 
    array (size=0)
      empty
  public 'exception' => *uninitialized*
  public 'parent' => 
    object(DDTrace\SpanData)[2191]
      public 'name' => *uninitialized*
      public 'resource' => *uninitialized*
      public 'service' => *uninitialized*
      public 'type' => *uninitialized*
      public 'meta' => 
        array (size=0)
          empty
      public 'metrics' => 
        array (size=0)
          empty
      public 'exception' => *uninitialized*
      public 'parent' => *uninitialized*
      public 'id' => *uninitialized*
  public 'id' => string '5290821481255565971' (length=19)

Calling GlobalTracer::get()->getActiveSpan() alone without registering the hook works fine.
We see same behaviour both with and without DD_TRACE_GENERATE_ROOT_SPAN option.

PHP version

PHP 8.1.4 (cli) (built: Mar 20 2022 16:51:10) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.1.4, Copyright (c) Zend Technologies
    with Zend OPcache v8.1.4, Copyright (c), by Zend Technologies
    with blackfire v1.75.0~linux-x64-non_zts81, https://blackfire.io, by Blackfire
    with ddtrace v0.71.0, Copyright Datadog, by Datadog

Tracer version

0.71.0

Installed extensions

[PHP Modules]
bcmath
blackfire
calendar
Core
ctype
curl
date
ddtrace
dom
exif
FFI
fileinfo
filter
ftp
gettext
hash
iconv
igbinary
imagick
imap
intl
json
libxml
mbstring
mysqli
mysqlnd
openssl
pcntl
pcre
PDO
pdo_mysql
Phar
posix
readline
Reflection
session
shmop
SimpleXML
soap
sockets
sodium
SPL
standard
sysvmsg
sysvsem
sysvshm
tokenizer
xml
xmlreader
xmlwriter
xsl
Zend OPcache
zip
zlib

[Zend Modules]
Zend OPcache
blackfire
ddtrace

OS info

PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster

Diagnostics and configuration

Output of phpinfo() (ddtrace >= 0.47.0)

{"date":"2022-03-21T14:27:48Z","os_name":"Linux f2f9e7dc8456 5.10.104-linuxkit #1 SMP Wed Mar 9 19:05:23 UTC 2022 x86_64","os_version":"5.10.104-linuxkit","version":"0.71.0","lang":"php","lang_version":"8.1.4","env":"olsavmic","enabled":true,"service":"testing-71","enabled_cli":true,"agent_url":"http:\/\/datadog:8126","debug":true,"analytics_enabled":false,"sample_rate":1,"sampling_rules":[],"tags":[],"service_mapping":[],"distributed_tracing_enabled":true,"priority_sampling_enabled":true,"dd_version":null,"architecture":"x86_64","sapi":"fpm-fcgi","datadog.trace.request_init_hook":"\/opt\/datadog-php\/dd-trace-sources\/bridge\/dd_wrap_autoloader.php","open_basedir_configured":false,"uri_fragment_regex":null,"uri_mapping_incoming":null,"uri_mapping_outgoing":null,"auto_flush_enabled":false,"generate_root_span":true,"http_client_split_by_domain":false,"measure_compile_time":true,"report_hostname_on_root_span":false,"traced_internal_functions":null,"auto_prepend_file_configured":false,"integrations_disabled":"default","enabled_from_env":true,"opcache.file_cache":null}

Diagnostic checks | passed

Upgrading info

DDTrace 0.69.0 -> DDTrace 0.70.0, DDTrace 0.71.0 (both versions do not work)

[krakjoe]

I'm not able to reproduce this specific behaviour, while I can reproduce behaviour that looks like it.

I wonder if you might be able to reduce the problem to its simplest form and provide a complete reproducing test case (of the kind we might be able to add to our test suites) ?

[olsavmic]

@krakjoe Thanks for quick response!

I created a repository demonstrating the issue (https://github.com/olsavmic/dd-trace-bug-1544).

After further investigation, I was able to replicate the issue only in combination with SymfonyIntegration.

I found out that when we're trying to hook onto HttpKernel::handleRaw (https://github.com/olsavmic/dd-trace-bug-1544/blob/master/public/index.php) reported error happens. DDTrace SymfonyIntegration does not hook onto this method though, only onto HttpKernel::handle.

The issue is not present in case hook_method is replaced with trace_method (but this is not something we want to do).

Also, as reported, commenting out the line GlobalTracer::get()->getActiveSpan() in https://github.com/olsavmic/dd-trace-bug-1544/blob/master/src/Kernel.php fixes the issue.

---

Debugging question
I was not able to get echo/die/throw expressions working in trace_method/hook_method with original php docker image, even when setting DD_TRACE_DEBUG=true. No messages were printed from these trace callbacks although other debug messages showed just fine.

I therefore used your PHP image from https://github.com/DataDog/dd-trace-php/blob/master/CONTRIBUTING.md with which I had no issues. I also found out that installing completely unrelated blackfire extension fixes this behaviour - all messages from trace callbacks were visible. All default PHP settings including opcache were matching.

Could you please explain to me what has to be changed in order to print messages from these "sandboxed" functions? I'm really curious as it took me quite some time to find out that my code is fine, it's just some PHP configuration. Does it have something to do with DEBUG build of PHP?

Thank you!

[bwoebi]

Hey there,

we have identified a minor behaviour change in PHP 8.1.4 which is incompatible with dd-trace-php. There is a fix in #1550, but until it is released dd-trace-php does not work properly with PHP 8.1.4.

Especially considering this:

I also found out that installing completely unrelated blackfire extension fixes this behaviour - all messages from trace callbacks were visible.

This strongly indicates that your encountered bug is related to that. Downgrading to PHP 8.1.3 for now also should fix it then.

Can you also confirm whether your reported memory leak in #1545 is related to that issue? I.e. disappears with PHP 8.1.3? Or whether that's an actually separate issue.

[bwoebi]

Regarding your debugging question: using DD_TRACE_DEBUG should work. The problem was though that due to this bug the tracing functionality was nearly completely disabled and thus your output not working.

[olsavmic]

@bwoebi Thank you for the hint!

Unfortunately while downgrading to PHP 8.1.3 fixes the issue with debugging messages not showing up while trying to reproduce the error, it does not fix the main problem mentioned in this issue. We are still seeing the same Warning: Undefined property: DDTrace\SpanData::$id exception.

We actually tried the upgrade the other way around back then - we first deployed dd-trace-php 0.71.0 on PHP 8.1.3 and seeing that it does not work, we tried it one more time after 8.1.4 was released. :/

[labbati]

@olsavmic can you explain what you are trying to achieve. We want to investigate the bug that you found, but we might also recommend the best way to achieve what you want to achieve.

For example the root span can be retrieved via \DDTrace\root_span() and be used with our modern api (rather than the legacy open tracing-inspired one).

Let me drop here a sort of API documentation that you might find useful, as we are revamping our docs with it.

\DDTrace\active_span(): gets you the current active span.
\DDTrace\root_span(): gets you the root span.
\DDTrace\current_context(): gets you the current context (e.g. for log injection or manual distributed tracing). the returned value is an array with keys trace_id, span_id plus other info that are typically not useful to users.

The returned span objects, have the following properties that can be written.

$span->name: [string] the name of the span.
$span->service: [string] although is already populated for you.
$span->resource: [string] the resource of the span (or of the trace if this is the root span).
$span->type: [string] the type. One of these values https://github.com/DataDog/dd-trace-php/blob/master/src/api/Type.php or custom if none of them apply.
$span->meta: [array] the span's tags. Never do $span->meta = ['key' => 'value'] because you would clear existing tags. Always add tags doing $span->meta['key'] = 'value'.
$span->metrics: [array] the span's metrics (numbers). Never do $span->metrics = ['key' => 123] because you would clear existing metrics. Always add metics doing $span->meta['key'] = 123.

[olsavmic]

@labbati We have several different custom instrumentation layers in our application:

1. Log augmentation with some tracing data
2. Augmenting traces with some context data using hook_method
3. Tracing a few specific methods using trace_method
4. Tracing callbacks eg. method calls only from specific callers.5.

$this->tracingService->traceCallback('initializeNextStops', function () use ($conveyor, $transaction): void {
    $this->initializeNextStops($conveyor, $transaction);
});

 $this->tracingService->traceConsumer(static::getConsumerName(), function () use ($msg): void {
      $parsedMessage = $this->messageParser->parseMessage($msg, static::getExpectedMessageClass());
      $this->processMessage($parsedMessage);
  });

1, 2, 3 can be easily rewritten to the modern API. I'm not sure about the 4th case though where we handle the full lifecycle of a span (start, finish, flush).

[bwoebi]

The fix for this is included in the now released 0.72.0.