Kovah's avatar
Level 5

Shared Log context is removed from logs coming from jobs running in queues / Horizon

Hi, I recently added a global shared log context to my Laravel application. As suggested in the docs, I have put it into my AppServiceProvider:

Log::shareContext(['trace_id' => (string) Str::ulid()]);

When logs are written by, for example, a controller or a helper library, the context is correctly added to the logs. However, when logs are written by a job that runs inside Laravel Horizon, the log context is removed. I manually have to add the context again.

[2024-01-05 13:18:54] local.DEBUG: Logging Test in command {"trace_id":"01HKCWDM76BHAH7BXFT3DH3C1K","type":"debugging"} 
[2024-01-05 13:18:54] local.DEBUG: Logging Test in command with manual Trace ID {"trace_id":"01HKCWDM9S7X34GK4S3JGMW8GE","type":"debugging"} 
[2024-01-05 13:18:56] local.DEBUG: Logging Test in job {"type":"debugging"} 
[2024-01-05 13:18:56] local.DEBUG: Logging Test in job with manual Trace ID {"trace_id":"01HKCWDM9S7X34GK4S3JGMW8GE","type":"debugging"} 

The third entry should have a a trace ID set, but it obviously doesn't have one. Does anyone why this happens and how to fix it? It's not about the trace ID being passed from the command to the job. I would expect that a job that is being started uses the same application logic than everything else, meaning it goes through the AppServiceProvider and set's up the log context. My assumption is that somewhere™️ in Horizon the log context is overridden / cleared.

Edit: I added a custom config variable to the app service provider: Config::set('logging.debug_type', 'debugging') just to make sure that jobs in Horizon really to through the app service provider. And they do. The logs contain the config value as expected. It's not set anywhere else.

Edit 2: Actually, this is not an issue caused by Horizon, but by Laravel's queues itself. I've updated the repo to also take into account the php artisan queue:work command.

I have created a clean repo for anyone to test this: https://github.com/Kovah/Horizon-Log-Context-Test

0 likes
3 replies
martinbean's avatar

@kovah Did you restart your Horizon processes after adding the line to your service provider?

Kovah's avatar
Level 5

@martinbean Yes. Actually, I have created the test repo where this issue can be replicated after I encountered it first in my app. Restarting does nothing.

rodrigo.pedra's avatar
Level 56

Hey @kovah I just replied to the GitHub issue.

The queue worker reset the logger shared context before each loop, in other words, before each job.

See: https://github.com/laravel/framework/blob/ab9f7c4cf563be95f6e9046bce4a92801627b282/src/Illuminate/Queue/QueueServiceProvider.php#L201-L203

This behavior was introduced 3 years ago in PR #37865, and there is no info about the reasoning.

One workaround is to add a listener to the Illuminate\Queue\Events\JobProcessing event, and also share the context from that listener.

1 like

Please or to participate in this conversation.