Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Unhandled ijson exceptions in various places causing log and sentry spam #14320

Open
DMRobertson opened this issue Oct 28, 2022 · 4 comments
Open

Unhandled ijson exceptions in various places causing log and sentry spam #14320

DMRobertson opened this issue Oct 28, 2022 · 4 comments
Labels
A-Logging Synapse's logs (structured or otherwise). Not metrics. O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Tolerable Minor significance, cosmetic issues, low or no impact to users. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact Z-Sentry Issue was discovered by looking at Sentry reports on Matrix.org

Comments

@DMRobertson
Copy link
Contributor

https://sentry.tools.element.io/organizations/element/issues/29/?project=2&query=is%3Aunresolved&statsPeriod=24h

2022-10-28 02:43:48,424 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- - Exception ignored in: <generator object utf8_encoder at 0x7f52723e7430>
2022-10-28 02:43:48,430 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- - Traceback (most recent call last):
2022-10-28 02:43:48,435 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-10-28 02:43:48,440 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- -     target.close()
2022-10-28 02:43:48,443 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 116, in Lexer
2022-10-28 02:43:48,447 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- -     target.send(EOF)
2022-10-28 02:43:48,450 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 161, in parse_value
2022-10-28 02:43:48,453 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-10-28 02:43:48,456 - twisted - 274 - ERROR - _maybe_retry_device_resync-852- - ijson.common.IncompleteJSONError: Incomplete JSON content
@DMRobertson DMRobertson added the Z-Sentry Issue was discovered by looking at Sentry reports on Matrix.org label Oct 28, 2022
@DMRobertson
Copy link
Contributor Author

There are nearby warning lines of the form

2022-10-28 02:43:48,366 - synapse.handlers.device - 1132 - WARNING - _maybe_retry_device_resync-852- - Failed to handle device list update for @user:example.com: 403: Forbidden

But I can't see where we call out to ijson from a quick inspection.

@squahtx
Copy link
Contributor

squahtx commented Oct 31, 2022

This is very puzzling. #14065 fixes the only usages of ijson that I can find.

I wonder if:

@DMRobertson DMRobertson added A-Logging Synapse's logs (structured or otherwise). Not metrics. S-Tolerable Minor significance, cosmetic issues, low or no impact to users. Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact O-Uncommon Most users are unlikely to come across this or unexpected workflow T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. labels Oct 31, 2022
@DMRobertson
Copy link
Contributor Author

DMRobertson commented Nov 22, 2022 •
edited

Seeing a similar message (possibly a different instance?) on the main process on m.org.

