synapse
synapse copied to clipboard
element-hq
Synapse v1.142.0 logging context warnings
Hi :) I can see a lot of logs like that :
2025-11-11 11:44:15,898 - synapse.logging.context - 105 - WARNING - - run_in_background(UcxFX): deferred already completed but the function did not maintain the calling logcontext call_later (found sentinel)
2025-11-11 11:44:15,899 - synapse.logging.context - 105 - WARNING - - Expected logging context call_later was lost
2025-11-11 11:45:32,895 - synapse.logging.context - 105 - WARNING - - run_in_background(HtziJ): deferred already completed but the function did not maintain the calling logcontext call_later (found sentinel)
2025-11-11 11:45:32,895 - synapse.logging.context - 105 - WARNING - - Expected logging context call_later was lost
2025-11-11 11:46:55,987 - synapse.logging.context - 105 - WARNING - - run_in_background(YzuBw): deferred already completed but the function did not maintain the calling logcontext call_later (found sentinel)
2025-11-11 11:46:55,988 - synapse.logging.context - 105 - WARNING - - Expected logging context call_later was lost
I did see that there is some work done on this subject in https://github.com/element-hq/synapse/pull/19090 and https://github.com/element-hq/synapse/pull/19108
Synapse v1.142.0
In https://github.com/element-hq/synapse/pull/19090 (shipped in Synapse v1.142.0), we added a warning to detect when our assumptions are being broken. So this kind of thing was happening before Synapse v1.142.0, it just wasn't being called out. To give some peace of mind, the warnings are harmless in terms of the app working (only logs/tracing won't be totally correct).
I would need more surrounding context in the logs to determine what's causing this (provide more logs).
Any obvious way to reproduce and trigger this?
Hi, thanks for answering ^^
I'm running synapse in a K8s cluster as a deployment, so, from the OCI image : docker.io/matrixdotorg/synapse:v1.142.0
I don't really have more logs than pages of :
2025-11-12 20:26:05,895 - synapse.logging.context - 105 - WARNING - - run_in_background(PopxM): deferred already completed but the function did not maintain the calling logcontext call_later (found sentinel)
2025-11-12 20:26:05,896 - synapse.logging.context - 105 - WARNING - - Expected logging context call_later was lost
2025-11-12 20:26:20,661 - synapse.logging.context - 105 - WARNING - - run_in_background(IWged): deferred already completed but the function did not maintain the calling logcontext call_later (found sentinel)
2025-11-12 20:26:20,662 - synapse.logging.context - 105 - WARNING - - Expected logging context call_later was lost
2025-11-12 20:26:25,437 - synapse.logging.context - 105 - WARNING - - run_in_background(BIBVQ): deferred already completed but the function did not maintain the calling logcontext call_later (found sentinel)
that said, Synapse seems to work well ...
[edit remove useless lines]
@Nemric Can you try enabling logging for synapse.logging.context.debug for a second while this happens? It will be very noisy, so you can disable it again as soon as you copy-paste some logs:
loggers:
synapse.storage.SQL:
# beware: increasing this to DEBUG will make synapse log sensitive
# information such as access tokens.
level: INFO
synapse.logging.context.debug:
level: DEBUG
It may or may not capture something obvious. What we really want to see is what's calling clock.call_later(...) which I've created a PR to add the necessary debug logs for (https://github.com/element-hq/synapse/pull/19173). If you know how to run Synapse from a branch, you could also try that out but I'm guessing that may be tricky if you're using Kubernetes.
Hi, I did run synapse with DEBUG logging level, I then get some WARNING and select from logs what happen between 2 of them :
More logs
2025-11-13 11:41:07,756 - synapse.logging.context - 105 - WARNING - - run_in_background(CZbga): deferred already completed but the function did not maintain the calling logcontext call_later (found sentinel)
2025-11-13 11:41:07,756 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(mBOMJ).__exit sentinel --> sentinel
2025-11-13 11:41:07,756 - synapse.logging.context - 105 - WARNING - - Expected logging context call_later was lost
2025-11-13 11:41:08,048 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(XtUuR): restoring calling logcontext to federation_transaction_transmission_loop-223
2025-11-13 11:41:08,048 - synapse.logging.context.debug - 990 - DEBUG - federation_transaction_transmission_loop-223 - run_in_background(iwXXM): resetting logcontext to sentinel
2025-11-13 11:41:08,341 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(jpDIA).__enter__ sentinel --> call_later
2025-11-13 11:41:08,341 - synapse.logging.context.debug - 896 - DEBUG - call_later - run_in_background(sqevQ): called with logcontext=call_later
2025-11-13 11:41:08,342 - synapse.logging.context.debug - 950 - DEBUG - call_later - run_in_background(sqevQ): deferred already completed (maintained the calling logcontext call_later)
2025-11-13 11:41:08,342 - synapse.logging.context.debug - 709 - DEBUG - call_later - PreserveLoggingContext(jpDIA).__exit call_later --> sentinel
2025-11-13 11:41:08,436 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(oudaN).__enter__ sentinel --> looping_call
2025-11-13 11:41:08,436 - synapse.logging.context.debug - 896 - DEBUG - looping_call - run_in_background(FZCog): called with logcontext=looping_call
2025-11-13 11:41:08,437 - synapse.logging.context.debug - 950 - DEBUG - looping_call - run_in_background(FZCog): deferred already completed (maintained the calling logcontext looping_call)
2025-11-13 11:41:08,437 - synapse.logging.context.debug - 709 - DEBUG - looping_call - PreserveLoggingContext(oudaN).__exit looping_call --> sentinel
2025-11-13 11:41:08,650 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(BkCfE).__enter__ sentinel --> looping_call
2025-11-13 11:41:08,650 - synapse.logging.context.debug - 896 - DEBUG - looping_call - run_in_background(oAyKk): called with logcontext=looping_call
2025-11-13 11:41:08,650 - synapse.logging.context.debug - 695 - DEBUG - looping_call - PreserveLoggingContext(NGupJ).__enter__ looping_call --> sentinel
2025-11-13 11:41:08,651 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(_reap_stale_read_write_locks-13).__enter__
2025-11-13 11:41:08,652 - synapse.logging.context.debug - 1058 - DEBUG - _reap_stale_read_write_locks-13 - make_deferred_yieldable(cQSxc): called with logcontext=_reap_stale_read_write_locks-13
2025-11-13 11:41:08,652 - synapse.logging.context.debug - 1084 - DEBUG - _reap_stale_read_write_locks-13 - make_deferred_yieldable(cQSxc): resetting logcontext to sentinel
2025-11-13 11:41:08,652 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(_reap_stale_read_write_locks-13).__enter__
2025-11-13 11:41:08,653 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(NGupJ).__exit sentinel --> looping_call
2025-11-13 11:41:08,654 - synapse.logging.context.debug - 965 - DEBUG - looping_call - run_in_background(oAyKk): restoring calling logcontext looping_call
2025-11-13 11:41:08,655 - synapse.logging.context.debug - 709 - DEBUG - looping_call - PreserveLoggingContext(BkCfE).__exit looping_call --> sentinel
2025-11-13 11:41:08,656 - synapse.logging.context.debug - 403 - DEBUG - _reap_stale_read_write_locks-13 - LoggingContext(_reap_stale_read_write_locks-13).__exit__ --> sentinel
2025-11-13 11:41:08,657 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(cQSxc): restoring calling logcontext to _reap_stale_read_write_locks-13
2025-11-13 11:41:08,658 - synapse.logging.context.debug - 403 - DEBUG - _reap_stale_read_write_locks-13 - LoggingContext(_reap_stale_read_write_locks-13).__exit__ --> sentinel
2025-11-13 11:41:08,658 - synapse.logging.context.debug - 990 - DEBUG - - run_in_background(oAyKk): resetting logcontext to sentinel
2025-11-13 11:41:09,098 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(VIAGd).__enter__ sentinel --> call_later
2025-11-13 11:41:09,098 - synapse.logging.context.debug - 896 - DEBUG - call_later - run_in_background(cAgfC): called with logcontext=call_later
2025-11-13 11:41:09,099 - synapse.logging.context.debug - 950 - DEBUG - call_later - run_in_background(cAgfC): deferred already completed (maintained the calling logcontext call_later)
2025-11-13 11:41:09,099 - synapse.logging.context.debug - 709 - DEBUG - call_later - PreserveLoggingContext(VIAGd).__exit call_later --> sentinel
2025-11-13 11:41:09,436 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(aYhFY).__enter__ sentinel --> looping_call
2025-11-13 11:41:09,436 - synapse.logging.context.debug - 896 - DEBUG - looping_call - run_in_background(JbHVi): called with logcontext=looping_call
2025-11-13 11:41:09,436 - synapse.logging.context.debug - 950 - DEBUG - looping_call - run_in_background(JbHVi): deferred already completed (maintained the calling logcontext looping_call)
2025-11-13 11:41:09,436 - synapse.logging.context.debug - 709 - DEBUG - looping_call - PreserveLoggingContext(aYhFY).__exit looping_call --> sentinel
2025-11-13 11:41:09,636 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(QDMed).__enter__ sentinel --> PUT-232
2025-11-13 11:41:09,637 - synapse.logging.context.debug - 896 - DEBUG - PUT-232 - run_in_background(nfVyP): called with logcontext=PUT-232
2025-11-13 11:41:09,638 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(sRMwG).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,639 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(keyring_server-113).__enter__
2025-11-13 11:41:09,640 - synapse.logging.context.debug - 695 - DEBUG - keyring_server-113 - PreserveLoggingContext(HONRR).__enter__ keyring_server-113 --> sentinel
2025-11-13 11:41:09,640 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(sRMwG).__exit sentinel --> PUT-232
2025-11-13 11:41:09,641 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(sNwrd): called with logcontext=PUT-232
2025-11-13 11:41:09,642 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(sNwrd): resetting logcontext to sentinel
2025-11-13 11:41:09,642 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(nfVyP): restoring calling logcontext PUT-232
2025-11-13 11:41:09,643 - synapse.logging.context.debug - 709 - DEBUG - PUT-232 - PreserveLoggingContext(QDMed).__exit PUT-232 --> sentinel
2025-11-13 11:41:09,644 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(HONRR).__exit sentinel --> keyring_server-113
2025-11-13 11:41:09,644 - synapse.logging.context.debug - 896 - DEBUG - keyring_server-113 - run_in_background(arAUk): called with logcontext=keyring_server-113
2025-11-13 11:41:09,645 - synapse.logging.context.debug - 695 - DEBUG - keyring_server-113 - PreserveLoggingContext(CyQif).__enter__ keyring_server-113 --> sentinel
2025-11-13 11:41:09,646 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(StoreKeyFetcher-106).__enter__
2025-11-13 11:41:09,647 - synapse.logging.context.debug - 695 - DEBUG - StoreKeyFetcher-106 - PreserveLoggingContext(dSdmL).__enter__ StoreKeyFetcher-106 --> sentinel
2025-11-13 11:41:09,647 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(CyQif).__exit sentinel --> keyring_server-113
2025-11-13 11:41:09,648 - synapse.logging.context.debug - 1058 - DEBUG - keyring_server-113 - make_deferred_yieldable(MMeAy): called with logcontext=keyring_server-113
2025-11-13 11:41:09,648 - synapse.logging.context.debug - 1084 - DEBUG - keyring_server-113 - make_deferred_yieldable(MMeAy): resetting logcontext to sentinel
2025-11-13 11:41:09,649 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(arAUk): restoring calling logcontext keyring_server-113
2025-11-13 11:41:09,650 - synapse.logging.context.debug - 1058 - DEBUG - keyring_server-113 - make_deferred_yieldable(rxftp): called with logcontext=keyring_server-113
2025-11-13 11:41:09,650 - synapse.logging.context.debug - 1084 - DEBUG - keyring_server-113 - make_deferred_yieldable(rxftp): resetting logcontext to sentinel
2025-11-13 11:41:09,650 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(dSdmL).__exit sentinel --> StoreKeyFetcher-106
2025-11-13 11:41:09,652 - synapse.logging.context.debug - 896 - DEBUG - StoreKeyFetcher-106 - run_in_background(KLifW): called with logcontext=StoreKeyFetcher-106
2025-11-13 11:41:09,652 - synapse.logging.context.debug - 1058 - DEBUG - StoreKeyFetcher-106 - make_deferred_yieldable(bzaxu): called with logcontext=StoreKeyFetcher-106
2025-11-13 11:41:09,653 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(StoreKeyFetcher-106).__enter__
2025-11-13 11:41:09,653 - synapse.logging.context.debug - 1084 - DEBUG - StoreKeyFetcher-106 - make_deferred_yieldable(bzaxu): resetting logcontext to sentinel
2025-11-13 11:41:09,655 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(KLifW): restoring calling logcontext StoreKeyFetcher-106
2025-11-13 11:41:09,656 - synapse.logging.context.debug - 1058 - DEBUG - StoreKeyFetcher-106 - make_deferred_yieldable(brIkr): called with logcontext=StoreKeyFetcher-106
2025-11-13 11:41:09,657 - synapse.logging.context.debug - 1084 - DEBUG - StoreKeyFetcher-106 - make_deferred_yieldable(brIkr): resetting logcontext to sentinel
2025-11-13 11:41:09,659 - synapse.logging.context.debug - 403 - DEBUG - StoreKeyFetcher-106 - LoggingContext(StoreKeyFetcher-106).__exit__ --> sentinel
2025-11-13 11:41:09,660 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(bzaxu): restoring calling logcontext to StoreKeyFetcher-106
2025-11-13 11:41:09,661 - synapse.logging.context.debug - 990 - DEBUG - StoreKeyFetcher-106 - run_in_background(KLifW): resetting logcontext to sentinel
2025-11-13 11:41:09,661 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(brIkr): restoring calling logcontext to StoreKeyFetcher-106
2025-11-13 11:41:09,662 - synapse.logging.context.debug - 695 - DEBUG - StoreKeyFetcher-106 - PreserveLoggingContext(vNbTl).__enter__ StoreKeyFetcher-106 --> sentinel
2025-11-13 11:41:09,662 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(MMeAy): restoring calling logcontext to keyring_server-113
2025-11-13 11:41:09,663 - synapse.logging.context.debug - 990 - DEBUG - keyring_server-113 - run_in_background(arAUk): resetting logcontext to sentinel
2025-11-13 11:41:09,664 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(rxftp): restoring calling logcontext to keyring_server-113
2025-11-13 11:41:09,664 - synapse.logging.context.debug - 695 - DEBUG - keyring_server-113 - PreserveLoggingContext(LWmAr).__enter__ keyring_server-113 --> sentinel
2025-11-13 11:41:09,665 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(sNwrd): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,666 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(KgatE): called with logcontext=PUT-232
2025-11-13 11:41:09,667 - synapse.logging.context.debug - 1068 - DEBUG - PUT-232 - make_deferred_yieldable(KgatE): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,667 - synapse.logging.context.debug - 896 - DEBUG - PUT-232 - run_in_background(XkmVz): called with logcontext=PUT-232
2025-11-13 11:41:09,668 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(IzpJZ): called with logcontext=PUT-232
2025-11-13 11:41:09,669 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,669 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(IzpJZ): resetting logcontext to sentinel
2025-11-13 11:41:09,671 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(XkmVz): restoring calling logcontext PUT-232
2025-11-13 11:41:09,671 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(ozPvC): called with logcontext=PUT-232
2025-11-13 11:41:09,672 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(ozPvC): resetting logcontext to sentinel
2025-11-13 11:41:09,672 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(LWmAr).__exit sentinel --> keyring_server-113
2025-11-13 11:41:09,673 - synapse.logging.context.debug - 695 - DEBUG - keyring_server-113 - PreserveLoggingContext(YmfRq).__enter__ keyring_server-113 --> sentinel
2025-11-13 11:41:09,673 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(vNbTl).__exit sentinel --> StoreKeyFetcher-106
2025-11-13 11:41:09,673 - synapse.logging.context.debug - 695 - DEBUG - StoreKeyFetcher-106 - PreserveLoggingContext(TfPzc).__enter__ StoreKeyFetcher-106 --> sentinel
2025-11-13 11:41:09,674 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(YmfRq).__exit sentinel --> keyring_server-113
2025-11-13 11:41:09,675 - synapse.logging.context.debug - 403 - DEBUG - keyring_server-113 - LoggingContext(keyring_server-113).__exit__ --> sentinel
2025-11-13 11:41:09,677 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(TfPzc).__exit sentinel --> StoreKeyFetcher-106
2025-11-13 11:41:09,678 - synapse.logging.context.debug - 403 - DEBUG - StoreKeyFetcher-106 - LoggingContext(StoreKeyFetcher-106).__exit__ --> sentinel
2025-11-13 11:41:09,677 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> sentinel
2025-11-13 11:41:09,681 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(IzpJZ): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,681 - synapse.logging.context.debug - 896 - DEBUG - PUT-232 - run_in_background(ZCxLT): called with logcontext=PUT-232
2025-11-13 11:41:09,682 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(nJNjl): called with logcontext=PUT-232
2025-11-13 11:41:09,682 - synapse.logging.context.debug - 1068 - DEBUG - PUT-232 - make_deferred_yieldable(nJNjl): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,683 - synapse.logging.context.debug - 950 - DEBUG - PUT-232 - run_in_background(ZCxLT): deferred already completed (maintained the calling logcontext PUT-232)
2025-11-13 11:41:09,684 - synapse.logging.context.debug - 896 - DEBUG - PUT-232 - run_in_background(zAeYg): called with logcontext=PUT-232
2025-11-13 11:41:09,686 - synapse.logging.context.debug - 896 - DEBUG - PUT-232 - run_in_background(YWWZR): called with logcontext=PUT-232
2025-11-13 11:41:09,687 - synapse.logging.context.debug - 896 - DEBUG - PUT-232 - run_in_background(dEPzL): called with logcontext=PUT-232
2025-11-13 11:41:09,688 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(qVDPY): called with logcontext=PUT-232
2025-11-13 11:41:09,688 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(qVDPY): resetting logcontext to sentinel
2025-11-13 11:41:09,688 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(dEPzL): restoring calling logcontext PUT-232
2025-11-13 11:41:09,688 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(nNetO): called with logcontext=PUT-232
2025-11-13 11:41:09,689 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(nNetO): resetting logcontext to sentinel
2025-11-13 11:41:09,689 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(YWWZR): restoring calling logcontext PUT-232
2025-11-13 11:41:09,689 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(qZYpz): called with logcontext=PUT-232
2025-11-13 11:41:09,689 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(qZYpz): resetting logcontext to sentinel
2025-11-13 11:41:09,689 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(zAeYg): restoring calling logcontext PUT-232
2025-11-13 11:41:09,690 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(njAVM): called with logcontext=PUT-232
2025-11-13 11:41:09,690 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(njAVM): resetting logcontext to sentinel
2025-11-13 11:41:09,691 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,693 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> sentinel
2025-11-13 11:41:09,695 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(qVDPY): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,696 - synapse.logging.context.debug - 990 - DEBUG - PUT-232 - run_in_background(dEPzL): resetting logcontext to sentinel
2025-11-13 11:41:09,696 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(nNetO): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,697 - synapse.logging.context.debug - 380 - DEBUG - PUT-232 - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,698 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(hXkVK): called with logcontext=PUT-232
2025-11-13 11:41:09,699 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,699 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(hXkVK): resetting logcontext to sentinel
2025-11-13 11:41:09,702 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> sentinel
2025-11-13 11:41:09,703 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(hXkVK): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,704 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(PCqBj): called with logcontext=PUT-232
2025-11-13 11:41:09,704 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(PCqBj): resetting logcontext to sentinel
2025-11-13 11:41:09,705 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,720 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> sentinel
2025-11-13 11:41:09,721 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(PCqBj): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,721 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(qnlTZ).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,722 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(user_directory.notify_new_event-162).__enter__
2025-11-13 11:41:09,722 - synapse.logging.context.debug - 380 - DEBUG - user_directory.notify_new_event-162 - LoggingContext(user_directory.notify_new_event-162).__enter__
2025-11-13 11:41:09,722 - synapse.logging.context.debug - 403 - DEBUG - user_directory.notify_new_event-162 - LoggingContext(user_directory.notify_new_event-162).__exit__ --> user_directory.notify_new_event-162
2025-11-13 11:41:09,723 - synapse.logging.context.debug - 403 - DEBUG - user_directory.notify_new_event-162 - LoggingContext(user_directory.notify_new_event-162).__exit__ --> sentinel
2025-11-13 11:41:09,723 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(qnlTZ).__exit sentinel --> PUT-232
2025-11-13 11:41:09,723 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(rooaR).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,724 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(presence.notify_new_event-165).__enter__
2025-11-13 11:41:09,724 - synapse.logging.context.debug - 380 - DEBUG - presence.notify_new_event-165 - LoggingContext(presence.notify_new_event-165).__enter__
2025-11-13 11:41:09,724 - synapse.logging.context.debug - 403 - DEBUG - presence.notify_new_event-165 - LoggingContext(presence.notify_new_event-165).__exit__ --> presence.notify_new_event-165
2025-11-13 11:41:09,725 - synapse.logging.context.debug - 403 - DEBUG - presence.notify_new_event-165 - LoggingContext(presence.notify_new_event-165).__exit__ --> sentinel
2025-11-13 11:41:09,726 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(rooaR).__exit sentinel --> PUT-232
2025-11-13 11:41:09,726 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(fPQCC).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,727 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(replication_notifier-79).__enter__
2025-11-13 11:41:09,727 - synapse.logging.context.debug - 380 - DEBUG - replication_notifier-79 - LoggingContext(replication_notifier-79).__enter__
2025-11-13 11:41:09,728 - synapse.logging.context.debug - 1058 - DEBUG - replication_notifier-79 - make_deferred_yieldable(VPxwt): called with logcontext=replication_notifier-79
2025-11-13 11:41:09,728 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(replication_notifier-79).__enter__
2025-11-13 11:41:09,728 - synapse.logging.context.debug - 1084 - DEBUG - replication_notifier-79 - make_deferred_yieldable(VPxwt): resetting logcontext to sentinel
2025-11-13 11:41:09,729 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(fPQCC).__exit sentinel --> PUT-232
2025-11-13 11:41:09,730 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(nSTdV).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,730 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(room_forgetter.notify_new_event-53).__enter__
2025-11-13 11:41:09,730 - synapse.logging.context.debug - 695 - DEBUG - room_forgetter.notify_new_event-53 - PreserveLoggingContext(yGQJR).__enter__ room_forgetter.notify_new_event-53 --> sentinel
2025-11-13 11:41:09,730 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(nSTdV).__exit sentinel --> PUT-232
2025-11-13 11:41:09,731 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(FoRbd).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,731 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(stats.notify_new_event-162).__enter__
2025-11-13 11:41:09,731 - synapse.logging.context.debug - 403 - DEBUG - stats.notify_new_event-162 - LoggingContext(stats.notify_new_event-162).__exit__ --> sentinel
2025-11-13 11:41:09,732 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(FoRbd).__exit sentinel --> PUT-232
2025-11-13 11:41:09,733 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(pIZHx).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,733 - synapse.logging.context.debug - 403 - DEBUG - replication_notifier-79 - LoggingContext(replication_notifier-79).__exit__ --> sentinel
2025-11-13 11:41:09,734 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(delayed_events.notify_new_event-109).__enter__
2025-11-13 11:41:09,735 - synapse.logging.context.debug - 1058 - DEBUG - delayed_events.notify_new_event-109 - make_deferred_yieldable(nTtgi): called with logcontext=delayed_events.notify_new_event-109
2025-11-13 11:41:09,736 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(delayed_events.notify_new_event-109).__enter__
2025-11-13 11:41:09,736 - synapse.logging.context.debug - 1084 - DEBUG - delayed_events.notify_new_event-109 - make_deferred_yieldable(nTtgi): resetting logcontext to sentinel
2025-11-13 11:41:09,737 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(pIZHx).__exit sentinel --> PUT-232
2025-11-13 11:41:09,737 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(cnfiu): called with logcontext=PUT-232
2025-11-13 11:41:09,737 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(cnfiu): resetting logcontext to sentinel
2025-11-13 11:41:09,738 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(VPxwt): restoring calling logcontext to replication_notifier-79
2025-11-13 11:41:09,739 - synapse.logging.context.debug - 695 - DEBUG - replication_notifier-79 - PreserveLoggingContext(OMDOh).__enter__ replication_notifier-79 --> sentinel
2025-11-13 11:41:09,739 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(send-cmd-137).__enter__
2025-11-13 11:41:09,738 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,740 - synapse.logging.context.debug - 403 - DEBUG - delayed_events.notify_new_event-109 - LoggingContext(delayed_events.notify_new_event-109).__exit__ --> sentinel
2025-11-13 11:41:09,740 - synapse.logging.context.debug - 1058 - DEBUG - send-cmd-137 - make_deferred_yieldable(iitop): called with logcontext=send-cmd-137
2025-11-13 11:41:09,741 - synapse.logging.context.debug - 1084 - DEBUG - send-cmd-137 - make_deferred_yieldable(iitop): resetting logcontext to sentinel
2025-11-13 11:41:09,742 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(OMDOh).__exit sentinel --> replication_notifier-79
2025-11-13 11:41:09,742 - synapse.logging.context.debug - 403 - DEBUG - replication_notifier-79 - LoggingContext(replication_notifier-79).__exit__ --> replication_notifier-79
2025-11-13 11:41:09,743 - synapse.logging.context.debug - 403 - DEBUG - replication_notifier-79 - LoggingContext(replication_notifier-79).__exit__ --> sentinel
2025-11-13 11:41:09,744 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(nTtgi): restoring calling logcontext to delayed_events.notify_new_event-109
2025-11-13 11:41:09,744 - synapse.logging.context.debug - 1058 - DEBUG - delayed_events.notify_new_event-109 - make_deferred_yieldable(lHOYJ): called with logcontext=delayed_events.notify_new_event-109
2025-11-13 11:41:09,744 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(delayed_events.notify_new_event-109).__enter__
2025-11-13 11:41:09,745 - synapse.logging.context.debug - 1084 - DEBUG - delayed_events.notify_new_event-109 - make_deferred_yieldable(lHOYJ): resetting logcontext to sentinel
2025-11-13 11:41:09,746 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(iitop): restoring calling logcontext to send-cmd-137
2025-11-13 11:41:09,746 - synapse.logging.context.debug - 403 - DEBUG - send-cmd-137 - LoggingContext(send-cmd-137).__exit__ --> sentinel
2025-11-13 11:41:09,747 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(GvGBT).__enter__ sentinel --> replication_command_handler-139997137051840
2025-11-13 11:41:09,748 - synapse.logging.context.debug - 709 - DEBUG - replication_command_handler-139997137051840 - PreserveLoggingContext(GvGBT).__exit replication_command_handler-139997137051840 --> sentinel
2025-11-13 11:41:09,749 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> sentinel
2025-11-13 11:41:09,749 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(cnfiu): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,750 - synapse.logging.context.debug - 896 - DEBUG - PUT-232 - run_in_background(nylNo): called with logcontext=PUT-232
2025-11-13 11:41:09,751 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(tSehl): called with logcontext=PUT-232
2025-11-13 11:41:09,752 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,752 - synapse.logging.context.debug - 403 - DEBUG - delayed_events.notify_new_event-109 - LoggingContext(delayed_events.notify_new_event-109).__exit__ --> sentinel
2025-11-13 11:41:09,752 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(tSehl): resetting logcontext to sentinel
2025-11-13 11:41:09,754 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(nylNo): restoring calling logcontext PUT-232
2025-11-13 11:41:09,754 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(GMBop): called with logcontext=PUT-232
2025-11-13 11:41:09,755 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(GMBop): resetting logcontext to sentinel
2025-11-13 11:41:09,756 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(lHOYJ): restoring calling logcontext to delayed_events.notify_new_event-109
2025-11-13 11:41:09,757 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> sentinel
2025-11-13 11:41:09,757 - synapse.logging.context.debug - 403 - DEBUG - delayed_events.notify_new_event-109 - LoggingContext(delayed_events.notify_new_event-109).__exit__ --> sentinel
2025-11-13 11:41:09,758 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(tSehl): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,759 - synapse.logging.context.debug - 990 - DEBUG - PUT-232 - run_in_background(nylNo): resetting logcontext to sentinel
2025-11-13 11:41:09,760 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(GMBop): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,761 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(mATUK).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,761 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(BVyqj).__exit sentinel --> GET-231
2025-11-13 11:41:09,762 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(cVbkV): called with logcontext=GET-231
2025-11-13 11:41:09,762 - synapse.logging.context.debug - 1068 - DEBUG - GET-231 - make_deferred_yieldable(cVbkV): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,763 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(cGyQS): called with logcontext=GET-231
2025-11-13 11:41:09,764 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(GET-231).__enter__
2025-11-13 11:41:09,764 - synapse.logging.context.debug - 1084 - DEBUG - GET-231 - make_deferred_yieldable(cGyQS): resetting logcontext to sentinel
2025-11-13 11:41:09,765 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(mATUK).__exit sentinel --> PUT-232
2025-11-13 11:41:09,765 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(lACWT).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,766 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(user_directory.notify_new_event-163).__enter__
2025-11-13 11:41:09,766 - synapse.logging.context.debug - 380 - DEBUG - user_directory.notify_new_event-163 - LoggingContext(user_directory.notify_new_event-163).__enter__
2025-11-13 11:41:09,767 - synapse.logging.context.debug - 403 - DEBUG - user_directory.notify_new_event-163 - LoggingContext(user_directory.notify_new_event-163).__exit__ --> user_directory.notify_new_event-163
2025-11-13 11:41:09,767 - synapse.logging.context.debug - 403 - DEBUG - user_directory.notify_new_event-163 - LoggingContext(user_directory.notify_new_event-163).__exit__ --> sentinel
2025-11-13 11:41:09,768 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(lACWT).__exit sentinel --> PUT-232
2025-11-13 11:41:09,769 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(EnUjJ).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,769 - synapse.logging.context.debug - 403 - DEBUG - GET-231 - LoggingContext(GET-231).__exit__ --> sentinel
2025-11-13 11:41:09,770 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(presence.notify_new_event-166).__enter__
2025-11-13 11:41:09,771 - synapse.logging.context.debug - 380 - DEBUG - presence.notify_new_event-166 - LoggingContext(presence.notify_new_event-166).__enter__
2025-11-13 11:41:09,771 - synapse.logging.context.debug - 403 - DEBUG - presence.notify_new_event-166 - LoggingContext(presence.notify_new_event-166).__exit__ --> presence.notify_new_event-166
2025-11-13 11:41:09,772 - synapse.logging.context.debug - 403 - DEBUG - presence.notify_new_event-166 - LoggingContext(presence.notify_new_event-166).__exit__ --> sentinel
2025-11-13 11:41:09,773 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(EnUjJ).__exit sentinel --> PUT-232
2025-11-13 11:41:09,773 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(CHGoq).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,774 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(stats.notify_new_event-163).__enter__
2025-11-13 11:41:09,774 - synapse.logging.context.debug - 403 - DEBUG - stats.notify_new_event-163 - LoggingContext(stats.notify_new_event-163).__exit__ --> sentinel
2025-11-13 11:41:09,775 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(CHGoq).__exit sentinel --> PUT-232
2025-11-13 11:41:09,775 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(pURVp).__enter__ PUT-232 --> sentinel
2025-11-13 11:41:09,776 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(delayed_events.notify_new_event-110).__enter__
2025-11-13 11:41:09,776 - synapse.logging.context.debug - 1058 - DEBUG - delayed_events.notify_new_event-110 - make_deferred_yieldable(PVFBE): called with logcontext=delayed_events.notify_new_event-110
2025-11-13 11:41:09,776 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(delayed_events.notify_new_event-110).__enter__
2025-11-13 11:41:09,777 - synapse.logging.context.debug - 1084 - DEBUG - delayed_events.notify_new_event-110 - make_deferred_yieldable(PVFBE): resetting logcontext to sentinel
2025-11-13 11:41:09,777 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(pURVp).__exit sentinel --> PUT-232
2025-11-13 11:41:09,778 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> PUT-232
2025-11-13 11:41:09,778 - synapse.logging.context.debug - 990 - DEBUG - PUT-232 - run_in_background(YWWZR): resetting logcontext to sentinel
2025-11-13 11:41:09,779 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(qZYpz): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,779 - synapse.logging.context.debug - 990 - DEBUG - PUT-232 - run_in_background(zAeYg): resetting logcontext to sentinel
2025-11-13 11:41:09,780 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(njAVM): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,780 - synapse.logging.context.debug - 403 - DEBUG - delayed_events.notify_new_event-110 - LoggingContext(delayed_events.notify_new_event-110).__exit__ --> sentinel
2025-11-13 11:41:09,781 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(GjQgc): called with logcontext=PUT-232
2025-11-13 11:41:09,782 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(GjQgc): resetting logcontext to sentinel
2025-11-13 11:41:09,783 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(cGyQS): restoring calling logcontext to GET-231
2025-11-13 11:41:09,783 - synapse.logging.context.debug - 380 - DEBUG - GET-231 - LoggingContext(GET-231).__enter__
2025-11-13 11:41:09,784 - synapse.logging.context.debug - 380 - DEBUG - GET-231 - LoggingContext(GET-231).__enter__
2025-11-13 11:41:09,784 - synapse.logging.context.debug - 403 - DEBUG - GET-231 - LoggingContext(GET-231).__exit__ --> GET-231
2025-11-13 11:41:09,785 - synapse.logging.context.debug - 403 - DEBUG - GET-231 - LoggingContext(GET-231).__exit__ --> GET-231
2025-11-13 11:41:09,782 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,785 - synapse.logging.context.debug - 380 - DEBUG - GET-231 - LoggingContext(GET-231).__enter__
2025-11-13 11:41:09,786 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(KlJON): called with logcontext=GET-231
2025-11-13 11:41:09,786 - synapse.logging.context.debug - 1068 - DEBUG - GET-231 - make_deferred_yieldable(KlJON): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,787 - synapse.logging.context.debug - 896 - DEBUG - GET-231 - run_in_background(SoSZA): called with logcontext=GET-231
2025-11-13 11:41:09,788 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(ABWGF): called with logcontext=GET-231
2025-11-13 11:41:09,788 - synapse.logging.context.debug - 1084 - DEBUG - GET-231 - make_deferred_yieldable(ABWGF): resetting logcontext to sentinel
2025-11-13 11:41:09,788 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(GET-231).__enter__
2025-11-13 11:41:09,789 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(SoSZA): restoring calling logcontext GET-231
2025-11-13 11:41:09,790 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(IlkNP): called with logcontext=GET-231
2025-11-13 11:41:09,790 - synapse.logging.context.debug - 1084 - DEBUG - GET-231 - make_deferred_yieldable(IlkNP): resetting logcontext to sentinel
2025-11-13 11:41:09,790 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(PVFBE): restoring calling logcontext to delayed_events.notify_new_event-110
2025-11-13 11:41:09,791 - synapse.logging.context.debug - 1058 - DEBUG - delayed_events.notify_new_event-110 - make_deferred_yieldable(pDQie): called with logcontext=delayed_events.notify_new_event-110
2025-11-13 11:41:09,791 - synapse.logging.context.debug - 1084 - DEBUG - delayed_events.notify_new_event-110 - make_deferred_yieldable(pDQie): resetting logcontext to sentinel
2025-11-13 11:41:09,792 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> sentinel
2025-11-13 11:41:09,793 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(delayed_events.notify_new_event-110).__enter__
2025-11-13 11:41:09,793 - synapse.logging.context.debug - 403 - DEBUG - GET-231 - LoggingContext(GET-231).__exit__ --> sentinel
2025-11-13 11:41:09,794 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(GjQgc): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,795 - synapse.logging.context.debug - 990 - DEBUG - PUT-232 - run_in_background(XkmVz): resetting logcontext to sentinel
2025-11-13 11:41:09,796 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(ozPvC): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,796 - synapse.logging.context.debug - 896 - DEBUG - PUT-232 - run_in_background(vvuxf): called with logcontext=PUT-232
2025-11-13 11:41:09,797 - synapse.logging.context.debug - 1058 - DEBUG - PUT-232 - make_deferred_yieldable(EbSbu): called with logcontext=PUT-232
2025-11-13 11:41:09,797 - synapse.logging.context.debug - 1084 - DEBUG - PUT-232 - make_deferred_yieldable(EbSbu): resetting logcontext to sentinel
2025-11-13 11:41:09,797 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(PUT-232).__enter__
2025-11-13 11:41:09,798 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(vvuxf): restoring calling logcontext PUT-232
2025-11-13 11:41:09,800 - synapse.logging.context.debug - 403 - DEBUG - PUT-232 - LoggingContext(PUT-232).__exit__ --> sentinel
2025-11-13 11:41:09,801 - synapse.logging.context.debug - 403 - DEBUG - delayed_events.notify_new_event-110 - LoggingContext(delayed_events.notify_new_event-110).__exit__ --> sentinel
2025-11-13 11:41:09,801 - synapse.logging.context.debug - 990 - DEBUG - PUT-232 - run_in_background(nfVyP): resetting logcontext to sentinel
2025-11-13 11:41:09,804 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(ABWGF): restoring calling logcontext to GET-231
2025-11-13 11:41:09,804 - synapse.logging.context.debug - 990 - DEBUG - GET-231 - run_in_background(SoSZA): resetting logcontext to sentinel
2025-11-13 11:41:09,805 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(IlkNP): restoring calling logcontext to GET-231
2025-11-13 11:41:09,805 - synapse.logging.context.debug - 403 - DEBUG - GET-231 - LoggingContext(GET-231).__exit__ --> GET-231
2025-11-13 11:41:09,806 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(boGYg): called with logcontext=GET-231
2025-11-13 11:41:09,806 - synapse.logging.context.debug - 1068 - DEBUG - GET-231 - make_deferred_yieldable(boGYg): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,807 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(SQYqh): called with logcontext=GET-231
2025-11-13 11:41:09,807 - synapse.logging.context.debug - 1068 - DEBUG - GET-231 - make_deferred_yieldable(SQYqh): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,807 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(YCqsC): called with logcontext=GET-231
2025-11-13 11:41:09,807 - synapse.logging.context.debug - 1068 - DEBUG - GET-231 - make_deferred_yieldable(YCqsC): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,808 - synapse.logging.context.debug - 990 - DEBUG - GET-231 - run_in_background(lNInu): resetting logcontext to sentinel
2025-11-13 11:41:09,808 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(kdIxY): restoring calling logcontext to GET-231
2025-11-13 11:41:09,809 - synapse.logging.context.debug - 896 - DEBUG - GET-231 - run_in_background(OzZph): called with logcontext=GET-231
2025-11-13 11:41:09,809 - synapse.logging.context.debug - 1058 - DEBUG - GET-231 - make_deferred_yieldable(lzvfK): called with logcontext=GET-231
2025-11-13 11:41:09,809 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(GET-231).__enter__
2025-11-13 11:41:09,809 - synapse.logging.context.debug - 1084 - DEBUG - GET-231 - make_deferred_yieldable(lzvfK): resetting logcontext to sentinel
2025-11-13 11:41:09,810 - synapse.logging.context.debug - 403 - DEBUG - GET-231 - LoggingContext(GET-231).__exit__ --> sentinel
2025-11-13 11:41:09,810 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(OzZph): restoring calling logcontext GET-231
2025-11-13 11:41:09,811 - synapse.logging.context.debug - 990 - DEBUG - GET-231 - run_in_background(mzsbB): resetting logcontext to sentinel
2025-11-13 11:41:09,811 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(EbSbu): restoring calling logcontext to PUT-232
2025-11-13 11:41:09,812 - synapse.logging.context.debug - 695 - DEBUG - PUT-232 - PreserveLoggingContext(HQgcE).__enter__ PUT-232 --> PUT-232
2025-11-13 11:41:09,813 - synapse.logging.context.debug - 709 - DEBUG - PUT-232 - PreserveLoggingContext(HQgcE).__exit PUT-232 --> PUT-232
2025-11-13 11:41:09,813 - synapse.logging.context.debug - 990 - DEBUG - PUT-232 - run_in_background(vvuxf): resetting logcontext to sentinel
2025-11-13 11:41:09,814 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(pDQie): restoring calling logcontext to delayed_events.notify_new_event-110
2025-11-13 11:41:09,814 - synapse.logging.context.debug - 403 - DEBUG - delayed_events.notify_new_event-110 - LoggingContext(delayed_events.notify_new_event-110).__exit__ --> sentinel
2025-11-13 11:41:09,815 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(lzvfK): restoring calling logcontext to GET-231
2025-11-13 11:41:09,816 - synapse.logging.context.debug - 695 - DEBUG - GET-231 - PreserveLoggingContext(pOhDk).__enter__ GET-231 --> GET-231
2025-11-13 11:41:09,817 - synapse.logging.context.debug - 709 - DEBUG - GET-231 - PreserveLoggingContext(pOhDk).__exit GET-231 --> GET-231
2025-11-13 11:41:09,818 - synapse.logging.context.debug - 990 - DEBUG - GET-231 - run_in_background(OzZph): resetting logcontext to sentinel
2025-11-13 11:41:09,854 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(bEQTj).__enter__ sentinel --> OPTIONS-233
2025-11-13 11:41:09,854 - synapse.logging.context.debug - 695 - DEBUG - OPTIONS-233 - PreserveLoggingContext(rnTzG).__enter__ OPTIONS-233 --> OPTIONS-233
2025-11-13 11:41:09,855 - synapse.logging.context.debug - 709 - DEBUG - OPTIONS-233 - PreserveLoggingContext(rnTzG).__exit OPTIONS-233 --> OPTIONS-233
2025-11-13 11:41:09,856 - synapse.logging.context.debug - 709 - DEBUG - OPTIONS-233 - PreserveLoggingContext(bEQTj).__exit OPTIONS-233 --> sentinel
2025-11-13 11:41:09,876 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(iPzMV).__enter__ sentinel --> GET-234
2025-11-13 11:41:09,876 - synapse.logging.context.debug - 896 - DEBUG - GET-234 - run_in_background(hqyCF): called with logcontext=GET-234
2025-11-13 11:41:09,877 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(MGZjN): called with logcontext=GET-234
2025-11-13 11:41:09,877 - synapse.logging.context.debug - 1068 - DEBUG - GET-234 - make_deferred_yieldable(MGZjN): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,878 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(qQVyD): called with logcontext=GET-234
2025-11-13 11:41:09,878 - synapse.logging.context.debug - 1068 - DEBUG - GET-234 - make_deferred_yieldable(qQVyD): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,879 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(COHfd): called with logcontext=GET-234
2025-11-13 11:41:09,879 - synapse.logging.context.debug - 1068 - DEBUG - GET-234 - make_deferred_yieldable(COHfd): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,880 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(zGQNF): called with logcontext=GET-234
2025-11-13 11:41:09,881 - synapse.logging.context.debug - 1068 - DEBUG - GET-234 - make_deferred_yieldable(zGQNF): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,881 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(FajTj): called with logcontext=GET-234
2025-11-13 11:41:09,882 - synapse.logging.context.debug - 1068 - DEBUG - GET-234 - make_deferred_yieldable(FajTj): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,883 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(CRbiy): called with logcontext=GET-234
2025-11-13 11:41:09,883 - synapse.logging.context.debug - 1068 - DEBUG - GET-234 - make_deferred_yieldable(CRbiy): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,883 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(aDaOc): called with logcontext=GET-234
2025-11-13 11:41:09,884 - synapse.logging.context.debug - 1068 - DEBUG - GET-234 - make_deferred_yieldable(aDaOc): deferred already completed and the function should have maintained the logcontext
2025-11-13 11:41:09,884 - synapse.logging.context.debug - 896 - DEBUG - GET-234 - run_in_background(uADXT): called with logcontext=GET-234
2025-11-13 11:41:09,885 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(KFJDP): called with logcontext=GET-234
2025-11-13 11:41:09,886 - synapse.logging.context.debug - 380 - DEBUG - - LoggingContext(GET-234).__enter__
2025-11-13 11:41:09,886 - synapse.logging.context.debug - 1084 - DEBUG - GET-234 - make_deferred_yieldable(KFJDP): resetting logcontext to sentinel
2025-11-13 11:41:09,887 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(uADXT): restoring calling logcontext GET-234
2025-11-13 11:41:09,888 - synapse.logging.context.debug - 1058 - DEBUG - GET-234 - make_deferred_yieldable(qpfoj): called with logcontext=GET-234
2025-11-13 11:41:09,890 - synapse.logging.context.debug - 1084 - DEBUG - GET-234 - make_deferred_yieldable(qpfoj): resetting logcontext to sentinel
2025-11-13 11:41:09,891 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(hqyCF): restoring calling logcontext GET-234
2025-11-13 11:41:09,892 - synapse.logging.context.debug - 709 - DEBUG - GET-234 - PreserveLoggingContext(iPzMV).__exit GET-234 --> sentinel
2025-11-13 11:41:09,891 - synapse.logging.context.debug - 403 - DEBUG - GET-234 - LoggingContext(GET-234).__exit__ --> sentinel
2025-11-13 11:41:09,893 - synapse.logging.context.debug - 1096 - DEBUG - - make_deferred_yieldable(KFJDP): restoring calling logcontext to GET-234
2025-11-13 11:41:09,894 - synapse.logging.context.debug - 695 - DEBUG - GET-234 - PreserveLoggingContext(nmLOQ).__enter__ GET-234 --> sentinel
2025-11-13 11:41:10,036 - synapse.logging.context.debug - 695 - DEBUG - - PreserveLoggingContext(zDtQo).__enter__ sentinel --> call_later
2025-11-13 11:41:10,037 - synapse.logging.context.debug - 896 - DEBUG - call_later - run_in_background(qJgQo): called with logcontext=call_later
2025-11-13 11:41:10,037 - synapse.logging.context.debug - 1096 - DEBUG - call_later - make_deferred_yieldable(UWCxx): restoring calling logcontext to federation_transaction_transmission_loop-65
2025-11-13 11:41:10,038 - synapse.logging.context.debug - 380 - DEBUG - federation_transaction_transmission_loop-65 - LoggingContext(federation_transaction_transmission_loop-65).__enter__
2025-11-13 11:41:10,038 - synapse.logging.context.debug - 896 - DEBUG - federation_transaction_transmission_loop-65 - run_in_background(DhSVi): called with logcontext=federation_transaction_transmission_loop-65
2025-11-13 11:41:10,039 - synapse.logging.context.debug - 896 - DEBUG - federation_transaction_transmission_loop-65 - run_in_background(wIiIt): called with logcontext=federation_transaction_transmission_loop-65
2025-11-13 11:41:10,041 - synapse.logging.context.debug - 1058 - DEBUG - federation_transaction_transmission_loop-65 - make_deferred_yieldable(QomNk): called with logcontext=federation_transaction_transmission_loop-65
2025-11-13 11:41:10,041 - synapse.logging.context.debug - 1084 - DEBUG - federation_transaction_transmission_loop-65 - make_deferred_yieldable(QomNk): resetting logcontext to sentinel
2025-11-13 11:41:10,042 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(wIiIt): restoring calling logcontext federation_transaction_transmission_loop-65
2025-11-13 11:41:10,042 - synapse.logging.context.debug - 1058 - DEBUG - federation_transaction_transmission_loop-65 - make_deferred_yieldable(EcSYT): called with logcontext=federation_transaction_transmission_loop-65
2025-11-13 11:41:10,042 - synapse.logging.context.debug - 1084 - DEBUG - federation_transaction_transmission_loop-65 - make_deferred_yieldable(EcSYT): resetting logcontext to sentinel
2025-11-13 11:41:10,042 - synapse.logging.context.debug - 965 - DEBUG - - run_in_background(DhSVi): restoring calling logcontext federation_transaction_transmission_loop-65
2025-11-13 11:41:10,043 - synapse.logging.context.debug - 1058 - DEBUG - federation_transaction_transmission_loop-65 - make_deferred_yieldable(MbUzl): called with logcontext=federation_transaction_transmission_loop-65
2025-11-13 11:41:10,043 - synapse.logging.context.debug - 1084 - DEBUG - federation_transaction_transmission_loop-65 - make_deferred_yieldable(MbUzl): resetting logcontext to sentinel
2025-11-13 11:41:10,043 - synapse.logging.context - 105 - WARNING - - run_in_background(qJgQo): deferred already completed but the function did not maintain the calling logcontext call_later (found sentinel)
2025-11-13 11:41:10,044 - synapse.logging.context.debug - 709 - DEBUG - - PreserveLoggingContext(zDtQo).__exit sentinel --> sentinel
2025-11-13 11:41:10,044 - synapse.logging.context - 105 - WARNING - - Expected logging context call_later was lost
Looking at your new logs
Thanks for the new set of logs! It looks related to the federation_transaction_transmission_loop and some call_later call that we should identify.
Logging for synapse.util.clock
https://github.com/element-hq/synapse/pull/19173 is now merged which means we can also get logs specifically where we need them.
Here is the Docker image from develop that includes the change:
Updated logging config:
loggers:
synapse.storage.SQL:
# beware: increasing this to DEBUG will make synapse log sensitive
# information such as access tokens.
level: INFO
# So we can see how the logcontext is changing
synapse.logging.context.debug:
level: DEBUG
# So we can debug which `clock.call_later(...)` we're interacting with
synapse.util.clock:
level: DEBUG
root:
# Good to generally see what's happening on the homeserver
level: INFO
# handlers: ....
Fixing lost logcontext with deferred
I've also fixed up various places where we may be mishandling logcontext with Deferred:
- https://github.com/element-hq/synapse/pull/19180
- https://github.com/element-hq/synapse/pull/19178
These aren't merged yet but just giving a bigger picture of things happening. I don't know if this actually solves the specific problem you're running into but should eliminate one side of things.
Hopefully a new set of logs can help us pinpoint things.
I was about to ask you for a dev container, that's nice, unfortunately, I won't be able to test it until few days
Sorry for being late ^^ I'm now running v1.143.0rc2 that seems to include your last changes and I can't see, for the moment, this kind of logs (without logging mode set to debug) I don't know if the PR is linked to the issue, but I'll close it as soon as v1.143.0 will be out without these logs ;) many thanks :)