Skip to content

[Messenger] improve logs #32036

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Jun 14, 2019
Merged

[Messenger] improve logs #32036

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions src/Symfony/Component/Messenger/Middleware/HandleMessageMiddleware.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,7 +64,7 @@ public function handle(Envelope $envelope, StackInterface $stack): Envelope
$handler = $handlerDescriptor->getHandler();
$handledStamp = HandledStamp::fromDescriptor($handlerDescriptor, $handler($message));
$envelope = $envelope->with($handledStamp);
$this->logger->info('Message "{class}" handled by "{handler}"', $context + ['handler' => $handledStamp->getHandlerName()]);
$this->logger->info('Message {class} handled by {handler}', $context + ['handler' => $handledStamp->getHandlerName()]);
} catch (\Throwable $e) {
$exceptions[] = $e;
}
Expand All @@ -75,7 +75,7 @@ public function handle(Envelope $envelope, StackInterface $stack): Envelope
throw new NoHandlerForMessageException(sprintf('No handler for message "%s".', $context['class']));
}

$this->logger->info('No handler for message "{class}"', $context);
$this->logger->info('No handler for message {class}', $context);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Removed quotes for consistency. They are not useful in logs because in cli they are colored due to the context and the class is a very fixed string anyway without whitespace.

}

if (\count($exceptions)) {
Expand Down
47 changes: 20 additions & 27 deletions src/Symfony/Component/Messenger/Middleware/SendMessageMiddleware.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,37 +54,30 @@ public function handle(Envelope $envelope, StackInterface $stack): Envelope

$sender = null;

try {
if ($envelope->all(ReceivedStamp::class)) {
// it's a received message, do not send it back
$this->logger->info('Received message "{class}"', $context);
} else {
/** @var RedeliveryStamp|null $redeliveryStamp */
$redeliveryStamp = $envelope->last(RedeliveryStamp::class);

// dispatch event unless this is a redelivery
$shouldDispatchEvent = null === $redeliveryStamp;
foreach ($this->getSenders($envelope, $redeliveryStamp) as $alias => $sender) {
if (null !== $this->eventDispatcher && $shouldDispatchEvent) {
$event = new SendMessageToTransportsEvent($envelope);
$this->eventDispatcher->dispatch($event);
$envelope = $event->getEnvelope();
$shouldDispatchEvent = false;
}

$this->logger->info('Sending message "{class}" with "{sender}"', $context + ['sender' => \get_class($sender)]);
$envelope = $sender->send($envelope->with(new SentStamp(\get_class($sender), \is_string($alias) ? $alias : null)));
if ($envelope->all(ReceivedStamp::class)) {
// it's a received message, do not send it back
$this->logger->info('Received message {class}', $context);
} else {
/** @var RedeliveryStamp|null $redeliveryStamp */
$redeliveryStamp = $envelope->last(RedeliveryStamp::class);

// dispatch event unless this is a redelivery
$shouldDispatchEvent = null === $redeliveryStamp;
foreach ($this->getSenders($envelope, $redeliveryStamp) as $alias => $sender) {
if (null !== $this->eventDispatcher && $shouldDispatchEvent) {
$event = new SendMessageToTransportsEvent($envelope);
$this->eventDispatcher->dispatch($event);
$envelope = $event->getEnvelope();
$shouldDispatchEvent = false;
}
}

if (null === $sender) {
return $stack->next()->handle($envelope, $stack);
$this->logger->info('Sending message {class} with {sender}', $context + ['sender' => \get_class($sender)]);
$envelope = $sender->send($envelope->with(new SentStamp(\get_class($sender), \is_string($alias) ? $alias : null)));
}
} catch (\Throwable $e) {
$context['exception'] = $e;
$this->logger->warning('An exception occurred while handling message "{class}": '.$e->getMessage(), $context);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just removing the try catch. It's usually not a good idea to both log and re-throw because it created duplicate logs.

}

throw $e;
if (null === $sender) {
return $stack->next()->handle($envelope, $stack);
}

// message should only be sent and not be handled by the next middleware
Expand Down
12 changes: 2 additions & 10 deletions src/Symfony/Component/Messenger/Retry/MultiplierRetryStrategy.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -70,14 +70,14 @@ public function isRetryable(Envelope $message): bool
return true;
}

$retries = $this->getCurrentRetryCount($message);
$retries = RedeliveryStamp::getRetryCountFromEnvelope($message);

return $retries < $this->maxRetries;
}

public function getWaitingTime(Envelope $message): int
{
$retries = $this->getCurrentRetryCount($message);
$retries = RedeliveryStamp::getRetryCountFromEnvelope($message);

$delay = $this->delayMilliseconds * pow($this->multiplier, $retries);

Expand All @@ -87,12 +87,4 @@ public function getWaitingTime(Envelope $message): int

return $delay;
}

private function getCurrentRetryCount(Envelope $message): int
{
/** @var RedeliveryStamp|null $retryMessageStamp */
$retryMessageStamp = $message->last(RedeliveryStamp::class);

return $retryMessageStamp ? $retryMessageStamp->getRetryCount() : 0;
}
}
9 changes: 9 additions & 0 deletions src/Symfony/Component/Messenger/Stamp/RedeliveryStamp.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
namespace Symfony\Component\Messenger\Stamp;

use Symfony\Component\Debug\Exception\FlattenException;
use Symfony\Component\Messenger\Envelope;

/**
* Stamp applied when a messages needs to be redelivered.
Expand All @@ -38,6 +39,14 @@ public function __construct(int $retryCount, string $senderClassOrAlias, string
$this->redeliveredAt = new \DateTimeImmutable();
}

public static function getRetryCountFromEnvelope(Envelope $envelope): int
{
/** @var self|null $retryMessageStamp */
$retryMessageStamp = $envelope->last(self::class);

return $retryMessageStamp ? $retryMessageStamp->getRetryCount() : 0;
}