022-11-22 16:07:14,207 - twisted - 274 - ERROR - replication_notifier-25517 - Traceback (most recent call last):
2022-11-22 16:07:14,211 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3
/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-11-22 16:07:14,216 - twisted - 274 - ERROR - replication_notifier-25517 -     target.close()
2022-11-22 16:07:14,220 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3
/site-packages/ijson/backends/python.py", line 116, in Lexer
2022-11-22 16:07:14,224 - twisted - 274 - ERROR - replication_notifier-25517 -     target.send(EOF)
2022-11-22 16:07:14,228 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3
/site-packages/ijson/backends/python.py", line 161, in parse_value
2022-11-22 16:07:14,232 - twisted - 274 - ERROR - replication_notifier-25517 -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-11-22 16:07:14,236 - twisted - 274 - ERROR - replication_notifier-25517 - ijson.common.IncompleteJSONError: Incomplete JSON content
2022-11-22 16:07:14,242 - twisted - 274 - ERROR - replication_notifier-25517 - Exception ignored in: <generator object utf8_encoder at 0x7f9eb
ab2edd0>
grepping for `replication_notifier-25517`: 
2022-11-22 16:07:14,052 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-25517 - Streaming: device_lists -> 5857571296
2022-11-22 16:07:14,065 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-25517 - Streaming: pushers -> 238526074
2022-11-22 16:07:14,068 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-25517 - Streaming: caches -> 700744366
2022-11-22 16:07:14,070 - twisted - 274 - ERROR - replication_notifier-25517 - Exception ignored in: <generator object utf8_encoder at 0x7f9eba6094a0>
2022-11-22 16:07:14,074 - twisted - 274 - ERROR - replication_notifier-25517 - Traceback (most recent call last):
2022-11-22 16:07:14,079 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-11-22 16:07:14,085 - twisted - 274 - ERROR - replication_notifier-25517 -     target.close()
2022-11-22 16:07:14,092 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 116, in Lexer
2022-11-22 16:07:14,097 - twisted - 274 - ERROR - replication_notifier-25517 -     target.send(EOF)
2022-11-22 16:07:14,102 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 161, in parse_value
2022-11-22 16:07:14,108 - twisted - 274 - ERROR - replication_notifier-25517 -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-11-22 16:07:14,112 - twisted - 274 - ERROR - replication_notifier-25517 - ijson.common.IncompleteJSONError: Incomplete JSON content
2022-11-22 16:07:14,116 - twisted - 274 - ERROR - replication_notifier-25517 - Exception ignored in: <generator object utf8_encoder at 0x7f9eba609270>
2022-11-22 16:07:14,122 - twisted - 274 - ERROR - replication_notifier-25517 - Traceback (most recent call last):
2022-11-22 16:07:14,127 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-11-22 16:07:14,131 - twisted - 274 - ERROR - replication_notifier-25517 -     target.close()
2022-11-22 16:07:14,136 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 116, in Lexer
2022-11-22 16:07:14,141 - twisted - 274 - ERROR - replication_notifier-25517 -     target.send(EOF)
2022-11-22 16:07:14,144 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 161, in parse_value
2022-11-22 16:07:14,149 - twisted - 274 - ERROR - replication_notifier-25517 -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-11-22 16:07:14,152 - twisted - 274 - ERROR - replication_notifier-25517 - ijson.common.IncompleteJSONError: Incomplete JSON content
2022-11-22 16:07:14,157 - twisted - 274 - ERROR - replication_notifier-25517 - Exception ignored in: <generator object utf8_encoder at 0x7f9eb8a79ba0>
2022-11-22 16:07:14,163 - twisted - 274 - ERROR - replication_notifier-25517 - Traceback (most recent call last):
2022-11-22 16:07:14,167 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-11-22 16:07:14,173 - twisted - 274 - ERROR - replication_notifier-25517 -     target.close()
2022-11-22 16:07:14,178 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 116, in Lexer
2022-11-22 16:07:14,183 - twisted - 274 - ERROR - replication_notifier-25517 -     target.send(EOF)
2022-11-22 16:07:14,186 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 161, in parse_value
2022-11-22 16:07:14,193 - twisted - 274 - ERROR - replication_notifier-25517 -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-11-22 16:07:14,198 - twisted - 274 - ERROR - replication_notifier-25517 - ijson.common.IncompleteJSONError: Incomplete JSON content
2022-11-22 16:07:14,203 - twisted - 274 - ERROR - replication_notifier-25517 - Exception ignored in: <generator object utf8_encoder at 0x7f9edf354890>
2022-11-22 16:07:14,207 - twisted - 274 - ERROR - replication_notifier-25517 - Traceback (most recent call last):
2022-11-22 16:07:14,211 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-11-22 16:07:14,216 - twisted - 274 - ERROR - replication_notifier-25517 -     target.close()
2022-11-22 16:07:14,220 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 116, in Lexer
2022-11-22 16:07:14,224 - twisted - 274 - ERROR - replication_notifier-25517 -     target.send(EOF)
2022-11-22 16:07:14,228 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 161, in parse_value
2022-11-22 16:07:14,232 - twisted - 274 - ERROR - replication_notifier-25517 -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-11-22 16:07:14,236 - twisted - 274 - ERROR - replication_notifier-25517 - ijson.common.IncompleteJSONError: Incomplete JSON content
2022-11-22 16:07:14,242 - twisted - 274 - ERROR - replication_notifier-25517 - Exception ignored in: <generator object utf8_encoder at 0x7f9ebab2edd0>
2022-11-22 16:07:14,245 - twisted - 274 - ERROR - replication_notifier-25517 - Traceback (most recent call last):
2022-11-22 16:07:14,249 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-11-22 16:07:14,253 - twisted - 274 - ERROR - replication_notifier-25517 -     target.close()
2022-11-22 16:07:14,257 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 116, in Lexer
2022-11-22 16:07:14,260 - twisted - 274 - ERROR - replication_notifier-25517 -     target.send(EOF)
2022-11-22 16:07:14,264 - twisted - 274 - ERROR - replication_notifier-25517 -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 161, in parse_value
2022-11-22 16:07:14,268 - twisted - 274 - ERROR - replication_notifier-25517 -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-11-22 16:07:14,273 - twisted - 274 - ERROR - replication_notifier-25517 - ijson.common.IncompleteJSONError: Incomplete JSON content

