Failed scheduler task messages miss important information

[cweiske]

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]

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]

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.

<?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);
    }
}

[christophlehmann]

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;

---

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}

[cweiske]

Having the original message as breadcrumb is a good idea!

[cweiske]

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