Lost logcontext with antispam module

[MadLittleMods]

This issue is specifically tracking the possible logcontext problem, not the twisted.web._newclient.RequestGenerationFailed problem.

As experienced by @olmari and shared by @tulir in #synapse-dev:matrix.org

Logs

Relevant logs:

synapse.logging.context - 107 - WARNING - sentinel - Expected logging context call_later but found POST-2453

synapse.logging.context - 107 - WARNING - sentinel - Expected logging context call_later was lost

Full logs:

event_send_requests-2.log.2025-10-17-2025-10-17 23:56:37,070 - synapse_http_antispam - 75 - ERROR - POST-2453 - Error in async callback (POST http://localhost:29350/_meowlnir/antispam/!iCeEkVITYBNQSjgDxF:hacklab.fi/user_may_join_room)
event_send_requests-2.log.2025-10-17-Traceback (most recent call last):
event_send_requests-2.log.2025-10-17-  File "/opt/venvs/matrix-synapse/lib/python3.13/site-packages/synapse_http_antispam.py", line 73, in _catch_errors
event_send_requests-2.log.2025-10-17-    await task
event_send_requests-2.log.2025-10-17-  File "/opt/venvs/matrix-synapse/lib/python3.13/site-packages/synapse/http/client.py", line 564, in post_json_get_json
event_send_requests-2.log.2025-10-17-    response = await self.request(
event_send_requests-2.log.2025-10-17-               ^^^^^^^^^^^^^^^^^^^
event_send_requests-2.log.2025-10-17-        "POST", uri, headers=Headers(actual_headers), data=json_str
event_send_requests-2.log.2025-10-17-        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
event_send_requests-2.log.2025-10-17-    )
event_send_requests-2.log.2025-10-17-    ^
event_send_requests-2.log.2025-10-17-  File "/opt/venvs/matrix-synapse/lib/python3.13/site-packages/synapse/http/client.py", line 448, in request
event_send_requests-2.log.2025-10-17-    response = await make_deferred_yieldable(request_deferred)
event_send_requests-2.log.2025-10-17-               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
event_send_requests-2.log.2025-10-17-  File "/opt/venvs/matrix-synapse/lib/python3.13/site-packages/twisted/internet/defer.py", line 1187, in __iter__
event_send_requests-2.log.2025-10-17-    yield self
event_send_requests-2.log.2025-10-17-twisted.web._newclient.RequestGenerationFailed: [<twisted.python.failure.Failure twisted.internet.error.AlreadyCalled: Tried to cancel an already-called event.>]
event_send_requests-2.log.2025-10-17-2025-10-17 23:56:37,071 - synapse.logging.context - 107 - WARNING - sentinel - Expected logging context call_later but found POST-2453
event_send_requests-2.log.2025-10-17:2025-10-17 23:58:27,073 - synapse_http_antispam - 106 - ERROR - POST-2459 - Failed to connect to antispam server (POST http://localhost:29350/_meowlnir/antispam/!iCeEkVITYBNQSjgDxF:hacklab.fi/user_may_invite {'inviter': '@heisenbridge:hacklab.fi', 'invitee': '@irc_liberachat_guest54:hacklab.fi', 'room_id': '!bXWqpyKMwbfYIQWslT:hacklab.fi'})
event_send_requests-2.log.2025-10-17-Traceback (most recent call last):
event_send_requests-2.log.2025-10-17-  File "/opt/venvs/matrix-synapse/lib/python3.13/site-packages/synapse_http_antispam.py", line 84, in _do_request
event_send_requests-2.log.2025-10-17-    await task
event_send_requests-2.log.2025-10-17-  File "/opt/venvs/matrix-synapse/lib/python3.13/site-packages/synapse/http/client.py", line 564, in post_json_get_json
event_send_requests-2.log.2025-10-17-    response = await self.request(
event_send_requests-2.log.2025-10-17-               ^^^^^^^^^^^^^^^^^^^
event_send_requests-2.log.2025-10-17-        "POST", uri, headers=Headers(actual_headers), data=json_str
event_send_requests-2.log.2025-10-17-        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
event_send_requests-2.log.2025-10-17-    )
event_send_requests-2.log.2025-10-17-    ^
event_send_requests-2.log.2025-10-17-  File "/opt/venvs/matrix-synapse/lib/python3.13/site-packages/synapse/http/client.py", line 448, in request
event_send_requests-2.log.2025-10-17-    response = await make_deferred_yieldable(request_deferred)
event_send_requests-2.log.2025-10-17-               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
event_send_requests-2.log.2025-10-17-  File "/opt/venvs/matrix-synapse/lib/python3.13/site-packages/twisted/internet/defer.py", line 1187, in __iter__
event_send_requests-2.log.2025-10-17-    yield self
event_send_requests-2.log.2025-10-17-twisted.web._newclient.RequestGenerationFailed: [<twisted.python.failure.Failure twisted.internet.error.AlreadyCalled: Tried to cancel an already-called event.>]
event_send_requests-2.log.2025-10-17-2025-10-17 23:58:27,074 - synapse.logging.context - 107 - WARNING - sentinel - Expected logging context call_later was lost

Relevant code

As far as I can tell this is in the context of Meowlnir,

• Relevant synapse-http-antispam code: https://github.com/maunium/synapse-http-antispam/blob/0a28a4d201928bdc2a9e2c66c16bf0840ec0dfb6/synapse_http_antispam.py
• Meowlnir Docs: https://github.com/mautrix/docs/blob/2dd4a8e542297bd465f37afa743e64c8d84ac2fa/meowlnir/SUMMARY.md
  • Mention of synapse-http-antispam: https://github.com/mautrix/docs/blob/2dd4a8e542297bd465f37afa743e64c8d84ac2fa/meowlnir/invite-blocking.md
• Meowlnir project: https://github.com/maunium/meowlnir
• Other mention of synpase-http-antispam in the Draupnir docs: https://github.com/the-draupnir-project/draupnir-documentation/blob/965b012e59a6df78d245336c3cca1f32baa191c0/docs/bot/synapse-http-antispam.md

[tulir]

The logs are actually from @olmari

https://github.com/maunium/synapse-http-antispam/blob/0a28a4d201928bdc2a9e2c66c16bf0840ec0dfb6/synapse_http_antispam.py#L80-L84 is the call from synapse-http-antispam (the first stack trace is an async call, the second is non-async)

[olmari]

I assume goes without saying that currently for us the synpase-http-antispam module and thus it's counterpart functionality with Meowlnir is unusable as this fails and doesn't "complete" the whatever query is flying in between.

[MadLittleMods]

@olmari This issue is only tracking the logcontext problems which are harmless in terms of the app working (only logs/tracing won't be totally correct).

The underlying twisted.web._newclient.RequestGenerationFailed problems causing the timeout are a separate thing and should be tracked somewhere else like https://github.com/maunium/synapse-http-antispam

[tulir]

Synapse is probably the best place to track those too, since there haven't been any changes to synapse-http-antispam and the meowlnir server side logs sound like a client issue

[MadLittleMods]

(in any case, create a separate issue)

[MadLittleMods]

(in any case, create a separate issue)

It looks like the twisted.web._newclient.RequestGenerationFailed problem got its own issue -> #19083