sentry_client
sentry_client copied to clipboard
Failed scheduler task messages miss important information
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":{}}
I see these options:
- Minimal solution: Modify
interpolate()to append the parent exception code and message to the log message - Cast any exception object in
$record->getData()into an array structure so it gets serialized with json_encode - When
$record->getData()has an 'exception' key, create a dummy exception ("LogMessageException") with the log message and use theexceptionvalue as parent exception. This way all information including the stacktrace would be properly visible in sentry.
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);
}
}
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}
Having the original message as breadcrumb is a good idea!
Bug report for TYPO3 core: https://forge.typo3.org/issues/103799 Patch for core: https://review.typo3.org/c/Packages/TYPO3.CMS/+/84152
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.