Skip to content

ContextVar with tracing breaks responses #19004

New issue
New issue
Closed
#19007
Closed
ContextVar with tracing breaks responses#19004
#19007
Assignees
MadLittleMods
Labels
A-TracingOpenTracing (maybe OpenTelemetry in the future)O-FrequentS-CriticalT-Defect

Description

@erikjohnston
erikjohnston
opened on Oct 1, 2025

When upgrading jki.re 19fe3f0..c284d8c (1.137.0 -> 1.139.0) I started noticing that some requests had their responses cut short and the following exception appearing in the logs:

2025-10-01 13:19:49,431 - twisted - 278 - CRITICAL - sentinel - 
Traceback (most recent call last):
  File "/home/erikj/synapse/src/synapse/synapse/http/server.py", line 804, in resumeProducing
    data = next(self._iterator)
           ^^^^^^^^^^^^^^^^^^^^
StopIteration

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/erikj/.virtualenvs/synapse311/lib/python3.11/site-packages/twisted/internet/asyncioreactor.py", line 138, in _readOrWrite
    why = method()
          ^^^^^^^^
  File "/home/erikj/.virtualenvs/synapse311/lib/python3.11/site-packages/twisted/internet/abstract.py", line 298, in doWrite
    self.producer.resumeProducing()
  File "/home/erikj/.virtualenvs/synapse311/lib/python3.11/site-packages/twisted/web/http.py", line 2953, in resumeProducing
    self._requestProducer.resumeProducing()
  File "/home/erikj/synapse/src/synapse/synapse/http/server.py", line 814, in resumeProducing
    self.stopProducing()
  File "/home/erikj/synapse/src/synapse/synapse/http/server.py", line 822, in stopProducing
    self.tracing_scope.__exit__(None, None, None)
  File "/home/erikj/.virtualenvs/synapse311/lib/python3.11/site-packages/opentracing/scope.py", line 84, in __exit__
    self.close()
  File "/home/erikj/.virtualenvs/synapse311/lib/python3.11/site-packages/opentracing/scope_managers/contextvars.py", line 101, in close
    _SCOPE.reset(self._token)
ValueError: <Token var=<ContextVar name='scope' at 0x7f90b631a190> at 0x7f90b284d150> was created in a different Context

Note that jki.re uses asyncioreactor

Activity

  1. anoadragon453
    added
    O-Frequent
    S-Critical
    T-Defect
    on Oct 1, 2025

  2. MadLittleMods commented on Oct 1, 2025

    @MadLittleMods
    MadLittleMods
    on Oct 1, 2025
    Contributor

    For reference, we switched from our own custom LogContextScopeManager to OpenTracing's ContextVarsScopeManager in #18849 (shipped in Synapse 1.138.0)

  3. MadLittleMods commented on Oct 1, 2025

    @MadLittleMods
    MadLittleMods
    on Oct 1, 2025
    Contributor

    I'm able to reproduce with the asyncioreactor and tracing enabled. Things work fine with the normal reactor.

    Reproduction instructions

    1. Modify the VersionsRestServlet to return a very large response that will buffer in the Twisted internals and cause pauseProducing/resumeProducing to be called in our _ByteProducer.
      synapse/rest/client/versions.py 
      # Create a very large JSON response (this will buffer in transport)
large_data = {
    "message": "Testing running into '<Token ...> was created in a different Context' and response being cut off",
    # ~100MB
    "items": [{"id": i, "data": "x" * 5000} for i in range(20000)],
}
return (200, large_data)
    2. Configure Synapse to use tracing:
      homeserver.yaml 
      ## Tracing ##
opentracing:
 enabled: true
 jaeger_config:
   sampler:
     type: const
     param: 1
   logging:
     false
    3. Make sure the optional opentracing depdency is installed: poetry install --extras all
    4. Start Synapse with the asyncioreactor 
      SYNAPSE_ASYNC_IO_REACTOR=1 poetry run synapse_homeserver --config-path homeserver.yaml
    5. Make a versions request: curl http://localhost:8008/_matrix/client/versions
    6. Notice that the response gets cut off at a certain point: ... curl: (18) transfer closed with outstanding read data remaining
    7. Notice the error in the homeserver logs (homeserver.log) -> ValueError: <Token var=<ContextVar name='scope' at 0x7f8c8e7fec00> at 0x7f8c88211240> was created in a different Context

  4. MadLittleMods commented on Oct 1, 2025

    @MadLittleMods
    MadLittleMods
    on Oct 1, 2025
    Contributor

    Twisted ContextVar support

    Feels suspiciously related to twisted/twisted#10301 which was also a builtins.ValueError: <Token foo> was created in a different Context problem.

    And may just be a lack of full Twisted supported for ContextVar:

    Unresolved issues:

    Resolved issues:

    I compiled this list of issues after the fact from merging #18849 while working on #18871 (comment); which I also documented on #10342 (comment)

    asyncioreactor is experimental in Synapse

    It looks like SYNAPSE_ASYNC_IO_REACTOR is still an "experimental" option and tracked by #8642 (previously matrix-org/synapse#8642).

    If the asyncioreactor was an officially supported option, the best course of action may be just to revert until we figure it out no matter what.

    ContextVarsScopeManager doesn't even work totally well with the normal reactor

    Now with even more hindsight and playing around with the reproduction more, I can also see that ContextVarsScopeManager wasn't a panacea for making the write_bytes_to_request span show up in the trace (#18804) which is where this switch originally spawned from. For example, with the normal reactor, write_bytes_to_request doesn't appear for the large response case (using the reproduction above) as it loses the tracing scope in that case (probably because of the aforementioned sketchy Twisted ContextVar support). For reference, with ContextVarsScopeManager, write_bytes_to_request does show up when there is no pause/resume cycles on the _ByteProducer. It didn't show up at all when we were using our custom LogContextScopeManager because the sentinel logcontext was being used there.

    Given that ContextVarsScopeManager isn't even giving us the full benefit from switching as expected, I think the best course of action is reverting back to using LogContextScopeManager for now ⏩

    And then we can look into extending the logcontext lifetime to play nicely with _ByteProducer to see the write_bytes_to_request span.

  5. MadLittleMods
    self-assigned this
    on Oct 1, 2025
  6. MadLittleMods
    closed this as completedin #19007on Oct 2, 2025
  7. MadLittleMods
    added a commit that references this issue on Oct 2, 2025

    Revert "Switch to OpenTracing's `ContextVarsScopeManager` (#18849)" (#…

    06a84f4

  8. MadLittleMods commented on Oct 2, 2025

    @MadLittleMods
    MadLittleMods
    on Oct 2, 2025
    Contributor

    Reverted in #19007

  9. erikjohnston commented on Oct 2, 2025

    @erikjohnston
    erikjohnston
    on Oct 2, 2025
    MemberAuthor

    Woo thank you!

  10. MadLittleMods
    added
    A-TracingOpenTracing (maybe OpenTelemetry in the future)
    on Oct 2, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

A-TracingOpenTracing (maybe OpenTelemetry in the future)O-FrequentS-CriticalT-Defect

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions