Skip to content

Commit e02da2a

Browse files
fabpotfabpot
committed
bug symfony#32036 [Messenger] improve logs (Tobion)
This PR was merged into the 4.3 branch. Discussion ---------- [Messenger] improve logs | Q | A | ------------- | --- | Branch? | 4.3 | Bug fix? | no | New feature? | no <!-- please update src/**/CHANGELOG.md files --> | BC breaks? | no <!-- see https://symfony.com/bc --> | Deprecations? | no <!-- please update UPGRADE-*.md and src/**/CHANGELOG.md files --> | Tests pass? | yes <!-- please add some, will be required by reviewers --> | Fixed tickets | | License | MIT | Doc PR | The logs are currently very confusing and duplicated: - When handled sync the uncaught error it logged and displayed by the console / http error handler anyway. Currently it the warning is duplicated and useless: ``` 14:26:11 WARNING [messenger] An exception occurred while handling message "{class}": OUCH, THAT HURTS! GO TO MOM! 14:26:11 ERROR [console] Error thrown while running command "{class}". Message: "OUCH, THAT HURTS! GO TO MOM!" In HandleMessageMiddleware.php line 82: [Symfony\Component\Messenger\Exception\HandlerFailedException] OUCH, THAT HURTS! GO TO MOM! ``` - When handling async is was even confusing because the actual error was logged as warning and the retry (which is a good thing) was the error. ``` 13:48:15 WARNING [messenger] An exception occurred while handling message "{class}": OUCH, THAT HURTS! GO TO MOM! 13:48:15 ERROR [messenger] Retrying {class} - retry #1. ``` Now it's must clearer and adds even context like the delay: ``` 16:20:11 ERROR [messenger] Error thrown while handling message {class}. Dispatching for retry #3 using 4000 ms delay. Error: "OUCH, THAT HURTS! GO TO MOM!" ... 16:20:15 CRITICAL [messenger] Error thrown while handling message {class}. Removing from transport after 3 retries. Error: "OUCH, THAT HURTS! GO TO MOM!" ``` Commits ------- 2ac7027 [Messenger] improve logs
2 parents d7ba773 + 2ac7027 commit e02da2a

File tree

5 files changed

+39
-51
lines changed

5 files changed

+39
-51
lines changed

‎src/Symfony/Component/Messenger/Middleware/HandleMessageMiddleware.php‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -64,7 +64,7 @@ public function handle(Envelope $envelope, StackInterface $stack): Envelope
6464
$handler = $handlerDescriptor->getHandler();
6565
$handledStamp = HandledStamp::fromDescriptor($handlerDescriptor, $handler($message));
6666
$envelope = $envelope->with($handledStamp);
67-
$this->logger->info('Message "{class}" handled by "{handler}"', $context + ['handler' => $handledStamp->getHandlerName()]);
67+
$this->logger->info('Message {class} handled by {handler}', $context + ['handler' => $handledStamp->getHandlerName()]);
6868
} catch (\Throwable $e) {
6969
$exceptions[] = $e;
7070
}
@@ -75,7 +75,7 @@ public function handle(Envelope $envelope, StackInterface $stack): Envelope
7575
throw new NoHandlerForMessageException(sprintf('No handler for message "%s".', $context['class']));
7676
}
7777

78-
$this->logger->info('No handler for message "{class}"', $context);
78+
$this->logger->info('No handler for message {class}', $context);
7979
}
8080

