Process args in "extra" key of recorded message

[prgTW]

This PR aims to fix the problem #836 (extra key of the recorded message is completely ignored) as quickly as possible not to loose data from logs

[Jean85]

As explained here #844 (comment) (similar issue with Python SDK) reading blindly a key from monolog could be dangerous, since other handlers could use such a generic key to store whatever.

[ste93cry]

I agree, reading from $context['extra'] should have never been implemented. If you want to "capture" additional data by extracting it from the Monolog payload besides the standard information like the channel name or the message then the best thing is to write your own handler or processor and use configureScope or withScope. Closing this as this kind of feature is something we don't want to support anymore out-of-the-box

[prgTW]

@ste93cry but how handling $record['context']['extra'] differs from $record['extra']? Both of them are handled as an array, with no data type checking of the values. How can You be sure that $record['context']['extra'] won't contain anything "bad"? My code was also using withScope so I don't understand the reasons why this PR got closed.

[ste93cry]

Quoting from the Monolog documentation:

At first glance context and extra look very similar, and they are in the sense that they both carry arbitrary data that is related to the log message somehow. The main difference is that context can be supplied in user land (it is the 3rd parameter to Logger::addRecord()) whereas extra is internal only and can be filled by processors. The reason processors write to extra and not to context is to prevent overriding any user provided data in context.

The main problem is that there is no guarantee that the data added to this key is data that you want to log in Sentry, that the "shape" of the data is compatible with what Sentry expects or that you want to blindly override what has been set by the user with the data coming from the processors if the share the same key

Both of them are handled as an array, with no data type checking of the values. How can You be sure that $record['context']['extra'] won't contain anything "bad"?

We can't of course, and this is one of the reasons why we want to avoid in the future blindly pulling information from the log data. I would say that we can be safer in thinking that the data coming from $record['context']['extra'] is already in a format compatible with Sentry because it's supplied from the user, but honestly I wouldn't bet on it. All these use-cases that wants to pull data from the log imho are too projects-dependant.

reading from $context['extra'] should have never been implemented

To clarify, pulling data from $record['context']['tags'] and $record['context']['extra'] (which is supported out-of-the-box right now) was an error, but we cannot remove such features or we will break BC. This doesn't prevent us to not add more support for similar things to avoid the pitfalls described above 😉

[prgTW]

Oh, support for $record['context']['extra'] was a mistake in the first place, now I get it, thanks!

What about introducing a processor that moves $record['context'] and $record['extra'] to the scope directly in Your repo? Should You handle this in a (more or less) generic way (may not fit to every project) should I totally implement it on my side?

[ste93cry]

Should You handle this in a (more or less) generic way (may not fit to every project) should I totally implement it on my side?

For the moment yes, you should implement in on your side. This way you can decide whether to blindly move everything or only certain things to the scope

[jbelien]

Hello everyone,

I was looking to do exactly this (sending $record['context'] to Sentry) but I totally understand the reasoning behind why this PR was closed.
That being said, I don't see how to implement this on my side ...

@prgTW How did you do it ?

Should I "just" extend the Sentry\Monolog\Handler ?

Thanks!

[ste93cry]

You should use composition to wrap the handler inside your custom one and then call withScope to add the data you need to the scope. Something like this should work:

use Monolog\Handler\AbstractProcessingHandler;
use Sentry\Scope;
use function Sentry\withScope;

final class CustomMonologHandler extends AbstractProcessingHandler
{
    private $innerHandler;

    public function __construct(HandlerInterface $handler)
    {
        $this->innerHandler = $handler;
    }

    public function handle(array $record)
    {
        withScope(function (Scope $scope): void {
            $scope->setExtra('...', '...');

            $this->innerHandler->handle($record);
        });
    }
}

I coded this example on the fly so don't expect it to work as is, but it should give you an hint on how I would do it

[jbelien]

Thanks @ste93cry ! That makes sense 👍

[Spriz]

Could also easily be handled in Monolog :)

$log->pushProcessor(function ($record) {
    if (isset($record['context']) && is_array($record['context'])) {
        foreach ($record['context'] as $key => $value) {
            if ($key === 'tags') {
                //Handled natively by Sentry monolog handler
                continue;
            }
            $record['context']['extra'][$key] = is_string($value) && json_decode($value) !== null ? json_decode($value) : $value;
        }
    }

    return $record;
});

[guicara]

To add extra information along the simple textual message, I also use the logging context to pass an array of data along the record. For example:

$logger->info('Adding a new user', array('username' => 'Seldaek'));

It was really important for me to get the context in Sentry issues.

Thank you very much @ste93cry and @Spriz. I have created a custom handler with a mix of your two answers. Tested successfully with Symfony 3.4. I decorate the Sentry\Monolog\Handler service.

config.yml:

