Background process 'stats.notify_new_event' threw an exception

[mrjohnson22]

Description

Starting a few hours ago, my HS has repeatedly been throwing exceptions that look like this:

2019-11-23 23:15:01,762 - synapse.metrics.background_process_metrics - 214 - ERROR - stats.notify_new_event-68- Background process 'stats.notify_new_event' threw an exception
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: (1278781, 1278781)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/metrics/background_process_metrics.py", line 212, in run
    return (yield result)
AssertionError

These errors get thrown several times per minute, but the visible operation of the homeserver seems to be fine.

Steps to reproduce

Not sure what the root cause is, but I did restore a pg_dumped synapse database right before this problem started happening. Maybe doing that caused a problem.

Version information

• Homeserver: personal non-federated homeserver
• Version: 1.5.1
• Install method: apt
• Platform: Debian 9.11 in Gnome Boxes

[mrjohnson22]

I think I found the cause of & fix for this problem.

• Cause: I was fiddling with Tulir's Facebook bridge and made it invite a secondary account to rooms already managed by the bridge. Any invites rejected by that secondary account became "tainted", meaning the account couldn't ever join those rooms again (attempts to do so led to an inconsistent state of that account thinking it didn't join, but other accounts/clients thinking it did). I believe the logged exceptions are due to that "tainted" state.
• Fix: For each "tainted" room, I had an admin user invite the alternate account and revoke the invite. This undid the damage on the rooms, as it allowed the account to join normally later, and stopped those exceptions from being logged.

Not sure if this represents a Synapse bug or is the expected outcome of haphazard tinkering, so I'll leave this issue open for others to judge.

[richvdh]

That probably shouldn't happen. Is there any more to the stack trace? In fact, can you share enough of the log that it shows the request arriving and completing?

[mrjohnson22]

Here are a few:

2019-11-23 22:30:57,718 - synapse.push.pusherpool - 237 - INFO - start_pushers-0- Starting 12 pushers
2019-11-23 22:30:57,730 - synapse.metrics.background_process_metrics - 214 - ERROR - stats.notify_new_event-0- Background process 'stats.notify_new_event' threw an exception
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: 13056

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: 13056

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/metrics/background_process_metrics.py", line 212, in run
    return (yield result)
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.5/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.5/site-packages/synapse/handlers/stats.py", line 74, in process
    yield self._unsafe_process()
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/handlers/stats.py", line 100, in _unsafe_process
    self.pos, room_max_stream_ordering
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/data_stores/main/state_deltas.py", line 51, in get_current_state_deltas
    assert prev_stream_id <= max_stream_id
AssertionError
2019-11-23 22:30:57,745 - synapse.push.pusherpool - 243 - INFO - start_pushers-0- Started pushers

2019-11-23 22:30:58,651 - synapse.access.http.8008 - 233 - INFO - PUT-1- <redacted-ip> - 8008 - Received request: PUT /_matrix/client/r0/presence/%40<reacted-for-github>/status?access_token=<redacted>&user_id=%40<redacted-for-github>
2019-11-23 22:30:58,693 - synapse.storage.background_updates - 114 - INFO - background_updates-0- No more background updates to do. Unscheduling background update task.
2019-11-23 22:30:58,760 - synapse.metrics.background_process_metrics - 214 - ERROR - stats.notify_new_event-1- Background process 'stats.notify_new_event' threw an exception
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: set()

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: set()

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: [RoomsForUser(room_id='<redacted-for-github>', sender='@<redacted-for-github>', membership='join', event_id='$NCKt1ZH2FWI7-N631Oc4GP74fLqFZf9xnMNkJB6c3-M', stream_ordering=699)]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: frozenset({_GetRoomsForUserWithStreamOrdering(room_id='<redacted-for-github>', stream_ordering=699)})

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: frozenset({'<redacted-for-github>'})

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: ({'<redacted-for-github>': [UserPresenceState(user_id='@<redacted-for-github>', state='unavailable', last_active_ts=1574565858231, last_federation_update_ts=1574566258669, last_user_sync_ts=0, status_msg='Playing World of Warcraft', currently_active=True)]}, {'@<redacted-for-github>': [UserPresenceState(user_id='@<redacted-for-github>', state='unavailable', last_active_ts=1574565858231, last_federation_update_ts=1574566258669, last_user_sync_ts=0, status_msg='Playing World of Warcraft', currently_active=True)]})

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/metrics/background_process_metrics.py", line 212, in run
    return (yield result)
AssertionError
2019-11-23 22:30:58,767 - synapse.access.http.8008 - 302 - INFO - PUT-1- <redacted-ip> - 8008 - {@<redacted-for-github>} Processed request: 0.115sec/0.001sec (0.016sec, 0.000sec) (0.005sec/0.091sec/5) 2B 200 "PUT /_matrix/client/r0/presence/%40<redacted-for-github>/status?access_token=<redacted>&user_id=%40<redacted-for-github> HTTP/1.0" "-" [0 dbevts]

2019-11-23 22:31:08,885 - synapse.access.http.8008 - 233 - INFO - PUT-25- <redacted-ip> - 8008 - Received request: PUT /_matrix/client/r0/presence/@<redacted-for-github>/status?user_id=@<redacted-for-github>
2019-11-23 22:31:09,228 - synapse.metrics.background_process_metrics - 214 - ERROR - stats.notify_new_event-2- Background process 'stats.notify_new_event' threw an exception
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: set()

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: set()

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: []

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: frozenset()

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: frozenset()

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: ({}, {'@<redacted-for-github>': [UserPresenceState(user_id='@<redacted-for-github>', state='online', last_active_ts=1574566268897, last_federation_update_ts=1574566268897, last_user_sync_ts=0, status_msg=None, currently_active=True)]})

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/metrics/background_process_metrics.py", line 212, in run
    return (yield result)
AssertionError
2019-11-23 22:31:09,233 - synapse.access.http.8008 - 302 - INFO - PUT-25- <redacted-ip> - 8008 - {@<redacted-for-github>} Processed request: 0.348sec/0.001sec (0.008sec, 0.004sec) (0.004sec/0.327sec/5) 2B 200 "PUT /_matrix/client/r0/presence/@<redacted-for-github>/status?user_id=@<redacted-for-github> HTTP/1.0" "Python/3.7 aiohttp/3.6.2" [0 dbevts]

[schnuffle]

Hi,
just wanted to open an issue about my problem. From the error I think I have the same problem. I hope it's okay to add my infos to the issue.

Infos

OS: centos7
Synapse: v1.7.2 and v1.8.0
Python: 3.6 and 3.8

I get following error repeating a couple of times per minute:

Dec 21 16:00:12 kolab python: return (yield result)
Dec 21 16:00:12 kolab python: AssertionError
Dec 21 16:00:13 kolab python: 2019-12-21 16:00:13,531 - synapse.metrics.background_process_metrics - 214 - ERROR - user_directory.notify_new_event-3145- Background process 'user_directory.notify_new_event' threw an exception
Dec 21 16:00:13 kolab python: Traceback (most recent call last):
Dec 21 16:00:13 kolab python: File "/home/synapse/pyenv36/lib64/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Dec 21 16:00:13 kolab python: result = g.send(result)
Dec 21 16:00:13 kolab python: StopIteration
Dec 21 16:00:13 kolab python: During handling of the above exception, another exception occurred:
Dec 21 16:00:13 kolab python: Traceback (most recent call last):
Dec 21 16:00:13 kolab python: File "/home/synapse/pyenv36/lib64/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Dec 21 16:00:13 kolab python: result = g.send(result)
Dec 21 16:00:13 kolab python: StopIteration
Dec 21 16:00:13 kolab python: During handling of the above exception, another exception occurred:
Dec 21 16:00:13 kolab python: Traceback (most recent call last):
Dec 21 16:00:13 kolab python: File "/home/synapse/pyenv36/lib64/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Dec 21 16:00:13 kolab python: result = g.send(result)
Dec 21 16:00:13 kolab python: StopIteration: (56354144, 56354144)
Dec 21 16:00:13 kolab python: During handling of the above exception, another exception occurred:
Dec 21 16:00:13 kolab python: Traceback (most recent call last):
Dec 21 16:00:13 kolab python: File "/home/synapse/pyenv36/lib64/python3.6/site-packages/synapse/metrics/background_process_metrics.py", line 212, in run

Haven't found any solution yet.

[schnuffle]

Here's the error on python 3.8 with synapse 1.8.0:

Jan  9 19:43:40 kolab python: 2020-01-09 19:43:40,129 - synapse.metrics.background_process_metrics - 214 - ERROR - user_directory.notify_new_event-597- Background process 'user_directory.notify_new_event' threw an exception
Jan  9 19:43:40 kolab python: Traceback (most recent call last):
Jan  9 19:43:40 kolab python: File "/home/synapse/.pyenv/versions/synapse-py381/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Jan  9 19:43:40 kolab python: result = g.send(result)
Jan  9 19:43:40 kolab python: StopIteration: set()
Jan  9 19:43:40 kolab python: During handling of the above exception, another exception occurred:
Jan  9 19:43:40 kolab python: Traceback (most recent call last):
Jan  9 19:43:40 kolab python: File "/home/synapse/.pyenv/versions/synapse-py381/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Jan  9 19:43:40 kolab python: result = g.send(result)
Jan  9 19:43:40 kolab python: StopIteration: set()
Jan  9 19:43:40 kolab python: During handling of the above exception, another exception occurred:
Jan  9 19:43:40 kolab python: Traceback (most recent call last):
Jan  9 19:43:40 kolab python: File "/home/synapse/.pyenv/versions/synapse-py381/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Jan  9 19:43:40 kolab python: result = g.send(result)
Jan  9 19:43:40 kolab python: StopIteration: [RoomsForUser(room_id='!QtykxKocfZaZOUrTwp:matrix.org', sender='@/dev/saces:saces.de', membership='join', event_id='$15325414061gsNxd:saces.de', stream_ordering=6072033), RoomsForUser(room_id='!HsxjoYRFsDtWBgDQPh:matrix.org', sender='@/dev/saces:saces.de', membership='join', event_id='$153885500627MPOuB:saces.de', stream_ordering=5954784)]
Jan  9 19:43:40 kolab python: During handling of the above exception, another exception occurred:
Jan  9 19:43:40 kolab python: Traceback (most recent call last):
Jan  9 19:43:40 kolab python: File "/home/synapse/.pyenv/versions/synapse-py381/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Jan  9 19:43:40 kolab python: result = g.send(result)
Jan  9 19:43:40 kolab python: StopIteration: frozenset({_GetRoomsForUserWithStreamOrdering(room_id='!QtykxKocfZaZOUrTwp:matrix.org', stream_ordering=6072033), _GetRoomsForUserWithStreamOrdering(room_id='!HsxjoYRFsDtWBgDQPh:matrix.org', stream_ordering=5954784)})
Jan  9 19:43:40 kolab python: During handling of the above exception, another exception occurred:
Jan  9 19:43:40 kolab python: Traceback (most recent call last):
Jan  9 19:43:40 kolab python: File "/home/synapse/.pyenv/versions/synapse-py381/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Jan  9 19:43:40 kolab python: result = g.send(result)
Jan  9 19:43:40 kolab python: StopIteration: frozenset({'!HsxjoYRFsDtWBgDQPh:matrix.org', '!QtykxKocfZaZOUrTwp:matrix.org'})
Jan  9 19:43:40 kolab python: During handling of the above exception, another exception occurred:
Jan  9 19:43:40 kolab python: Traceback (most recent call last):
Jan  9 19:43:40 kolab python: File "/home/synapse/.pyenv/versions/synapse-py381/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Jan  9 19:43:40 kolab python: result = g.send(result)
Jan  9 19:43:40 kolab python: StopIteration: ({'!HsxjoYRFsDtWBgDQPh:matrix.org': [UserPresenceState(user_id='@/dev/saces:saces.de', state='unavailable', last_active_ts=1578595411476, last_federation_update_ts=1578595420096, last_user_sync_ts=0, status_msg=None, currently_active=False)], '!QtykxKocfZaZOUrTwp:matrix.org': [UserPresenceState(user_id='@/dev/saces:saces.de', state='unavailable', last_active_ts=1578595411476, last_federation_update_ts=1578595420096, last_user_sync_ts=0, status_msg=None, currently_active=False)]}, {'@/dev/saces:saces.de': [UserPresenceState(user_id='@/dev/saces:saces.de', state='unavailable', last_active_ts=1578595411476, last_federation_update_ts=1578595420096, last_user_sync_ts=0, status_msg=None, currently_active=False)]})
Jan  9 19:43:40 kolab python: During handling of the above exception, another exception occurred:
Jan  9 19:43:40 kolab python: Traceback (most recent call last):
Jan  9 19:43:40 kolab python: File "/home/synapse/.pyenv/versions/synapse-py381/lib/python3.8/site-packages/synapse/metrics/background_process_metrics.py", line 212, in run
Jan  9 19:43:40 kolab python: return (yield result)
Jan  9 19:43:40 kolab python: AssertionError

[andreaspeters]

I'm getting the same Error messages but with the current synapse Version 1.16.1. With 1.15.2 everything is running fine. I'm using our docker-matrix container. :-) If its helpfull, I can send u the error messages. But because if the private MatrixID's I prefer not to publish it here.

[richvdh]

sorry, we seem to have dropped this.

However, Background process 'stats.notify_new_event' threw an exception doesn't actually tell us much: it could indicate any number of different problems.

We've actually just improved the exception reporting here: please could those of you reporting problems please:

• upgrade to synapse 1.17.0rc1 (or wait for 1.17.0 to be released)
• open your own new issues including the full stack traces. if they turn out to be duplicates, it's much easier for us to merge duplicates than it is to unpick different bugs from one github issue.

@schnuffle please note that we need the original stack trace from homeserver.log; yours appears to have been badly formatted by syslog or similar.

I'm going to close this one for now; @mrjohnson22 if you're still seeing the problem please open a new issue with stacktraces from 1.17.0rc1, as above.