Skip to content

Log stack traces and report exceptions as PSR-3 context (#41068, #41069) - #41070

Open
lbajsarowicz wants to merge 2 commits into
magento:2.4-developfrom
lbajsarowicz:fix/41068-41069-structured-exception-logging
Open

Log stack traces and report exceptions as PSR-3 context (#41068, #41069)#41070
lbajsarowicz wants to merge 2 commits into
magento:2.4-developfrom
lbajsarowicz:fix/41068-41069-structured-exception-logging

Conversation

@lbajsarowicz

Copy link
Copy Markdown
Contributor

Description

Two defects that together make Magento's own logs unusable for diagnosing failures. They have to be fixed in this order, which is why they are in one PR: converting call sites first would lose stack traces under the current formatter.

1. The log formatter discards stack traces (#41068)

Logger\Handler\Base is the only place in app/ or lib/ that constructs a Monolog formatter, and it left includeStacktraces at its default:

$this->setFormatter(new LineFormatter(null, null, true));
//                                     ^ 5th arg $includeStacktraces = false

Consequence: a Throwable passed in the PSR-3 reserved context['exception'] key rendered as its throw site and nothing else —

main.CRITICAL: Order placement failed {"exception":"[object] (RuntimeException(code: 42): Something failed at /app/Foo.php:8)"} []

so the correct PSR-3 call produced less information than stringifying the exception into the message. Reported as #13128 back in 2018; merchants have been carrying composer-patches against this framework file ever since.

This PR enables stack traces on the default formatter and makes the formatter injectable, so a merchant can swap in JsonFormatter (one valid JSON document per record, structured trace, no frame arguments) through di.xml instead of patching core. Documented in lib/internal/Magento/Framework/Logger/README.md.

2. Exception logging in Magento\Framework is not aggregatable (#41069)

26 call sites either stringified the Throwable as the log message ($this->logger->critical($e)Throwable extends Stringable since PHP 8.0, so this silently casts) or logged $e->getMessage() with no context at all.

Both are hostile to observability:

  • The message is the aggregation key, and these calls make it unique per occurrence. $e->getMessage() routinely embeds an entity id (No such entity with customerId = 4711), so 10,000 occurrences of one bug become 10,000 distinct groups in any log pipeline. Nothing crosses an alert threshold.
  • The payload lands in the field nothing reads. With the trace inside message as free text, context — already parsed, already indexed — is empty. Extracting the trace needs a per-version regex maintained by the merchant.
  • getMessage()-only is silent data loss. No class, no code, no file, no line, no trace. And because Logger\Handler\System routes on context['exception'], those records never reach exception.log either.
  • No correlation identifiers. When a consumer fails on 3 of 5,000 messages, nothing in the log says which 3.

Every converted site now uses a constant message template plus structured context, preferring identifiers already in scope in the catch block:

$this->logger->critical(
    'Unable to render the {elementName} layout element',
    ['elementName' => $name, 'exception' => $e]
);

Notes on specific conversions:

  • Webapi\ErrorProcessor::_critical() wrapped the exception in a new \Exception purely to build the log message, which made the wrapper's own location the top trace frame. The original exception is now logged directly, with the report ID in context — the report ID is still returned unchanged.
  • MessageQueue\Consumer gained a $topicName = null initialiser so the topic name is available to the catch block.
  • MessageQueue/Amqp/Stomp topology installers no longer interpolate getTraceAsString() into the message.
  • $e->getTrace() is deliberately not used as a context value anywhere: trace frames carry call arguments, which may contain personal data or credentials. Monolog's normalizer renders context['exception'] as "file:line" frames with no arguments.
  • DB\Adapter\Pdo\Mysql was left alone on purpose — its $logger is Magento\Framework\DB\LoggerInterface, whose critical(\Exception $e) contract is not PSR-3.

Scope is limited to lib/internal/Magento/Framework to keep the diff reviewable. The remaining ~330 app/code sites are listed in #41069 and are proposed as follow-ups grouped by module.

Related Pull Requests

None.

Fixed Issues

  1. Fixes Stack traces are never written to log files: Logger\Handler\Base hardcodes LineFormatter with includeStacktraces = false #41068
  2. Fixes Exception logging is not aggregatable: Throwable stringified as the log message (269 sites) or logged without exception context (87 sites) #41069

Manual testing scenarios

Stack traces are present (#41068)

  1. Install Magento in production mode.
  2. Make an exception reachable — e.g. chmod 000 var/view_preprocessed and open a storefront page, or trigger any handled failure from a converted call site.
  3. tail var/log/exception.log.
  4. Before: the entry ends at the throw site, e.g. {"exception":"[object] (FileSystemException(code: 0): ... at /app/lib/.../Write.php:154)"}.
  5. After: the same entry carries a [stacktrace] block with the full call chain, and the message is a stable template with the identifiers in context.

Formatter is replaceable (#41068)

  1. Add to a module's di.xml:
    <virtualType name="jsonLogFormatter" type="Monolog\Formatter\JsonFormatter">
        <arguments>
            <argument name="includeStacktraces" xsi:type="boolean">true</argument>
        </arguments>
    </virtualType>
    <type name="Magento\Framework\Logger\Handler\System">
        <arguments>
            <argument name="formatter" xsi:type="object">jsonLogFormatter</argument>
        </arguments>
    </type>
  2. bin/magento setup:di:compile && bin/magento cache:flush, trigger an exception.
  3. Each record in var/log/exception.log is one line of valid JSON; context.exception.trace is an array of file:line frames. Confirm with tail -1 var/log/exception.log | php -r 'var_dump(json_decode(fgets(STDIN)) !== null);'.

Aggregatable messages (#41069)

  1. Trigger the same failure twice with different entities — e.g. call getViewFileUrl() for two different missing files.
  2. Before: two different messages, so a log pipeline records two distinct groups.
  3. After: both records share Unable to resolve the URL of the {fileId} view file, and differ only in context.fileId — one group, two samples.

Questions or comments

The default stays LineFormatter so the human-readable log shape is preserved; enabling includeStacktraces does make entries multi-line, which is the trade-off #13128 asked for. Merchants who parse logs should use the JsonFormatter wiring above — happy to promote that to a shipped virtual type or a deployment_config switch if maintainers prefer that over documentation only.

Contribution checklist (*)

  • Pull request has a meaningful description of its purpose
  • All commits are accompanied by meaningful commit messages
  • All new or changed code is covered with unit/integration tests (if applicable)
  • All automated tests passed successfully (all builds are green)

Logger\Handler\Base constructed LineFormatter without includeStacktraces, so a
Throwable passed in the PSR-3 reserved context['exception'] key was rendered as
its throw site alone. The correct PSR-3 call therefore produced less information
than stringifying the exception into the message, which is why 268 call sites do
the latter. Enable stack traces on the default formatter and accept an injected
FormatterInterface, so JsonFormatter can be wired through di.xml instead of
patching the framework.

Convert the exception logging in Magento\Framework to a constant message
template plus structured context, carrying the identifiers already in scope in
the catch block. Stringified exceptions produce a message that is unique per
occurrence and cannot be aggregated, and message-only calls drop the class,
code, file, line and trace entirely, as well as the routing to exception.log
that Handler\System performs on context['exception'].

Webapi\ErrorProcessor no longer wraps the exception to build the log message,
which made the wrapper the top frame of the logged trace; the original exception
is logged instead and the report id moves to the context. DB\Adapter\Pdo\Mysql
is left as is: its logger is Magento\Framework\DB\LoggerInterface, whose
critical(\Exception $e) contract is not PSR-3.

context['exception'] holds the Throwable rather than getTrace(), whose frames
carry call arguments that may contain personal data or credentials.

Fixes magento#41068
Fixes magento#41069
@m2-assistant

m2-assistant Bot commented Jul 29, 2026

Copy link
Copy Markdown

Hi @lbajsarowicz. Thank you for your contribution!
Here are some useful tips on how you can test your changes using Magento test environment.
❗ Automated tests can be triggered manually with an appropriate comment:

  • @magento run all tests - run or re-run all required tests against the PR changes
  • @magento run <test-build(s)> - run or re-run specific test build(s)
    For example: @magento run Unit Tests

<test-build(s)> is a comma-separated list of build names.

Allowed build names are:
  1. Database Compare
  2. Functional Tests CE
  3. Functional Tests EE
  4. Functional Tests B2B
  5. Integration Tests
  6. Magento Health Index
  7. Sample Data Tests CE
  8. Sample Data Tests EE
  9. Sample Data Tests B2B
  10. Static Tests
  11. Unit Tests
  12. WebAPI Tests
  13. Semantic Version Checker

You can find more information about the builds here
ℹ️ Run only required test builds during development. Run all test builds before sending your pull request for review.


For more details, review the Code Contributions documentation.
Join Magento Community Engineering Slack and ask your questions in #github channel.

@lbajsarowicz

Copy link
Copy Markdown
Contributor Author

Local verification, for transparency about what I ran and what I could not:

Green

  • Unit: full lib/internal/Magento/Framework suite — 6726 tests, 0 failures.
  • Unit: the app/code tests that exercise the changed framework methods (Catalog, Payment, Paypal, Theme, Webapi, WebapiAsync) — 60 tests, 0 failures.
  • Integration: Magento/Framework/View, Code, Mail — 248 tests, 0 failures. Magento/Framework/App — 0 failures.
  • PHPCS Magento2: 0 errors on all changed files.
  • PHPStan level 1 with the project neon: no new errors. The one reported error in View/Layout.php (Variable $name on left side of ?? always exists, in setBlock()) reproduces on the unmodified file.
  • The new BaseTest cases fail without the Handler\\Base change and pass with it.

Pre-existing failures in my environment, unrelated to this diff — not fixed here

  • Framework\\Image\\Adapter\\InterfaceTest::testRotate / testCreatePngFromString: ImagickException: unrecognized color 'srgb255,255,255' from ImageMagick.php:270. Imagick version behaviour; this diff only touches the !is_writable() branch of AbstractAdapter.
  • Framework\\MessageQueue\\MessageEncoderTest::testEncode: customer payload now carries created_in => 'Default Store View'. Fixture drift; the test does not use a logger. Reproduces in isolation.
  • Framework\\MessageQueue\\UseCase\\*: the suite aborts with deployment configuration is corrupted after its own RPC cases run. Environment state, not assertion failures. Consumer::configureQueueConsumer() is covered by ConsumerTest::testProcessWithNotFoundException, which is updated and passing.

Happy to adjust the formatter default if maintainers would rather have includeStacktraces behind a deployment_config flag than on by default.

@lbajsarowicz

Copy link
Copy Markdown
Contributor Author

@magento run all tests

Static Tests counts PHPCS warnings as violations, so pre-existing warnings in
the files this branch touches now fail the build. Declare constant visibility,
replace {@inheritdoc} with @inheritdoc plus the parameter annotations the sniff
expects, drop property descriptions that only repeat the property name, and give
FeedFactory a class description that says what it does.

Layout::setBlock() casts the block name instead of coalescing it, which keeps
the null to empty string behaviour while satisfying the PHPStan rule that the
variable is never null at that point.
@lbajsarowicz

Copy link
Copy Markdown
Contributor Author

Pushed ab3017e to fix the two Static Tests failures.

LiveCodeTest::testPhpStanView/Layout.php:804, Variable $name on left side of ?? always exists and is not nullable. Pre-existing in setBlock(); it only started failing because this branch puts the file in the changed-files scope. Replaced $name = $name ?? ''; with a cast on the array key, which keeps the null → '' coercion for any caller relying on it.

LiveCodeTest::testCodeStyleCodeSniffer::run() returns PHPCS's exit code, and PHPCS counts warnings, so all 24 pre-existing warnings in the touched files were failing the build (my local run had used --warning-severity=0, which is why I missed them). Cleared in 6 files:

  • constant visibility: View/Design/Theme/Image.php, View/TemplateEngine/Xhtml/Template.php, App/Test/Unit/AreaTest.php
  • {@inheritdoc}@inheritdoc + the parameter annotations the sniff wants: App/FeedFactory.php, Css/PreProcessor/ErrorHandler.php, Session/SaveHandler/Redis/Logger.php
  • property descriptions that only repeated the property name, and a class description: View/Design/Theme/Image.php, App/FeedFactory.php

Verified locally with the CI ruleset (dev/tests/static/framework/Magento/ruleset.xml, warnings included): 0 violations. PHPStan: [OK] No errors. Unit tests for the touched areas: 857 tests, 0 failures.

The docblock and constant cleanup is unrelated to the logging change — happy to split it into a separate PR if you'd rather keep this diff narrow.

@lbajsarowicz

Copy link
Copy Markdown
Contributor Author

@magento run all tests

@engcom-Hotel engcom-Hotel added the Priority: P2 A defect with this priority could have functionality issues which are not to expectations. label Aug 4, 2026
@github-project-automation github-project-automation Bot moved this to Pending Review in Pull Requests Dashboard Aug 4, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Priority: P2 A defect with this priority could have functionality issues which are not to expectations. Progress: pending review

Projects

Status: Pending Review

2 participants