sentry_client icon indicating copy to clipboard operation
sentry_client copied to clipboard

Failed scheduler task messages miss important information

Open cweiske opened this issue 1 year ago • 5 comments
trafficstars

Problem

Exceptions thrown in scheduler tasks only have a generic message in sentry:

Task failed to execute successfully. Class: TYPO3\CMS\Scheduler\Task\ExecuteSchedulableCommandTask, UID: 5

There is no information what actually failed when TYPO3 v11 or v12 are used. The "Zusätzliche Daten"/"Additional data" property data in Sentry only contains the ExecuteSchedulableCommandTask class and UID as already seen in the message. The exception data key is an empty object:

component TYPO3.CMS.Scheduler.Scheduler
data {
    class: TYPO3\CMS\Scheduler\Task\ExecuteSchedulableCommandTask,
    exception: {},
    uid: 5
}

It would be nice if the exception data would be available in Sentry.

History

TYPO3 v10 appended the source exception message to the log message, which gave us a better hint:

Task failed to execute successfully. Class: TYPO3\CMS\Scheduler\Task\ExecuteSchedulableCommandTask, UID: 1, Code: 56, OpenSSL SSL_read: Connection reset by peer, errno 104

Since [BUGFIX] Make logger usage PSR-3 compliant in TYPO3 v11.2 this is no longer the case.

Code dive

When a TYPO3 scheduler task throws an exception, Scheduler::executeTask logs the exception with

$this->logger->error(
    'Task failed to execute successfully. Class: {class}, UID: {uid}',
    [
        'class' => get_class($task),
        'uid' => $task->getTaskUid(),
        'exception' => $e,
    ]
);

SentryClient's SentryLogWriter passes those data via $scope->setExtra to Sentry and runs Client::captureMessage. Sentry then uses json_encode to serialize the data. The Exception class is not serialized but converted to an empty object:

php > echo json_encode((object) ['a' => 1, 'e' => new Exception('test')]);
{"a":1,"e":{}}

cweiske avatar May 06 '24 10:05 cweiske

I see these options:

  1. Minimal solution: Modify interpolate() to append the parent exception code and message to the log message
  2. Cast any exception object in $record->getData() into an array structure so it gets serialized with json_encode
  3. When $record->getData() has an 'exception' key, create a dummy exception ("LogMessageException") with the log message and use the exception value as parent exception. This way all information including the stacktrace would be properly visible in sentry.

cweiske avatar May 06 '24 13:05 cweiske

This is an example how a LogMessageException (option 3) looks like in Sentry. Note the two exceptions; the latter one is the original exception from the data.

2024-05-06 sentry logmessageexception

<?php

namespace Mogic\Dbi\Exception;

use Networkteam\SentryClient\Client;
use Networkteam\SentryClient\Service\SentryService;
use Sentry\State\Scope;

use TYPO3\CMS\Core\Log\LogLevel;
use TYPO3\CMS\Core\Log\LogRecord;

use function Sentry\withScope;

/**
 * Add the scheduler exception message to the log message
 *
 * @link https://github.com/networkteam/sentry_client/issues/106
 */
class BetterSentryLogWriter extends \Networkteam\SentryClient\SentryLogWriter
{
    /**
     * Forwards the log record to Sentry
     *
     * @return \TYPO3\CMS\Core\Log\Writer\WriterInterface $this
     */
    public function writeLog(LogRecord $record)
    {
        if (!SentryService::isEnabled()
            || !$this->shouldHandleLogMessage($record)
        ) {
            return $this;
        }

        $data = $record->getData();
        if (isset($data['exception']) && $data['exception'] instanceof \Throwable) {
            $dummy = new LogMessageException(
                $this->interpolate($record->getMessage(), $record->getData()),
                LogLevel::normalizeLevel($record->getLevel()),
                $data['exception']
            );

            withScope(function (Scope $scope) use ($record, $dummy): void {
                $scope->setExtra('component', $record->getComponent());
                if ($record->getData()) {
                    $scope->setExtra('data', $record->getData());
                }
                Client::captureException($dummy);
            });

            return $this;
        }

        return parent::writeLog($record);
    }
}

cweiske avatar May 06 '24 13:05 cweiske

I see the point, we should report the Exception and somehow keep the log records message. I not yet sure if i like the dummy Exception. The stacktrace looks superfluous to me.

How about a Breadcrumb...

$message = $record->getMessage();
if (method_exists($this, 'interpolate')) {
    $message = $this->interpolate($message, $record->getData());
}

$breadcrumb = new Breadcrumb('error', 'default', 'log message', $message, []);
SentrySdk::getCurrentHub()->addBreadcrumb($breadcrumb);
Client::captureException($record->getData()['exception']);
return $this;
sentry-breadcrumb

Beside this, in the core we could better wrap the Exception message like

<ExceptionMessage> <File> <Line>... , occured during executing a scheduler task, class: {class}, uid: {uid}

christophlehmann avatar May 06 '24 20:05 christophlehmann

Having the original message as breadcrumb is a good idea!

cweiske avatar May 07 '24 04:05 cweiske

Bug report for TYPO3 core: https://forge.typo3.org/issues/103799 Patch for core: https://review.typo3.org/c/Packages/TYPO3.CMS/+/84152

cweiske avatar May 07 '24 11:05 cweiske

TYPO3 v12.4.17 contains the patch that improves the scheduler exception message: https://get.typo3.org/release-notes/12.4.17

This issue here is solved with it.

cweiske avatar Aug 19 '24 13:08 cweiske