Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Presence handler is stuck with Could not find event #5157

Closed
richvdh opened this issue May 9, 2019 · 3 comments
Closed

Presence handler is stuck with Could not find event #5157

richvdh opened this issue May 9, 2019 · 3 comments
Labels
z-bug (Deprecated Label) z-p2 (Deprecated Label)

Comments

@richvdh
Copy link
Member

richvdh commented May 9, 2019

My server is spamming this out every couple of seconds:

2019-05-09 12:51:05,679 - synapse.metrics.background_process_metrics - 203 - ERROR - presence.notify_new_event-135987- Background process 'presence.notify_new_event' threw an exception
Capture point (most recent call last):
  File "/usr/lib/python3.5/runpy.py", line 184, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/lib/python3.5/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/synapse/synapse/synapse/app/homeserver.py", line 661, in <module>
    main()
  File "/opt/synapse/synapse/synapse/app/homeserver.py", line 657, in main
    run(hs)
  File "/opt/synapse/synapse/synapse/app/homeserver.py", line 648, in run
    logger=logger,
  File "/opt/synapse/synapse/synapse/app/_base.py", line 143, in start_reactor
    run()
  File "/opt/synapse/synapse/synapse/app/_base.py", line 127, in run
    reactor.run()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/base.py", line 1267, in run
    self.mainLoop()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/base.py", line 1276, in mainLoop
    self.runUntilCurrent()
  File "/opt/synapse/synapse/synapse/metrics/__init__.py", line 347, in f
    ret = func(*args, **kwargs)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/base.py", line 875, in runUntilCurrent
    f(*a, **kw)
  File "/opt/synapse/synapse/synapse/storage/events_worker.py", line 349, in fire
    d.callback([res[i] for i in ids if i in res])
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
    status.deferred.callback(e.value)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
    status.deferred.callback(e.value)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
 File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
    status.deferred.callback(e.value)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
Traceback (most recent call last):
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/opt/synapse/synapse/synapse/storage/events_worker.py", line 419, in _enqueue_events
    defer.returnValue({e.event.event_id: e for e in res if e})
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: {}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/opt/synapse/synapse/synapse/storage/events_worker.py", line 263, in _get_events
    defer.returnValue(events)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: []

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/synapse/synapse/metrics/background_process_metrics.py", line 201, in run
    yield func(*args, **kwargs)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/synapse/synapse/synapse/handlers/presence.py", line 790, in _process_presence
    yield self._unsafe_process()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/synapse/synapse/synapse/handlers/presence.py", line 805, in _unsafe_process
    yield self._handle_state_delta(deltas)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/synapse/synapse/synapse/handlers/presence.py", line 836, in _handle_state_delta
    event = yield self.store.get_event(event_id)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/opt/synapse/synapse/synapse/storage/events_worker.py", line 120, in get_event
    raise NotFoundError("Could not find event %s" % (event_id,))
synapse.api.errors.NotFoundError: 404: Could not find event $<redacted>:matrix.org

It never seems to make any progress, and has been stuck in this loop for days.

Related to #3617 ?
@neilisfragile neilisfragile added z-bug (Deprecated Label) z-p2 (Deprecated Label) labels May 13, 2019
@aryasenna
Copy link

aryasenna commented May 19, 2019 •
edited
Loading

Happening also to me as of now:

2019-05-19 12:44:50,700 - synapse.metrics.background_process_metrics - 203 - ERROR - presence.notify_new_event-577- Background process 'presence.notify_new_event' threw an exception
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/events_worker.py", line 419, in _enqueue_events
    defer.returnValue({e.event.event_id: e for e in res if e})
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: {}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/events_worker.py", line 263, in _get_events
    defer.returnValue(events)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: []

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/metrics/background_process_metrics.py", line 201, in run
    yield func(*args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/presence.py", line 790, in _process_presence
    yield self._unsafe_process()
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/presence.py", line 805, in _unsafe_process
    yield self._handle_state_delta(deltas)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/presence.py", line 842, in _handle_state_delta
    prev_event = yield self.store.get_event(prev_event_id)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/events_worker.py", line 120, in get_event
    raise NotFoundError("Could not find event %s" % (event_id,))
synapse.api.errors.NotFoundError: 404: Could not find event $155820743021HnRdj:<redacted>

Edit: this is on Synapse 0.99.4

@turt2live
Copy link
Member

turt2live commented May 21, 2019 •
edited
Loading

Also happening for t2bot.io on 0.99.4 (+irrelevant modifications):

homeserver_1 - 2019-05-21 01:15:47,720 - synapse.metrics.background_process_metrics - 203 - ERROR - presence.notify_new_event-36597 - Background process 'presence.notify_new_event' threw an exception
Traceback (most recent call last):
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events_worker.py", line 419, in _enqueue_events
    defer.returnValue({e.event.event_id: e for e in res if e})
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: {}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events_worker.py", line 263, in _get_events
    defer.returnValue(events)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: []

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/metrics/background_process_metrics.py", line 201, in run
    yield func(*args, **kwargs)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/presence.py", line 790, in _process_presence
    yield self._unsafe_process()
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/presence.py", line 805, in _unsafe_process
    yield self._handle_state_delta(deltas)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/presence.py", line 836, in _handle_state_delta
    event = yield self.store.get_event(event_id)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events_worker.py", line 120, in get_event
    raise NotFoundError("Could not find event %s" % (event_id,))
synapse.api.errors.NotFoundError: 404: Could not find event $redacted:matrix.org

Not sure if using workers affects this, however given the stack trace and recent changes to presence handling, I think this was introduced by 197fae1

Edit: this is appearing on the master, unlike #3617

@turt2live turt2live mentioned this issue May 21, 2019
Closed
@richvdh richvdh mentioned this issue May 24, 2019
Closed
@richvdh richvdh mentioned this issue Jun 3, 2019
Closed
@hawkowl hawkowl mentioned this issue Jun 5, 2019
Merged
@hawkowl hawkowl closed this as completed Jun 5, 2019
@hawkowl
Copy link
Contributor

hawkowl commented Jun 5, 2019

Fixed in #5352

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
z-bug (Deprecated Label) z-p2 (Deprecated Label)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@neilisfragile @turt2live @richvdh @hawkowl @aryasenna