@DMRobertson DMRobertson changed the title Unhandled ijson exception in _maybe_retry_device_resync causing log spam Unhandled ijson exceptions in various places causing log and sentry spam Feb 19, 2023
@DMRobertson
Copy link
Contributor Author

Another example from processing an incoming /send transaction:

2023-02-19 21:58:04,644 - synapse.federation.transport.server.federation - 103 - INFO - PUT-79c24305dec878b2-VIE- - Received txn 1648753783417 from example.com. (PDUs: 0, EDUs: 2)
2023-02-19 21:58:04,647 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- - Exception ignored in: <generator object utf8_encoder at 0x7f3adf252510>
2023-02-19 21:58:04,654 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- - Traceback (most recent call last):
2023-02-19 21:58:04,662 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2023-02-19 21:58:04,667 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -     target.close()
2023-02-19 21:58:04,672 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 116, in Lexer
2023-02-19 21:58:04,676 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -     target.send(EOF)
2023-02-19 21:58:04,681 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 161, in parse_value
2023-02-19 21:58:04,687 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -     raise common.IncompleteJSONError('Incomplete JSON content')
2023-02-19 21:58:04,693 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- - ijson.common.IncompleteJSONError: Incomplete JSON content
2023-02-19 21:58:04,699 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- - Exception ignored in: <generator object utf8_encoder at 0x7f3adadfac80>
2023-02-19 21:58:04,705 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- - Traceback (most recent call last):
2023-02-19 21:58:04,711 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2023-02-19 21:58:04,717 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -     target.close()
2023-02-19 21:58:04,723 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 116, in Lexer
2023-02-19 21:58:04,730 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -     target.send(EOF)
2023-02-19 21:58:04,736 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -   File "/home/synapse/env-pyston-poetry/lib/python3.8-pyston2.3/site-packages/ijson/backends/python.py", line 161, in parse_value
2023-02-19 21:58:04,742 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- -     raise common.IncompleteJSONError('Incomplete JSON content')
2023-02-19 21:58:04,748 - twisted - 277 - ERROR - PUT-79c24305dec878b2-VIE- - ijson.common.IncompleteJSONError: Incomplete JSON content
2023-02-19 21:58:04,915 - synapse.8631_debug - 122 - DEBUG - PUT-79c24305dec878b2-VIE- - received transaction [1648753783417] including device list updates: [<removed>]
2023-02-19 21:58:05,001 - synapse.http.client - 463 - INFO - PUT-79c24305dec878b2-VIE---- - Received response to POST http://10.103.0.1:29401/_synapse/replication/fed_send_edu/m.receipt/RGnrSUeLET: 200
2023-02-19 21:58:05,090 - synapse.http.client - 463 - INFO - PUT-79c24305dec878b2-VIE---- - Received response to POST http://10.103.0.1:9092/_synapse/replication/fed_send_edu/m.device_list_update/vHexqNyInw: 200
2023-02-19 21:58:05,091 - synapse.replication.tcp.client - 372 - INFO - PUT-79c24305dec878b2-VIE--- - Waiting for repl stream 'pushers' to reach 259223516 (master)
2023-02-19 21:58:05,130 - synapse.replication.tcp.client - 384 - INFO - PUT-79c24305dec878b2-VIE--- - Finished waiting for repl stream 'pushers' to reach 259223516 (master)
2023-02-19 21:58:05,167 - synapse.access.http.15104 - 460 - INFO - PUT-79c24305dec878b2-VIE - 195.201.194.175 - 15104 - {example.com} Processed request: 0.643sec/0.003sec (0.234sec, 0.039sec) (0.021sec/0.021sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1648753783417 HTTP/1.1" "Synapse/1.51.0" [0 dbevts]

@matrixbot matrixbot mentioned this issue Dec 21, 2023
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Logging Synapse's logs (structured or otherwise). Not metrics. O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Tolerable Minor significance, cosmetic issues, low or no impact to users. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact Z-Sentry Issue was discovered by looking at Sentry reports on Matrix.org
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@squahtx @DMRobertson