StopIteration / LoggingContext has no current_context errors with some remote thumbnailing and media downloads

[michaelkaye]

We get an exception when trying to handle both thumbnail requests and media downloads for some images. It reliably happens for a given URL, but not all downloads / thumbnails for a remote host fail.

2020-05-04 08:50:22,981 - synapse.http.server - 110 - ERROR - GET-5511628 - Failed handle request via 'DownloadResource': <XForwardedForRequest at 0x7f44d27a9821 method='GET' uri='/_matrix/media/v1/download/remote_server/XXXX' clientproto='HTTP/1.1' site=8085>
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/media_repository.py", line 24, in <module>
    start(sys.argv[1:])
  File "/home/synapse/src/synapse/app/generic_worker.py", line 983, in start
    _base.start_worker_reactor("synapse-generic-worker", config)
  File "/home/synapse/src/synapse/app/_base.py", line 77, in start_worker_reactor
    run_command=run_command,
  File "/home/synapse/src/synapse/app/_base.py", line 137, in start_reactor
    daemon.start()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/daemonize.py", line 248, in start
    self.action(*privileged_action_result)
  File "/home/synapse/src/synapse/app/_base.py", line 114, in run
    run_command()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1283, in run
    self.mainLoop()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1292, in mainLoop
    self.runUntilCurrent()
  File "/home/synapse/src/synapse/metrics/__init__.py", line 436, in f
    ret = func(*args, **kwargs)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 886, in runUntilCurrent
    f(*a, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 886, in runUntilCurrent
    f(*a, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1421, in _inlineCallbacks
    status.deferred.callback(getattr(e, "value", None))
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1421, in _inlineCallbacks
    status.deferred.callback(getattr(e, "value", None))
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/synapse/src/synapse/http/server.py", line 209, in wrapped_async_request_handler
    await h(self, request)
  File "/home/synapse/src/synapse/http/server.py", line 78, in wrapped_request_handler
    await h(self, request)
  File "/home/synapse/src/synapse/rest/media/v1/download_resource.py", line 72, in _async_render_GET
    await self.media_repo.get_remote_media(request, server_name, media_id, name)
  File "/home/synapse/src/synapse/rest/media/v1/media_repository.py", line 236, in get_remote_media
    server_name, media_id
  File "/home/synapse/src/synapse/rest/media/v1/media_repository.py", line 313, in _get_remote_media_impl
    responder = await self.media_storage.fetch_media(file_info)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1613, in unwindGenerator
    return _cancellableInlineCallbacks(gen)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1529, in _cancellableInlineCallbacks
    _inlineCallbacks(None, g, status)
Traceback (most recent call last):
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'media_type': 'image/png', 'media_length': 500000, 'upload_name': 'name.png', 'created_ts': 1554744000000, 'filesystem_id': 'YYYY', 'quarantined_by': None}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'media_type': 'image/png', 'media_length': 50000, 'upload_name': 'name.png', 'created_ts': 1554744000000, 'filesystem_id': 'YYYY', 'quarantined_by': None}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/synapse/src/synapse/http/server.py", line 78, in wrapped_request_handler
    await h(self, request)
  File "/home/synapse/src/synapse/rest/media/v1/download_resource.py", line 72, in _async_render_GET
    await self.media_repo.get_remote_media(request, server_name, media_id, name)
  File "/home/synapse/src/synapse/rest/media/v1/media_repository.py", line 236, in get_remote_media
    server_name, media_id
  File "/home/synapse/src/synapse/rest/media/v1/media_repository.py", line 313, in _get_remote_media_impl
    responder = await self.media_storage.fetch_media(file_info)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/synapse/src/synapse/rest/media/v1/media_storage.py", line 149, in fetch_media
    res = yield provider.fetch(path, file_info)
  File "/home/synapse/src/synapse/rest/media/v1/storage_provider.py", line 104, in fetch
    return self.backend.fetch(path, file_info)
  File "/home/synapse/synapse-s3-storage-provider/s3_storage_provider.py", line 74, in fetch
    logcontext = LoggingContext.current_context()
AttributeError: type object 'LoggingContext' has no attribute 'current_context'

[babolivier]

FTR the remote server is mine and I don't see that media ID appearing once in my logs, not even matrix.org's media repo downloading it, so maybe this is an error with matrix.org's local media?

[richvdh]

I changed LoggingContext without realising ss3sp was digging into it

[clokep]

I changed LoggingContext without realising ss3sp was digging into it

This seems to be #7120.

[clokep]

From chat:

we need to either (a) grandfather a deprecated LoggingContext.current_context method back in for plugins like this that want to use it (b) change ss3sp to not use it (c) both of the above

[anoadragon453]

Looks like we chose (c).

[clokep]

Yes, we chose option (c) above:

• Add backwards compatibility codepath to LoggingContext. #7408 re-added the removed methods.
• Add compatibility for upcoming changes to Synapse synapse-s3-storage-provider#36 made the synapse-s3-storage-provider forward compatible with the change.

This is now fixed on release.