monolog:
    handlers:
        sentry:
            type: service
            id: Acme\Monolog\SentryHandler

services.yml:

services:
    Acme\Monolog\SentryHandler:
        decorates: Sentry\Monolog\Handler
        arguments: ['@Acme\Monolog\SentryHandler.inner']

src/Acme/Monolog/SentryHandler.php:

<?php

namespace Acme\Monolog;

use Monolog\Handler\AbstractProcessingHandler;
use Monolog\Logger;
use Sentry\Monolog\Handler as InnerHandler;
use Sentry\Severity;
use Sentry\State\HubInterface;
use Sentry\State\Scope;
use function Sentry\withScope;

/**
 * This Monolog handler logs every message to a Sentry's server using the given
 * hub instance. 
 * 
 * If extra information are added to the simple textual message (through an array 
 * of data along the record), this custom Sentry handler iterate the array to set 
 * data in the extra Sentry context.
 *
 * @author Stefano Arlandini <sarlandini@alice.it>
 */
final class SentryHandler extends AbstractProcessingHandler
{
    /**
     * @var HubInterface
     */
    private $hub;

    /**
     * @var InnerHandler
     */
    private $handler;

    /**
     * SentryHandler constructor.
     *
     * @param InnerHandler $handler
     * @param HubInterface $hub    The hub to which errors are reported
     * @param int          $level  The minimum logging level at which this
     *                             handler will be triggered
     * @param bool         $bubble Whether the messages that are handled can
     *                             bubble up the stack or not
     */
    public function __construct(InnerHandler $handler, HubInterface $hub, $level = Logger::DEBUG, bool $bubble = true)
    {
        $this->handler = $handler;
        $this->hub = $hub;

        parent::__construct($level, $bubble);
    }

    public function handle(array $record)
    {
        withScope(function (Scope $scope) use ($record): void {
            if (isset($record['context']) && is_array($record['context'])) {
                foreach ($record['context'] as $key => $value) {
                    if ($key === 'tags') {
                        // Handled natively by Sentry monolog handler
                        continue;
                    }
                    $scope->setExtra($key, is_string($value) && json_decode($value) !== null ? json_decode($value) : $value);
                }
            }

            $this->handler->handle($record);
        });
    }

    /**
     * {@inheritdoc}
     */
    protected function write(array $record): void
    {
        $payload = [
            'level' => $this->getSeverityFromLevel($record['level']),
            'message' => $record['message'],
            'logger' => 'monolog.' . $record['channel'],
        ];

        if (isset($record['context']['exception']) && $record['context']['exception'] instanceof \Throwable) {
            $payload['exception'] = $record['context']['exception'];
        }

        $this->hub->withScope(function (Scope $scope) use ($record, $payload): void {
            $scope->setExtra('monolog.channel', $record['channel']);
            $scope->setExtra('monolog.level', $record['level_name']);

            if (isset($record['context']['extra']) && \is_array($record['context']['extra'])) {
                foreach ($record['context']['extra'] as $key => $value) {
                    $scope->setExtra((string) $key, $value);
                }
            }

            if (isset($record['context']['tags']) && \is_array($record['context']['tags'])) {
                foreach ($record['context']['tags'] as $key => $value) {
                    $scope->setTag($key, $value);
                }
            }

            $this->hub->captureEvent($payload);
        });
    }

    /**
     * Translates the Monolog level into the Sentry severity.
     *
     * @param int $level The Monolog log level
     * @return Severity
     */
    private function getSeverityFromLevel(int $level): Severity
    {
        switch ($level) {
            case Logger::DEBUG:
                return Severity::debug();
            case Logger::INFO:
            case Logger::NOTICE:
                return Severity::info();
            case Logger::WARNING:
                return Severity::warning();
            case Logger::ERROR:
                return Severity::error();
            case Logger::CRITICAL:
            case Logger::ALERT:
            case Logger::EMERGENCY:
                return Severity::fatal();
            default:
                return Severity::info();
        }
    }
}

The write method is abstract and protected, so I had to implement this method and I could not use the decorator $this->handler->write(). Moreover, this method also calls the private method getSeverityFromLevel. So, lot of copy and paste from the original Sentry\Monolog\Handler handler... Is there a better way?

[ste93cry]

That's not really how I would expect a decorator to be written. Isn't this sufficient?

class TestHandler implements HandlerInterface
{
    /**
     * @var HandlerInterface
     */
    private $decoratedHandler;

    public function __construct(HandlerInterface $decoratedHandler)
    {
        $this->decoratedHandler = $decoratedHandler;
    }

    public function isHandling(array $record): bool
    {
        return $this->decoratedHandler->isHandling($record);
    }

