Unhandled ijson exceptions in various places causing log and sentry spam

[DMRobertson]

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]

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]

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

I wonder if:

• the logging contexts in the error messages are incorrect?
• and whether a non-Exception exception can be raised out of coro.close(), which would be missed by Always close _all_ ijson coroutines, even if doing so raises Exceptions #14065?
  

  synapse/synapse/federation/transport/client.py

  Lines 986 to 990 in cb20b88

  	for c in coros:
  	try:
  	c.close()
  	except Exception as e:
  	exceptions.append(e)

  
  There's a list of them here. None of them seem very plausible though.

[DMRobertson]

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]

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]