Skip to content

Parent Trace ID not always correctly propagated to Laravel Workers #819

Open
@nwilliams-lw

Description

@nwilliams-lw

Description

When using Laravel queues with a redis driver, we expect that the jobs in the worker consumers
should have the same trace id as the launching transaction. In practice we see that the jobs
sometimes do not have the correct IDs resulting in the distributed trace not being complete in the NR UI.

In our production system we have a web handler that launches ~8 jobs to be processed by the workers,
often a couple of the jobs have the wrong trace ids. On average I'd say it happens to roughly half the jobs launched.

Steps to Reproduce

  1. Create a laravel setup with worker instance using a redis QUEUE_DRIVER.
  2. Publish jobs to the queue
  3. Check the trace id in the job's hander

Example code:
Web handler launching jobs:

    for ($x = 0; $x <= 10; $x++) {
      TracePrintingQueue::dispatch()->onQueue('default');
    }

Worker:

class TracePrintingQueue implements ShouldQueue
{
    use Dispatchable;
    use InteractsWithQueue;
    use Queueable;
    use SerializesModels;

    public function handle(): void
    {
        $meta = newrelic_get_trace_metadata();
        $stdout = fopen('php://stdout', 'w');
        fwrite(\STDOUT, "Job Trace ID:" . $meta['trace_id'] . "\n");
    }
}

Expected Behavior

Jobs handled asynchronously in the workers should appear under the parent trace within new relic UI.

Relevant Logs / Console output

From the above sample code we see the output:

demo-php-1                    | Web Trace ID:995aaee9a2d0d3e2
demo-worker-1                 |   2024-01-25 12:05:53 App\Http\Controllers\TracePrintingQueue ........ RUNNING
demo-worker-1                 | Child Trace ID:bb1c352842d98655517b6aecec99d847
demo-worker-1                 |   2024-01-25 12:05:53 App\Http\Controllers\TracePrintingQueue .... 5.59ms DONE
demo-worker-1                 |   2024-01-25 12:05:53 App\Http\Controllers\TracePrintingQueue ........ RUNNING
demo-worker-1                 | Child Trace ID:d5d8c2822918713a
demo-worker-1                 |   2024-01-25 12:05:53 App\Http\Controllers\TracePrintingQueue .... 3.13ms DONE
etc..

Note that the TraceIDs here are different lengths too which is odd.

Your Environment

Seen locally on mac m1 and linux alpine.
php 8.3
newrelic agent: 10.13.0.2 (is an issue on earlier versions too)

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions