A single trigger_error() call gets reported multiple times with auto instrumentation

[kisprof]

Describe the bug
A single trigger_error() call gets reported multiple times to the APM server if autoinstrumentation is enabled.
To Reproduce
Steps to reproduce the behavior:
Following code snippet will report 13 number of user deprecated errors to the server.

• PHP:
  • Version: 8.3.10, 8.2.11 (could reproduce with both)
  • OS: Alpine Linux v3.20.2, Ubuntu 22.04.3 LTS (could reproduce with both)
  • Code

    <?php
    
    $pdo = new PDO("mysql:host=db;dbname=trigger_test", 'root', 'root');
    error_reporting(E_ALL);
    ini_set('display_errors', 1);
    trigger_error('Test', E_USER_DEPRECATED);
    
    for ($i = 0; $i < 3; $i++) {
        $random = random_int(1, 1000000);
        $statement = $pdo->prepare("insert into trigger_test (data) values (?)");
        $statement->execute([$random]);
    }
    
    echo "trigger_test";
    

  • Dockerfile:

    FROM php:8.3-fpm-alpine
    
    ADD --chmod=0755 https://github.com/mlocati/docker-php-extension-installer/releases/latest/download/install-php-extensions /usr/local/bin/
    
    RUN install-php-extensions pdo_mysql
    
    ADD --chmod=0755 https://github.com/elastic/apm-agent-php/releases/download/v1.13.0/apm-agent-php_1.13.0_x86_64.apk /root
    RUN apk add --allow-untrusted /root/apm-agent-php_1.13.0_x86_64.apk
    
    COPY . /var/www/html
    

• APM
  • Agent version: 1.13.0
  • Agent config:

    [elastic]
    elastic_apm.enabled = true
    elastic_apm.secret_token = "{{REPLACE_ME}}"
    elastic_apm.server_url = "{{REPLACE_ME}}"
    elastic_apm.environment = "local"
    elastic_apm.log_level = "DEBUG"
    elastic_apm.log_level_stderr = "DEBUG"
    elastic_apm.server_timeout = "30s"
    elastic_apm.service_name = "trigger_test"
    elastic_apm.service_version = "v1"
    elastic_apm.transaction_max_spans = 500
    elastic_apm.transaction_sample_rate = 1.0
    elastic_apm.verify_server_cert = true
    elastic_apm.dev_internal_backend_comm_log_verbose = true
    elastic_apm.profiling_inferred_spans_enabled = true
    

  • Results in kibana:
    
• Notes:
  • Based on a quick investigation what I can see is that \elastic_apm_get_last_php_error() will return the last triggered error every time in PhpPartFacade::ensureHaveLastPhpError() called through both internalFuncCallPreHook() and internalFuncCallPostHook(). This creates 2 error event on every autoinstrument captured call. This results in a total of 13 errors (1 original on the trigger, 2 on $pdo->prepare() and 2 on $statement->execute() executed 3 times in the for cycle for a total of 12 [3 * 2 * 2])
    
    

Expected behavior
Auto instrumented calls should not report earlier triggered errors. So in above scenario I would like to only see 1 error event.

[intuibase]

Hey @kisprof

Thank you for bug report. I tried to reproduce it but I failed - app quits on PDO constructor with uncaught exception.
I got only one error:

Could you please review your app and settings and try again (or should I create DB)?

[kisprof]

Hi @intuibase

Yep a DB is needed for the test. Sorry my original ticket description is not that "plug and play".

Here is the same example with a full docker compose setup:

• Files:

  • ./src/test.php

    <?php
    
    $pdo = new PDO("mysql:host=db;dbname=trigger_test", 'root', 'root');
    error_reporting(E_ALL);
    ini_set('display_errors', 1);
    trigger_error('Test', E_USER_DEPRECATED);
    
    for ($i = 0; $i < 3; $i++) {
        $random = random_int(1, 1000000);
        $statement = $pdo->prepare("insert into trigger_test (data) values (?)");
        $statement->execute([$random]);
    }
    
    echo "trigger_test";
    

  • ./99-elastic-apm-custom.ini

    [elastic]
    elastic_apm.enabled = true
    elastic_apm.secret_token = "{{REPLACE_ME}}"
    elastic_apm.server_url = "{{REPLACE_ME}}"
    elastic_apm.environment = "local"
    elastic_apm.log_level = "DEBUG"
    elastic_apm.log_level_stderr = "DEBUG"
    elastic_apm.server_timeout = "30s"
    elastic_apm.service_name = "trigger_test"
    elastic_apm.service_version = "v1"
    elastic_apm.transaction_max_spans = 500
    elastic_apm.transaction_sample_rate = 1.0
    elastic_apm.verify_server_cert = true
    elastic_apm.dev_internal_backend_comm_log_verbose = true
    elastic_apm.profiling_inferred_spans_enabled = true
    

  • ./docker-compose.yml

    name: trigger_test
    services:
        db:
            image: mysql
            ports:
                - '3306:3306'
            volumes:
                - { type: volume, target: /var/lib/mysql, source: db-data }
                - "./init.sql:/docker-entrypoint-initdb.d/1.sql"
            environment:
                MYSQL_ROOT_PASSWORD: root
        trigger_test:
            build:
                context: "."
            volumes:
                - "./src:/root/src"
                - "./99-elastic-apm-custom.ini:/usr/local/etc/php/conf.d/99-elastic-apm-custom.ini"
            tty: true
            stdin_open: true
    volumes:
      db-data: null
    

  • ./Dockerfile

    FROM php:8.3-cli-alpine
    
    ADD --chmod=0755 https://github.com/mlocati/docker-php-extension-installer/releases/latest/download/install-php-extensions /usr/local/bin/
    
    RUN install-php-extensions pdo_mysql
    
    ADD --chmod=0755 https://github.com/elastic/apm-agent-php/releases/download/v1.13.0/apm-agent-php_1.13.0_x86_64.apk /root
    RUN apk add --allow-untrusted /root/apm-agent-php_1.13.0_x86_64.apk
    
    COPY ./src /root/src
    WORKDIR /root/src
    

  • ./init.sql

    CREATE SCHEMA trigger_test;
    CREATE TABLE trigger_test.trigger_test
    (
     id INT AUTO_INCREMENT PRIMARY KEY,
     data VARCHAR(255) NULL
    );
    

• Steps:
  • docker compose up -d
  • docker compose exec trigger_test /bin/sh
  • php test.php

[intuibase]

Thank you for reproduction - it works for me, I'll do my best to fix it.