    public function handle(array $record): bool
    {
        $result = false;

        withScope(function (Scope $scope) use ($record, &$result): void {
            $scope->setExtra(...);

            $result = $this->decoratedHandler->handle($record);
        });

        return $result;
    }

    public function handleBatch(array $records): void
    {
        $this->decoratedHandler->handleBatch($records);
    }

    public function close(): void
    {
        $this->decoratedHandler->close();
    }
}

[guicara]

Sorry, I'm not a Symfony developer. I have tested your code, and implementing HandlerInterface is much better! With my version of Monolog I had to implement also pushProcessor, popProcessor, setFormatter and getFormatter.

So the final code, tested successfully is:

src/Acme/Monolog/SentryHandler.php:

<?php

namespace Acme\Monolog;

use Monolog\Formatter\FormatterInterface;
use Monolog\Handler\HandlerInterface;
use Sentry\State\Scope;
use function Sentry\withScope;

/**
 * This Monolog handler logs every message to a Sentry's server using the given
 * hub instance.
 *
 * If extra information is added to the simple textual message (through an array
 * of data along the record), this custom Sentry handler iterate the array to set
 * data in the extra Sentry context.
 */
class SentryHandler implements HandlerInterface
{
    /**
     * @var HandlerInterface
     */
    private $decoratedHandler;

    /**
     * SentryHandler constructor.
     *
     * @param HandlerInterface $decoratedHandler
     */
    public function __construct(HandlerInterface $decoratedHandler)
    {
        $this->decoratedHandler = $decoratedHandler;
    }

    /**
     * @inheritDoc
     */
    public function isHandling(array $record): bool
    {
        return $this->decoratedHandler->isHandling($record);
    }

    /**
     * @inheritDoc
     */
    public function handle(array $record): bool
    {
        $result = false;

        withScope(function (Scope $scope) use ($record, &$result): void {
            if (isset($record['context']) && is_array($record['context'])) {
                foreach ($record['context'] as $key => $value) {
                    if ($key === 'tags') {
                        // Handled natively by Sentry monolog handler
                        continue;
                    }
                    $scope->setExtra($key, is_string($value) && json_decode($value) !== null ? json_decode($value) : $value);
                }
            }

            $result = $this->decoratedHandler->handle($record);
        });

        return $result;
    }

    /**
     * @inheritDoc
     */
    public function handleBatch(array $records): void
    {
        $this->decoratedHandler->handleBatch($records);
    }

    /**
     * @inheritDoc
     */
    public function close(): void
    {
        $this->decoratedHandler->close();
    }

    /**
     * @inheritDoc
     */
    public function pushProcessor($callback)
    {
        $this->decoratedHandler->pushProcessor($callback);

        return $this;
    }

    /**
     * @inheritDoc
     */
    public function popProcessor()
    {
        $this->decoratedHandler->popProcessor();
    }

    /**
     * @inheritDoc
     */
    public function setFormatter(FormatterInterface $formatter)
    {
        $this->decoratedHandler->setFormatter($formatter);

        return $this;
    }

    /**
     * @inheritDoc
     */
    public function getFormatter()
    {
        return $this->decoratedHandler->getFormatter();
    }
}

Thank you @ste93cry :)

[dedpikhto]

Hi there! I have an issue using "withScope". I've decorated Sentry\Monolog\Handler, but "withScope" pushes modified scope in stack, so when i call write(), i got another scope, than modified in decorator. What do i do wrong?

[Jean85]

Scopes work with a stack, so you can push & pop as needed.
withScope pushes a new scope on the stack temporarily, just for the time of execution of the callback:

sentry-php/src/State/HubInterface.php

Lines 52 to 58 in d9fdc40

	/**
	* Creates a new scope with and executes the given operation within. The scope
	* is automatically removed once the operation finishes or throws.
	*
	* @param callable $callback The callback to be executed
	*/
	public function withScope(callable $callback): void;

You're probably gonna need configureScope, with a pushScope just before if needed.

[dedpikhto]

public function handle(array $record): bool
{
$result = false;

withScope(function (Scope $scope) use ($record, &$result): void {
    if (isset($record['context']) && is_array($record['context']) && count($record['context']) > 0) {
        $scope->setContext('monolog.context', $record['context']);
        $scope->setExtras($record['extra']);
        $scope->setExtra('monolog.formatted', $record['formatted'] ?? '');

    }

    $result = $this->handler->handle($record);
});

return $result;

}

I mean handle() method in callback has it's own withScope() call, so your changes to scope in decorator has no effect on final event. Also, configureScope has no effect.

UPD: i see that pushed scope is cloned, so it should work, but it isn't. I'll check more. Thank you.

[dedpikhto]

It's a symfony + monolog-bundle issue: decorator has different hub instance (via function withScope) than Sentry\Monolog\Handler decorated instance. One from DI container, other from static SentrySdk call.