appservice_stream_position can get into such a state that ASes break silently

[ara4n]

I wasted 3h on arasphere last night trying to work out why it wouldn't send stuff to ASes. turns out the value in that table was somehow mangled. deleting it didn't help, but manually reinserting max streampos did. Plus it's inconsistently named wrt all the other AS stuff :(

[ara4n]

so on my HS atm i have:

sqlite> select max(stream_ordering) from events;
811112
sqlite> select * from appservice_stream_position;
X|809618

and it somehow got into a state that the value in appservice_stream_position was mangled (missing entirely, iirc)
and i unstuck it by manually inserting max(stream_ordering) from events into it

[varesa]

I've also been hit by this, now for the second time during the last week.

The first time I "solved" this be destroying the DBs and starting from scratch as I was still setting things up anyway.

Now on the second time my DB looked like this:

sqlite> select max(stream_ordering) from events;                                                                                                                                                                                                                                                                               
82774
sqlite> select * from appservice_stream_position;
X|6481

I was able to fix it by setting the stream_ordering column in appservice_stream_position to max(stream_ordering) from events like @ara4n said even though I was not missing the row.

sqlite> update appservice_stream_position set stream_ordering=82774;

[ara4n]

@kegsay any idea?

[Spydar007]

I also had this issue, but correcting the values fixed it.

[kegsay]

@ara4n no - I didn't do any of the stream position stuff when I did the original Synapse AS API implementation. You'd need to ask @erikjohnston.

[Sorunome]

I had the same issue, fixed it via this.

Then I joined a room (#riot:matrix.org) noone on the synapse server was in yet, and it got off-sync again and i had to re-apply the fix. Perhaps this'll help to hunt down the bug

[turt2live]

This is still very much an issue. There's absolutely no information in the appservice worker's log, as it seems to successfully send a transaction to an appservice, then it stops trying ever again. It does still receive rdata caches/events, and the following appears between rdata updates, but eventually it also stops receiving rdata:

appservice - 2017-10-11 02:55:54,347 - synapse.storage.TIME - 219 - INFO - - Total database time: 0.000% {set_appservice_last_pos(0): 0.000%, get_users_in_room(0): 0.000%, get_user_by_id(0): 0.000%} {}

A restart of the appservice worker did not help too much (it started receiving rdata again, but not sending transactions to appservices). I had to do the update query manually and restart the entire synapse instance.

Are there particular flags/logging I can leave on to try and debug this if it happens again? (this is the 3rd time in ~5 months it has happened).

[turt2live]

This happened once again for me (t2bot.io), and I don't see anything useful in the logs. I have exported them for viewing if desired though (they have tokens and such, so I'd rather not post them publicly).

[turt2live]

and again :(

synapse=# select max(stream_ordering) from events;
   max
----------
 65145242
(1 row)

synapse=# select * from appservice_stream_position;
 lock | stream_ordering
------+-----------------
 X    |        65097572
(1 row)

Logs are also available for this event.

[turt2live]

This is becoming a trend where every couple months I'm having to meddle with the database. This has once again happened.

Is there a lead on a possible cause for this happening?

[richvdh]

ok so let me just try to understand the symptoms here:

• synapse stops sending events to appservices
• inspection of the db shows that appservice_stream_position is stuck at an old event
• restarting synapse does not fix it
• updating appservice_stream_position to a later value (and restarting synapse) does fix it

Is that correct?

If so, the only plausible conclusion is that synapse's appservice sender gets stuck on particular events; by updating appservice_stream_position, we skip the problematic event and things get going again.

Since synapse handles events in batches of 100, the problem might lie anywhere in the next 100 events after the sticking point (ie, stream_orderings 65097573 to 65097672 in @turt2live 's latest example). I'm not quite sure how we can go about narrowing down the problem further :/.

It's possible that some recent improvements to error handling in synapse (in particular, https://github.com/matrix-org/synapse/pull/3138/files#diff-df9c8550f76f9aca4912eaa72d55379eR121) will reveal the problem here.

[turt2live]

That's pretty much the problem. The additional issue is that there's no logging whatsoever for an issue occuring: it just... stops

Improved error handling may catch it. I'm also looking at adding much more verbose logging in the area to see if it can catch what's going on.

[Half-Shot]

We got bitten by this again today, because of some events that existed in the events table, yet DataStore._get_events couldn't find any of them so the stream position couldn't advance. I believe we should skip over any events we couldn't fetch.