[opentelemetry-php-instrumentation] unable to hook functions that have already executed

[iamacarpet]

Describe your environment

PHP 8.3.0
OpenTelemetry extension 1.0.0

Docker imaged based on gcr.io/gae-runtimes/buildpacks/php83/run:latest

Steps to reproduce

use function OpenTelemetry\Instrumentation\hook;

echo "<pre>\n";

class Demo {
    public function hello() {
        echo "public\n\n";
    }

    public function world() {
        return $this->wor();
    }

    private function wor() {
        echo "private 123\n\n";
    }
}

$d = new Demo();
$d->world();
$d->hello();

hook(
    Demo::class,
    'hello',
    pre: static function (Demo $client, array $params, string $class, string $function, ?string $filename, ?int $lineno): void {
        echo $function . "\n\n";
    },
);

hook(
    Demo::class,
    'wor',
    pre: static function (Demo $client, array $params, string $class, string $function, ?string $filename, ?int $lineno): void {
        echo $function . "\n\n";
    },
);

$d = new Demo();
$d->world();
$d->hello();

What is the expected behavior?

I expect that the hooks should run the second time those functions are called (after the hooks are registered).

What is the actual behavior?

The hooks never run, or more specifically, the closure specified as pre never runs.

If however, you comment out the execution before you register the hooks, i.e.:

use function OpenTelemetry\Instrumentation\hook;

echo "<pre>\n";

class Demo {
    public function hello() {
        echo "public\n\n";
    }

    public function world() {
        return $this->wor();
    }

    private function wor() {
        echo "private 123\n\n";
    }
}

/* $d = new Demo();
$d->world();
$d->hello(); */

hook(
    Demo::class,
    'hello',
    pre: static function (Demo $client, array $params, string $class, string $function, ?string $filename, ?int $lineno): void {
        echo $function . "\n\n";
    },
);

hook(
    Demo::class,
    'wor',
    pre: static function (Demo $client, array $params, string $class, string $function, ?string $filename, ?int $lineno): void {
        echo $function . "\n\n";
    },
);

$d = new Demo();
$d->world();
$d->hello();

then the hooks run as expected.

So to clarify, if you try to register a hook for a function that has already been executed during the current request - it doesn't appear that those hooks will ever run.

Additional context

I stumbled upon this while trying to get instrumentation working for Guzzle - no matter what I tried, I couldn't hook the correct function (GuzzleHttp\Client::transfer), nor many of the surrounding functions or even classes, like HandlerStack: it was driving me crazy, initially thinking it was optimiser inlining, something to do with the JIT, or that you couldn't trace private or protected functions - although all of those assumptions turned out to be false.

After much testing, I discovered the problem as described above.

I was hitting this due to Guzzle being used VERY early in the request, due to metadata & authentication tokens being loaded from the metadata server (on GCP) before the instrumentation hooks were being registered.

Now this may not be something you can fix, as it may well be something inherent to the underlying zend_observer implementation, however, it may be useful to document it alongside the warning about function inlining, in case someone else runs across the same problem.

[brettmc]

I'm pretty sure that's just how zend observer works. In all of the auto-instrumentation packages we provide, hooks are registered as part of composer autoloading (via autoload->files in composer.json), and then assume that calling vendor/autoload.php is the first thing that an application does. AFAIK there's no way to influence the order that those files are run in (if your problem is that another autoloaded file is calling guzzle before the hooks are registered).

I think documentation is the answer here (and if the suggestion above is helpful, maybe that can be better documented, too).

[iamacarpet]

Thanks for the reply @brettmc ,

AFAIK there's no way to influence the order that those files are run in (if your problem is that another autoloaded file is calling guzzle before the hooks are registered).

Yes, exactly this - although I had other problems with the auto instrumentation, in that when running on the CLI locally without the opentelemetry extension installed, it was throwing fatal errors; our Laravel package is to allow an app to run on Google's serverless environment and seemlessly enable all the extra observability, by detecting when running in that environment at runtime & only enabling the features there.

I've rolled all the instrumentation into our Laravel package itself & changed the order everything is loaded, which seems to be working great.

If the documentation could be updated to help make this more clear, that would be ideal please.

[bobstrecansky]

@iamacarpet - what sort of documentation would have helped you in this particular situation now that you understand it better?

[iamacarpet]

Thanks @bobstrecansky ,

In the extension repository, it already includes the following under “Usage”:

Warning Be aware that trivial functions are candidates for optimizations. Optimizer can optimize them out and replace user function call with more optimal set of instructions (inlining). In this case hooks will not be invoked as there will be no function.

I feel a similar warning, to say something like:

Warning: Be aware when registering a hook that functions can only be registered to be traced if they haven’t already been called in the current runtime context.

I’m not sure of the exact wording, but something to that effect would have been helpful.