Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[11.x] Add --json flag to queue:work command for structured logging #52887

Merged

Conversation

josecl
Copy link
Contributor

@josecl josecl commented Sep 23, 2024

This PR introduces a new --json flag for the queue:work command, enabling structured JSON output for enhanced observability.

Motivation

  • Improves monitoring capabilities in cloud and Kubernetes environments without disrupting existing functionality.
  • Provides contextual information about job execution, facilitating processing by log analysis tools.
  • Standardizes log format, enabling community sharing of tooling (e.g., Grafana Loki dashboards).
  • Aligns with recent JSON support additions to other Artisan commands.
  • I’m ready to create a test if this PR is approved.

Why not?

  • Introduces changes to a core command. My sense of smell tells me that I am proposing changes in a place where unnecessary changes are not welcome.
  • Similar functionality could be achieved using custom queue event listeners and logging with Monolog\Formatter\JsonFormatter.

JSON output format

The JSON output continues to include two log entries per job: one at the start and another at completion.

Key fields include:

  • timestamp: Datetime in ISO 8601 format.
  • level: PSR-3 log level info or warning. It helps monitoring tools.
  • status: Current execution status of queue:work command: starting, success, released_after_exception or failed.
  • result: Outcome of completed jobs: deleted, released or failed.
  • duration: In seconds.
  • exception: FQCN of the Exception.
  • message: Exception message.

Sucessful Job

{
  "timestamp": "2024-09-23T13:47:37.347077+00:00",
  "level": "info",
  "job": "App\\Jobs\\NotificarJob",
  "id": "9af01732-609a-4418-86f3-904f928fd8cc",
  "uuid": "88098a41-4a1e-4ea6-a4f0-58511f91e915",
  "connection": "rabbitmq",
  "queue": "default",
  "status": "success",
  "result": "deleted",
  "attempts": 1,
  "duration": 0.014354
}

Failed Job

{
  "timestamp": "2024-09-23T13:44:57.393616+00:00",
  "level": "warning",
  "job": "App\\Jobs\\TestJob",
  "id": "12c2916c-6a04-40d7-b0d8-c48897c425a0",
  "uuid": "7e719912-f6c2-4018-a1c2-c7254992f182",
  "connection": "rabbitmq",
  "queue": "default",
  "status": "failed",
  "result": "deleted",
  "attempts": 3,
  "exception": "App\\Exceptions\\TestException",
  "message": "I have failed you.",
  "duration": 0.001601
}

Job Starting

{
  "timestamp": "2024-09-23T13:48:37.593466+00:00",
  "level": "info",
  "job": "App\\Jobs\\ConsultarEnvioDocumentoAReguladorJob",
  "id": "e600e9dd-474b-4e18-ad5e-a3cadd3b04c9",
  "uuid": "e76cd7c8-1754-48e7-9b45-5a7ea8664d53",
  "connection": "rabbitmq",
  "queue": "regulador",
  "status": "starting",
  "attempts": 2
}

Open Questions

  • Is the "Job Starting" log entry necessary, or should we only log job completion?
  • Should we use the -v argument to control the verbosity of the JSON output?
  • Are there any additional fields that would be valuable to include in the JSON output?

@josecl
Copy link
Contributor Author

josecl commented Sep 25, 2024

Proposed Improvements

Would you like me to update the PR with these suggestions?

1. Introduce JSON_PRETTY_PRINT Option

Currently, the JSON log is correctly formatted as a single line. However, for improved readability, I propose adding an option to use JSON_PRETTY_PRINT when APP_DEBUG=true.

2. Include Log Contextual Information

I suggest incorporating the logger's contextual information. This will allow users to add custom information and reduce the need for future pull requests. The feature should be configurable as an opt-in option in the queue.php config file, maybe accepting either a boolean flag or a specific channel name for flexibility.

Example:

{
    "level": "info",
    "id": "44d41635-8f54-4fa0-b121-03408624176c",
    "uuid": "c1a054e8-f0aa-4220-b325-78843135e621",
    "connection": "rabbitmq",
    "queue": "contraparte",
    "job": "App\\Jobs\\EnviarDocumentoAContraparteJob",
    "status": "success",
    "result": "released",
    "attempts": 2,
    "context": {
        "documento_id": "01j8kzztykzxqmmmccqc146jnm",
        "institucion_id": 1,
        "action": "App\\Actions\\FirmarXmlAction"
    },
    "timestamp": "2024-09-25T07:09:44.223718+00:00",
    "duration": 0.343553
}

To implement this, I believe we will need to add a context() method to the Illuminate\Log\Logger class:

public function context(): array
{
    return $this->context;
}

@josecl
Copy link
Contributor Author

josecl commented Sep 25, 2024

3. Add Exception to JobReleasedAfterException event

When a Job finishes with released_after_exception status, there's no Exception context. I propose adding a third parameter to the event's constructor, similar to JobFailed.

Is this a potential breaking change? The JobReleasedAfterException event is only dispatched in Illuminate\Queue\Worker. To avoid potential breaking changes, we could make it null by default.

@taylorotwell taylorotwell merged commit 2599bc4 into laravel:11.x Oct 8, 2024
31 checks passed
@aromka
Copy link

aromka commented Oct 8, 2024

This throws errors when running php artisan horizon.

The "json" option does not exist.

The "json" option does not exist. {"exception":"[object] (Symfony\\Component\\Console\\Exception\\InvalidArgumentException(code: 0): The \"json\" option does not exist. at /vendor/symfony/console/Input/Input.php:127)

Also reported in #53071

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants