TypeError: Object of type FrozenEvent is not JSON serializable

[anoadragon453]

When testing out commit d1e6333 on matrix.org today, we ended up with the following stacktrace:

stacktrace

2022-01-19 13:31:19,225 - twisted - 279 - CRITICAL - sentinel - Unhandled error in Deferred:
2022-01-19 13:31:19,237 - twisted - 279 - CRITICAL - sentinel - 
Capture point (most recent call last):
  File "/usr/local/lib/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/local/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/synapse/src/synapse/app/generic_worker.py", line 514, in <module>
    main()
  File "/home/synapse/src/synapse/app/generic_worker.py", line 510, in main
    start(sys.argv[1:])
  File "/home/synapse/src/synapse/app/generic_worker.py", line 505, in start
    _base.start_worker_reactor("synapse-generic-worker", config)
  File "/home/synapse/src/synapse/app/_base.py", line 126, in start_worker_reactor
    run_command=run_command,
  File "/home/synapse/src/synapse/app/_base.py", line 179, in start_reactor
  File "/home/synapse/src/synapse/app/_base.py", line 163, in run
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1318, in run
    self.mainLoop()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1328, in mainLoop
    reactorBaseSelf.runUntilCurrent()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 967, in runUntilCurrent
    f(*a, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 701, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 764, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 859, in _runCallbacks
    current.result, *args, **kwargs
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1751, in gotResult
    current_context.run(_inlineCallbacks, r, gen, status)
Traceback (most recent call last):
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1658, in _inlineCallbacks
    cast(Failure, result).throwExceptionIntoGenerator, gen
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/failure.py", line 500, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/synapse/src/synapse/http/server.py", line 779, in _async_write_json_to_request_in_thread
    json_str = await defer_to_thread(request.reactor, encode, span)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/threadpool.py", line 238, in inContext
    result = inContext.theWork()  # type: ignore[attr-defined]
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/threadpool.py", line 255, in <lambda>
    ctx, func, *args, **kw
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/context.py", line 83, in callWithContext
    return func(*args, **kw)
  File "/home/synapse/src/synapse/logging/context.py", line 958, in g
    return f(*args, **kwargs)
  File "/home/synapse/src/synapse/http/server.py", line 772, in encode
    res = json_encoder(json_object)
  File "/home/synapse/src/synapse/http/server.py", line 663, in _encode_json_bytes
    return json_encoder.encode(json_object).encode("utf-8")
  File "/usr/local/lib/python3.7/json/encoder.py", line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/local/lib/python3.7/json/encoder.py", line 257, in iterencode
    return _iterencode(o, 0)
  File "/home/synapse/src/synapse/util/__init__.py", line 67, in _handle_frozendict
    "Object of type %s is not JSON serializable" % obj.__class__.__name__
TypeError: Object of type FrozenEvent is not JSON serializable

Sentry link for those with access: https://sentry.matrix.org/sentry/synapse-matrixorg/issues/239798/

This issue only occurs on our client_reader workers, but does occur frequently across multiple instances of it.

Unfortunately no surrounding processed request lines are relevant. However, there do seem to be a number of replication related lines, so that may be a clue...

Note that a similar error has occurred before: #8678.

[anoadragon453]

What is known:

• Somewhere between release-v1.50.0..15ffc4143c36593bc3d899fad7fb5db00f4d95ea (commits), a commit was introduced that caused a FrozenEvent to be included in a dict that is then serialised to JSON.
• Passing a frozendict to our JSONEncoder is fine, as it has a customer serialiser which handles frozendict's:

synapse/synapse/util/__init__.py

Lines 71 to 77 in eec34b1

	# A custom JSON encoder which:
	# * handles frozendicts
	# * produces valid JSON (no NaNs etc)
	# * reduces redundant whitespace
	json_encoder = json.JSONEncoder(
	allow_nan=False, separators=(",", ":"), default=_handle_frozendict
	)

synapse/synapse/util/__init__.py

Lines 49 to 68 in eec34b1

	def _handle_frozendict(obj: Any) -> Dict[Any, Any]:
	"""Helper for json_encoder. Makes frozendicts serializable by returning
	the underlying dict
	"""
	if type(obj) is frozendict:
	# fishing the protected dict out of the object is a bit nasty,
	# but we don't really want the overhead of copying the dict.
	try:
	# Safety: we catch the AttributeError immediately below.
	# See https://github.com/matrix-org/python-canonicaljson/issues/36#issuecomment-927816293
	# for discussion on how frozendict's internals have changed over time.
	return obj._dict # type: ignore[attr-defined]
	except AttributeError:
	# When the C implementation of frozendict is used,
	# there isn't a `_dict` attribute with a dict
	# so we resort to making a copy of the frozendict
	return dict(obj)
	raise TypeError(
	"Object of type %s is not JSON serializable" % obj.__class__.__name__
	)

• However, a FrozenEvent is now being passed to this method - which causes a TypeError to be raised.
• Critical logging from this exception is lost as the stack trace isn't logged against the correct logging context. And there's no Processed request log line to help narrow it down to a given endpoint.

[anoadragon453]

Tried running this with debug logging enabled on client_reader4, which gave us https://sentry.matrix.org/sentry/synapse-matrixorg/issues/239798/events/5028451/ (plus 3 other exceptions in the logs that Sentry doesn't seem to have captured...).

I was hoping for a "Received request ..." which could help us out here, but I don't see any consistent clues between them. There's lots of events received over replication - but it's difficult to tell if that's just background noise or not.

Logging could be added to _handle_frozendict, though it presumably would also get lost. We could include the event's contents in the TypeError, though that's also probably not too helpful. ...can we shove a traceback in the TypeError?

[clokep]

This is a regression from #11612, by the way.