Close ijson coroutines ourselves instead of letting the GC close them

[squahtx]

Hopefully this means that exceptions raised due to truncated JSON
get a sensible logging context and stack.

Signed-off-by: Sean Quah [email protected]

---

On matrix.org sentry, we are seeing a lot of Exception ignored in: <generator object utf8_encoder at 0x7f87c9b1ccf0> errors without a proper stack trace or logging context.

Digging into the logs, we find something like:

2022-05-25 05:15:16,092 - twisted - 279 - ERROR - sentinel - Exception ignored in: <generator object utf8_encoder at 0x7ff6c944b6d0>
2022-05-25 05:15:16,093 - twisted - 279 - ERROR - sentinel - Traceback (most recent call last):
2022-05-25 05:15:16,095 - twisted - 279 - ERROR - sentinel -   File "/.../site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-05-25 05:15:16,098 - twisted - 279 - ERROR - sentinel -     target.close()
2022-05-25 05:15:16,099 - twisted - 279 - ERROR - sentinel -   File "/.../site-packages/ijson/backends/python.py", line 116, in Lexer
2022-05-25 05:15:16,100 - twisted - 279 - ERROR - sentinel -     target.send(EOF)
2022-05-25 05:15:16,101 - twisted - 279 - ERROR - sentinel -   File "/.../site-packages/ijson/backends/python.py", line 161, in parse_value
2022-05-25 05:15:16,102 - twisted - 279 - ERROR - sentinel -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-05-25 05:15:16,103 - twisted - 279 - ERROR - sentinel - ijson.common.IncompleteJSONError: Incomplete JSON content
2022-05-25 05:15:16,104 - twisted - 279 - ERROR - sentinel - Exception ignored in: <generator object utf8_encoder at 0x7ff614ca97b0>
2022-05-25 05:15:16,105 - twisted - 279 - ERROR - sentinel - Traceback (most recent call last):
2022-05-25 05:15:16,106 - twisted - 279 - ERROR - sentinel -   File "/.../site-packages/ijson/backends/python.py", line 46, in utf8_encoder
2022-05-25 05:15:16,107 - twisted - 279 - ERROR - sentinel -     target.close()
2022-05-25 05:15:16,108 - twisted - 279 - ERROR - sentinel -   File "/.../site-packages/ijson/backends/python.py", line 116, in Lexer
2022-05-25 05:15:16,110 - twisted - 279 - ERROR - sentinel -     target.send(EOF)
2022-05-25 05:15:16,111 - twisted - 279 - ERROR - sentinel -   File "/.../site-packages/ijson/backends/python.py", line 161, in parse_value
2022-05-25 05:15:16,112 - twisted - 279 - ERROR - sentinel -     raise common.IncompleteJSONError('Incomplete JSON content')
2022-05-25 05:15:16,113 - twisted - 279 - ERROR - sentinel - ijson.common.IncompleteJSONError: Incomplete JSON content

Which I think is happening when Python garbage collects / frees ijson coroutines and throws a GeneratorExit into them.
So let's call close() ourselves to have the exception raised upfront.

Note that the ijson examples all include an explicit close() call:
https://pypi.org/project/ijson/#push-interfaces

[clokep]

Seems like an improvement, but I think these won't be closed in situations where we don't call parser.finish(), e.g. a timeout, response, etc.

See

synapse/synapse/http/matrixfederationclient.py

Lines 236 to 285 in 8afb7b5

	value = parser.finish()
	except BodyExceededMaxSize as e:
	# The response was too big.
	logger.warning(
	"{%s} [%s] JSON response exceeded max size %i - %s %s",
	request.txn_id,
	request.destination,
	MAX_RESPONSE_SIZE,
	request.method,
	request.uri.decode("ascii"),
	)
	raise RequestSendFailed(e, can_retry=False) from e
	except ValueError as e:
	# The content was invalid.
	logger.warning(
	"{%s} [%s] Failed to parse response - %s %s",
	request.txn_id,
	request.destination,
	request.method,
	request.uri.decode("ascii"),
	)
	raise RequestSendFailed(e, can_retry=False) from e
	except defer.TimeoutError as e:
	logger.warning(
	"{%s} [%s] Timed out reading response - %s %s",
	request.txn_id,
	request.destination,
	request.method,
	request.uri.decode("ascii"),
	)
	raise RequestSendFailed(e, can_retry=True) from e
	except ResponseFailed as e:
	logger.warning(
	"{%s} [%s] Failed to read response - %s %s",
	request.txn_id,
	request.destination,
	request.method,
	request.uri.decode("ascii"),
	)
	raise RequestSendFailed(e, can_retry=True) from e
	except Exception as e:
	logger.warning(
	"{%s} [%s] Error reading response %s %s: %s",
	request.txn_id,
	request.destination,
	request.method,
	request.uri.decode("ascii"),
	e,
	)
	raise

; not sure if we can refactor that or not?

I'm going to approve since I think this is an improvement.

[squahtx]

Seems like an improvement, but I think these won't be closed in situations where we don't call parser.finish(), e.g. a timeout, response, etc.

Yuck, that's a good point. I'll have to think about this a little.

Updated some code to always call .finish()

[reivilibre]

Looks reasonable to me — thanks for adding the clean-up :)

[squahtx]

The failing sytests are due to CI using develop. The failing tests have been changed recently on develop and pass on the release-v1.60 branch locally.

[squahtx]

This'll only close the first ijson coroutine if it raises an IncompleteJSONError.