public function getRetryCount(): int
{
return $this->retryCount;
Expand Down
18 changes: 6 additions & 12 deletions src/Symfony/Component/Messenger/Worker.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -140,14 +140,16 @@ private function handleMessage(Envelope $envelope, ReceiverInterface $receiver,

$this->dispatchEvent(new WorkerMessageFailedEvent($envelope, $transportName, $throwable, $shouldRetry));

$retryCount = RedeliveryStamp::getRetryCountFromEnvelope($envelope);
if ($shouldRetry) {
$retryCount = $this->getRetryCount($envelope) + 1;
++$retryCount;
$delay = $retryStrategy->getWaitingTime($envelope);
if (null !== $this->logger) {
$this->logger->error('Retrying {class} - retry #{retryCount}.', $context + ['retryCount' => $retryCount, 'error' => $throwable]);
$this->logger->error('Error thrown while handling message {class}. Dispatching for retry #{retryCount} using {delay} ms delay. Error: "{error}"', $context + ['retryCount' => $retryCount, 'delay' => $delay, 'error' => $throwable->getMessage(), 'exception' => $throwable]);
}

// add the delay and retry stamp info + remove ReceivedStamp
$retryEnvelope = $envelope->with(new DelayStamp($retryStrategy->getWaitingTime($envelope)))
$retryEnvelope = $envelope->with(new DelayStamp($delay))
->with(new RedeliveryStamp($retryCount, $this->getSenderClassOrAlias($envelope)))
->withoutAll(ReceivedStamp::class);

Expand All @@ -157,7 +159,7 @@ private function handleMessage(Envelope $envelope, ReceiverInterface $receiver,
$receiver->ack($envelope);
} else {
if (null !== $this->logger) {
$this->logger->critical('Rejecting {class} (removing from transport).', $context + ['error' => $throwable]);
$this->logger->critical('Error thrown while handling message {class}. Removing from transport after {retryCount} retries. Error: "{error}"', $context + ['retryCount' => $retryCount, 'error' => $throwable->getMessage(), 'exception' => $throwable]);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

including the exception message makes sure you can see it without having to run in -vvv mode. the context otherwise only shows the exception class but not the message.

}

$receiver->reject($envelope);
Expand Down Expand Up @@ -207,14 +209,6 @@ private function shouldRetry(\Throwable $e, Envelope $envelope, RetryStrategyInt
return $retryStrategy->isRetryable($envelope);
}

private function getRetryCount(Envelope $envelope): int
{
/** @var RedeliveryStamp|null $retryMessageStamp */
$retryMessageStamp = $envelope->last(RedeliveryStamp::class);

return $retryMessageStamp ? $retryMessageStamp->getRetryCount() : 0;
}

private function getSenderClassOrAlias(Envelope $envelope): string
{
/** @var SentStamp|null $sentStamp */
Expand Down