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.