elastic / elastic/apm-agent-php

Queued async events appear to be lost on normal CLI process exit

Open
#1,450 0 comments 0 reactions 0 assignees View on GitHub
agent-php bug
Dominant language
PHP
Stars
268
Forks
86
PR merge metrics
No merged PRs in 30d

Description

# Queued async events appear to be lost on normal CLI process exit

## Summary

When a CLI process exits normally with `async_backend_comm = true`, some events that are still queued in the background sender appear not to arrive at APM Server after the process ends.

I reproduced this on Linux with agent version `v1.16.0`. The script reaches the end normally and exits with code `0`.

This report is about the normal-exit loss path specifically. In the runs behind this report, I do not see queue-overflow errors explaining the missing data.

## Version Scope

- My original reproduction is on `v1.16.0`
- I have not yet retested this exact scenario on the latest `1.16.x`

## Environment

- PHP 7.3
- Elastic APM PHP agent `v1.16.0`
- CLI SAPI
- Linux
- `async_backend_comm = true`
- `server_timeout = 120s`

## Reproduction Pattern

The workload is a CLI script that:

1. Loops over many units of work in a single process
2. Creates one APM transaction per iteration
3. Produces roughly 200 to 400 auto-instrumented DB spans per transaction
4. Reaches the end of the script normally and exits with code `0`

This is not a fatal-error, crash, or forced-kill scenario.

## Observed Behavior

- The number of transactions that arrive at APM Server depends on how much the background sender flushes before the script ends.
- Events that are still queued when the process exits do not appear later.
- In the runs behind this report, I do not see queue-overflow errors such as:

```text
Already queued events are above max queue
```

- With `dev_internal_backend_comm_log_verbose = true`, the last backend-comm logs show a request body being uploaded:

```text
CURLINFO_DATA_OUT: [10923 bytes of span data]
CURLINFO_TEXT: upload completely sent off: 10923 out of 10923 bytes
```

- I do not see the corresponding HTTP response afterwards, such as `202 Accepted`.

## Additional Evidence

### 1. DEBUG logs stop at request shutdown

With `log_level_stderr = DEBUG`, the last log line in one run was:

```text
[22:24:57] [Lifecycle] [lifecycle.cpp:615] [elasticApmRequestShutdown] Exiting...
```

After that, I do not see log entries from:

- `elasticApmModuleShutdown`
- `signalBackgroundBackendCommThreadToExit`
- `unwindBackgroundBackendComm`

I do not take that as proof that module shutdown never ran. It only means I do not have positive log evidence that the async shutdown path completed.

### 2. TRACE-level shared-state logs did not show the shutdown flag flipping

In a separate TRACE-level run, the last shared-state snapshot I captured from the background thread still showed `shouldExit: false`.

I do not think that is conclusive by itself, because the sender thread logs snapshots at loop boundaries. If shutdown starts while the thread is blocked in an in-flight HTTP send, the next snapshot may never be logged.

## Why This Looks Unexpected

From reading the source, I expected queued events to keep draining during module shutdown, at least until the queue became empty or the background sender decided its shutdown deadline had expired:

```c
PHP_MSHUTDOWN_FUNCTION(elastic_apm)
-> elasticApmModuleShutdown()
-> backgroundBackendCommOnModuleShutdown()
-> signalBackgroundBackendCommThreadToExit()
-> unwindBackgroundBackendComm()
```

The relevant pieces appear to be:

- `PHP_MSHUTDOWN_FUNCTION(elastic_apm)` calls `elasticApmModuleShutdown()`
- `elasticApmModuleShutdown()` calls `backgroundBackendCommOnModuleShutdown()`
- `signalBackgroundBackendCommThreadToExit()` sets `shouldExit = true`
- it computes `shouldExitBy` from `server_timeout`
- the worker loop keeps running until the queue is empty or the shutdown deadline has passed
- if the shutdown deadline is exceeded with queued data still pending, the worker logs that the remaining events will be dropped

One Linux-specific nuance in `v1.16.0` may matter here:

- `unwindBackgroundBackendComm()` passes the computed deadline into `timedJoinAndDeleteThread()`
- but the Linux implementation uses `pthread_join()` rather than `pthread_timedjoin_np()`

So on Linux `v1.16.0`, `server_timeout` clearly affects the worker's internal shutdown deadline and curl timeout, but it is not a hard timeout for the join helper itself.

## Question

Given the shutdown path above, I would expect queued async events to continue draining during normal CLI module shutdown until the queue becomes empty or the worker reaches its shutdown deadline.

What I am seeing looks like that expected drain path is not completing, or is starting too late to finish, in this normal-exit CLI case.

Is that interpretation correct?

If so, this seems like a shutdown/drain bug or a shutdown-while-POST-is-in-flight bug rather than expected behavior.

## Suggested Investigation

- Retest this exact scenario on the latest `1.16.x`
- Confirm whether `elasticApmApiEntered()` can fail in `PHP_MSHUTDOWN_FUNCTION(elastic_apm)` for this CLI case
- Confirm whether `elasticApmModuleShutdown()` reaches `backgroundBackendCommOnModuleShutdown()`
- Add temporary logs around:
- `PHP_MSHUTDOWN_FUNCTION(elastic_apm)`
- `elasticApmModuleShutdown()`
- `signalBackgroundBackendCommThreadToExit()`
- `unwindBackgroundBackendComm()`
- the return from `timedJoinAndDeleteThread()`
- Correlate those logs with the final verbose curl output to see whether shutdown begins while the sender is still blocked in `curl_easy_perform()`
- Confirm whether the existing async-shutdown timeout warning is emitted anywhere in this reproduction path

## Additional Context

- I can provide a reduced reproduction script if useful
- This report is meant to describe the exit-time loss path specifically, not the separate queue-overflow path that logs `Already queued events are above max queue`

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.