8181
if (\count($exceptions)) {

‎src/Symfony/Component/Messenger/Middleware/SendMessageMiddleware.php‎

Lines changed: 20 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -54,37 +54,30 @@ public function handle(Envelope $envelope, StackInterface $stack): Envelope
5454

5555
$sender = null;
5656

57-
try {
58-
if ($envelope->all(ReceivedStamp::class)) {
59-
// it's a received message, do not send it back
60-
$this->logger->info('Received message "{class}"', $context);
61-
} else {
62-
/** @var RedeliveryStamp|null $redeliveryStamp */
63-
$redeliveryStamp = $envelope->last(RedeliveryStamp::class);
64-
65-
// dispatch event unless this is a redelivery
66-
$shouldDispatchEvent = null === $redeliveryStamp;
67-
foreach ($this->getSenders($envelope, $redeliveryStamp) as $alias => $sender) {
68-
if (null !== $this->eventDispatcher && $shouldDispatchEvent) {
69-
$event = new SendMessageToTransportsEvent($envelope);
70-
$this->eventDispatcher->dispatch($event);
71-
$envelope = $event->getEnvelope();
72-
$shouldDispatchEvent = false;
73-
}
74-
75-
$this->logger->info('Sending message "{class}" with "{sender}"', $context + ['sender' => \get_class($sender)]);
76-
$envelope = $sender->send($envelope->with(new SentStamp(\get_class($sender), \is_string($alias) ? $alias : null)));
57+
if ($envelope->all(ReceivedStamp::class)) {
58+
// it's a received message, do not send it back
59+
$this->logger->info('Received message {class}', $context);
60+
} else {
61+
/** @var RedeliveryStamp|null $redeliveryStamp */
62+
$redeliveryStamp = $envelope->last(RedeliveryStamp::class);
63+
64+
// dispatch event unless this is a redelivery
65+
$shouldDispatchEvent = null === $redeliveryStamp;
66+
foreach ($this->getSenders($envelope, $redeliveryStamp) as $alias => $sender) {
67+
if (null !== $this->eventDispatcher && $shouldDispatchEvent) {
68+
$event = new SendMessageToTransportsEvent($envelope);
69+
$this->eventDispatcher->dispatch($event);
70+
$envelope = $event->getEnvelope();
71+
$shouldDispatchEvent = false;
7772
}
78-
}
7973

80-
if (null === $sender) {
81-
return $stack->next()->handle($envelope, $stack);
74+
$this->logger->info('Sending message {class} with {sender}', $context + ['sender' => \get_class($sender)]);
75+
$envelope = $sender->send($envelope->with(new SentStamp(\get_class($sender), \is_string($alias) ? $alias : null)));
8276
}
83-
} catch (\Throwable $e) {
84-
$context['exception'] = $e;
85-
$this->logger->warning('An exception occurred while handling message "{class}": '.$e->getMessage(), $context);
77+
}
8678

87-
throw $e;
79+
if (null === $sender) {
80+
return $stack->next()->handle($envelope, $stack);
8881
}
8982

9083
// message should only be sent and not be handled by the next middleware

‎src/Symfony/Component/Messenger/Retry/MultiplierRetryStrategy.php‎

Lines changed: 2 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -70,14 +70,14 @@ public function isRetryable(Envelope $message): bool
7070
return true;
7171
}
7272

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

7575
return $retries < $this->maxRetries;
7676
}
7777

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

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

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

8888
return $delay;
8989
}
90-
91-
private function getCurrentRetryCount(Envelope $message): int
92-
{
93-
/** @var RedeliveryStamp|null $retryMessageStamp */
94-
$retryMessageStamp = $message->last(RedeliveryStamp::class);
95-
96-
return $retryMessageStamp ? $retryMessageStamp->getRetryCount() : 0;
97-
}
9890
}

‎src/Symfony/Component/Messenger/Stamp/RedeliveryStamp.php‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
namespace Symfony\Component\Messenger\Stamp;
1313

1414
use Symfony\Component\Debug\Exception\FlattenException;
15+
use Symfony\Component\Messenger\Envelope;
1516

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

42+
public static function getRetryCountFromEnvelope(Envelope $envelope): int
43+
{
44+
/** @var self|null $retryMessageStamp */
45+
$retryMessageStamp = $envelope->last(self::class);
46+
47+
return $retryMessageStamp ? $retryMessageStamp->getRetryCount() : 0;
48+
}
49+
4150
public function getRetryCount(): int
4251
{
4352
return $this->retryCount;

‎src/Symfony/Component/Messenger/Worker.php‎

Lines changed: 6 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -140,14 +140,16 @@ private function handleMessage(Envelope $envelope, ReceiverInterface $receiver,
140140

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

143+
$retryCount = RedeliveryStamp::getRetryCountFromEnvelope($envelope);
143144
if ($shouldRetry) {
144-
$retryCount = $this->getRetryCount($envelope) + 1;
145+
++$retryCount;
146+
$delay = $retryStrategy->getWaitingTime($envelope);
145147
if (null !== $this->logger) {
146-
$this->logger->error('Retrying {class} - retry #{retryCount}.', $context + ['retryCount' => $retryCount, 'error' => $throwable]);
148+
$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]);
147149
}
148150

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

@@ -157,7 +159,7 @@ private function handleMessage(Envelope $envelope, ReceiverInterface $receiver,
157159
$receiver->ack($envelope);
158160
} else {
159161
if (null !== $this->logger) {
160-
$this->logger->critical('Rejecting {class} (removing from transport).', $context + ['error' => $throwable]);
162+
$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]);
161163
}
162164

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

210-
private function getRetryCount(Envelope $envelope): int
211-
{
212-
/** @var RedeliveryStamp|null $retryMessageStamp */
213-
$retryMessageStamp = $envelope->last(RedeliveryStamp::class);
214-
215-
return $retryMessageStamp ? $retryMessageStamp->getRetryCount() : 0;
216-
}
217-
218212
private function getSenderClassOrAlias(Envelope $envelope): string
219213
{
220214
/** @var SentStamp|null $sentStamp */

0 commit comments

Comments
 (0)