sygnal icon indicating copy to clipboard operation
sygnal copied to clipboard

Don't log stack trace when handling `TemporaryNotificationDispatchException` exception

Open chagai95 opened this issue 3 years ago • 2 comments

Describe the bug Not sure but saw something in the debug logs

2021-06-09 14:12:27,111 [1] INFO  sygnal.access Handled request: "127.0.0.1" - - [09/Jun/2021:12:12:27 +0000] "POST /_matrix/push/v1/notify HTTP/1.0" 200 16 "-" "Synapse/1.27.0"
2021-06-09 14:14:51,633 [1] DEBUG sygnal.http [132ef873-b946-4892-8c14-3260ae636326] Sending push to pushkin com.aarenet.anConnect.ios.app.ios.prod for app ID com.aarenet.anConnect.ios.app.ios.prod
2021-06-09 14:14:51,634 [1] INFO  sygnal.apnspushkin [132ef873-b946-4892-8c14-3260ae636326] Sending as APNs-ID 202656f0-f97e-4782-8911-9c26dfce882b
2021-06-09 14:14:51,634 [1] DEBUG aioapns Notification 202656f0-f97e-4782-8911-9c26dfce882b: waiting for connection
2021-06-09 14:14:51,636 [1] DEBUG sygnal.http [3a3949ad-d628-44c8-abff-c812aa08b910] Sending push to pushkin com.aarenet.anconnect.android for app ID com.aarenet.anconnect.android
2021-06-09 14:14:51,638 [1] INFO  sygnal.gcmpushkin [3a3949ad-d628-44c8-abff-c812aa08b910] Sending (attempt 0) => ['fG3HsmCoQGCt4nV37ce68K:APA91bF5ST_wz9tBHmgC8VNmjLz52rkOSe-3JdkNoeFiaj_ge7hD0Fr6Imcl-mRHihviqohmhg9q4IoO_WSy0wplMxCYRAVbFD7Wi2UVvOu8YFGmYwruN-TAldH9Qx0f2EN5WgBcpacA']
2021-06-09 14:14:51,638 [1] DEBUG sygnal.helper.proxy.proxyagent_twisted Requesting b'https://fcm.googleapis.com/fcm/send' via <HostnameEndpoint fcm.googleapis.com:443>
2021-06-09 14:14:51,644 [1] WARNING sygnal.gcmpushkin [3a3949ad-d628-44c8-abff-c812aa08b910] Temporary failure, will retry in 10 seconds
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/sygnal/gcmpushkin.py", line 193, in _perform_http_request
    bodyProducer=body_producer,
twisted.web._newclient.ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>]

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/sygnal/gcmpushkin.py", line 384, in _dispatch_notification_unlimited
    n, log, body, headers, mapped_pushkeys, span
  File "/usr/local/lib/python3.7/site-packages/sygnal/gcmpushkin.py", line 209, in _request_dispatch
    response, response_text = await self._perform_http_request(body, headers)
  File "/usr/local/lib/python3.7/site-packages/sygnal/gcmpushkin.py", line 199, in _perform_http_request
    ) from exception
sygnal.exceptions.TemporaryNotificationDispatchException: GCM request failure
2021-06-09 14:14:51,745 [1] INFO  twisted Stopping factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x7f99c4350f80>, <twisted.internet.endpoints._WrapperEndpoint object at 0x7f99c42b36d0>)

chagai95 avatar Jun 10 '21 08:06 chagai95

That looks to be because the request timed out. Maybe the internet or Google had a blip or something :shrug:

I'm not sure why we log the stack trace though, we should just log the exception message and not the stack trace.

erikjohnston avatar Jul 23 '21 15:07 erikjohnston

I think this is just a case of removing exc_info=True here:

https://github.com/matrix-org/sygnal/blob/214497a1584c37e57f01499628d123ed984bd271/sygnal/gcmpushkin.py#L398-L402

And also adding exc to the log line.

erikjohnston avatar Jul 23 '21 15:07 erikjohnston