Incremental syncs are returning `{"errcode":"M_NOT_FOUND","error":"Unknown room"}`

[Half-Shot]

Description

Not sure why it has started doing it, but I am seeing {"errcode":"M_NOT_FOUND","error":"Unknown room"} errors when trying to do an incremental sync.

Version information

• Homeserver: 0.33.9

EDIT1:

It's very likely

synapse/synapse/storage/state.py

Line 434 in 678ad15

if not create_id:

since I cannot find another path for "Unknown room" to do with syncs.

EDIT2:

synapse=# SELECT type, state_key, event_id FROM current_state_events
synapse-#                 WHERE room_id = '!YztxsnzcdfOllJOvZA:jcg.re';
     type      |        state_key        |             event_id             
---------------+-------------------------+----------------------------------
 m.room.member | @Half-Shot:half-shot.uk | $1537608760248JGTdh:half-shot.uk

my current_state_events table is miserable though.

EDIT3: Fixed by logging out and in, and doing an initial sync. I suspect I wasn't actually in the room and there was no state for it, however the sync I was using figured I was in the room hence the confusion. Not sure what there is to fix here. Perhaps we should drop any rooms that have incorrect state in the incremental syncs.

[Half-Shot]

Loggingwise:

Halfy-VM log/matrix-synapse » grep "GET-32-" synchrotron.log                                                                                                                                                                                                                                                                                   130 ↵
2018-12-13 18:51:30,567 - synapse.access.http.8018 - 233 - INFO - GET-32- 127.0.0.1 - 8018 - Received request: GET /_matrix/client/r0/sync?filter=174&timeout=0&since=s12145216_128038192_54192_8787232_59407_747_68534_427436_41
2018-12-13 18:51:30,568 - synapse.rest.client.v2_alpha.sync - 117 - DEBUG - GET-32- /sync: user=@Half-Shot:half-shot.uk, timeout=0, since='s12145216_128038192_54192_8787232_59407_747_68534_427436_41', set_presence='online', filter_id='174', device_id='ERGXXQLHYS'
2018-12-13 18:51:30,568 - synapse.util.caches.response_cache - 151 - INFO - GET-32- [sync]: no cached result for [(@Half-Shot:half-shot.uk, 0, 's12145216_128038192_54192_8787232_59407_747_68534_427436_41', '174', False, 'ERGXXQLHYS')], calculating new one
2018-12-13 18:51:30,569 - synapse.handlers.sync - 898 - INFO - GET-32- Calculating sync response for @Half-Shot:half-shot.uk
2018-12-13 18:51:30,576 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_membership_changes_for_user-cfb}
2018-12-13 18:51:30,576 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_membership_changes_for_user-cfb} SELECT m.event_id, stream_ordering FROM events AS e, room_memberships AS m WHERE e.event_id = m.event_id AND m.user_id = ? AND e.stream_ordering > ? AND e.stream_ordering <= ? ORDER BY e.stream_ordering ASC
2018-12-13 18:51:30,577 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_membership_changes_for_user-cfb} ('@Half-Shot:half-shot.uk', 12145216, 12145625)
2018-12-13 18:51:30,584 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_membership_changes_for_user-cfb} 0.007268 sec
2018-12-13 18:51:30,585 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_membership_changes_for_user-cfb} 0.008868 sec
2018-12-13 18:51:30,586 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-cfc}
2018-12-13 18:51:30,587 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-cfc} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,588 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-cfc} [False, '!nsCuueBtSKpKZyLWYU:jcg.re', 1]
2018-12-13 18:51:30,589 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-cfc} 0.001023 sec
2018-12-13 18:51:30,589 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-cfc} 0.003066 sec
2018-12-13 18:51:30,590 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:30,590 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:30,591 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {_simple_select_one_onecol-cfd}
2018-12-13 18:51:30,591 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {_simple_select_one_onecol-cfd} SELECT stream_ordering FROM events WHERE event_id = ?
2018-12-13 18:51:30,591 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {_simple_select_one_onecol-cfd} ['$1544722158331frcgm:half-shot.uk']
2018-12-13 18:51:30,592 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {_simple_select_one_onecol-cfd} 0.000631 sec
2018-12-13 18:51:30,593 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {_simple_select_one_onecol-cfd} 0.002082 sec
2018-12-13 18:51:30,594 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-cfe}
2018-12-13 18:51:30,594 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-cfe} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,594 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-cfe} [False, '!YztxsnzcdfOllJOvZA:jcg.re', 1]
2018-12-13 18:51:30,595 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-cfe} 0.000755 sec
2018-12-13 18:51:30,596 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-cfe} 0.002171 sec
2018-12-13 18:51:30,597 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:30,597 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:30,598 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {_simple_select_one_onecol-cff}
2018-12-13 18:51:30,598 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {_simple_select_one_onecol-cff} SELECT stream_ordering FROM events WHERE event_id = ?
2018-12-13 18:51:30,599 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {_simple_select_one_onecol-cff} ['$1544722159333dYweK:half-shot.uk']
2018-12-13 18:51:30,600 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {_simple_select_one_onecol-cff} 0.000653 sec
2018-12-13 18:51:30,600 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {_simple_select_one_onecol-cff} 0.002043 sec
2018-12-13 18:51:30,606 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d00}
2018-12-13 18:51:30,606 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d01}
2018-12-13 18:51:30,606 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d02}
2018-12-13 18:51:30,606 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d03}
2018-12-13 18:51:30,607 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d04}
2018-12-13 18:51:30,607 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d05}
2018-12-13 18:51:30,607 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d06}
2018-12-13 18:51:30,607 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d07}
2018-12-13 18:51:30,609 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d00} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,609 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d01} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,609 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d02} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,610 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d03} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,610 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d04} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,610 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d05} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,611 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d06} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,611 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d07} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,612 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d00} ('!BsHsnxXKXyNxvwUpzv:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,612 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d01} ('!WCHwNGGsrVwPeRtAnq:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,612 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d02} ('!sQalHldvNOJEUBoRjz:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,613 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d03} ('!pqwsHhdjYsAqQvRuls:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,613 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d04} ('!lIbqlvLrZTysCKQSvi:t2l.io', 12145216, 12145625, 11)
2018-12-13 18:51:30,613 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d05} ('!uDQoIebqsjEEtmWLrO:disroot.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,614 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d06} ('!boLskYiwabbCQNNhlK:sw1v.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,614 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d07} ('!yZHTGeDKZUeKaqeTeU:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,616 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d02} 0.000891 sec
2018-12-13 18:51:30,617 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d04} 0.001256 sec
2018-12-13 18:51:30,617 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d05} 0.001202 sec
2018-12-13 18:51:30,617 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d00} 0.003066 sec
2018-12-13 18:51:30,617 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d01} 0.003018 sec
2018-12-13 18:51:30,618 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d03} 0.002485 sec
2018-12-13 18:51:30,618 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d06} 0.001949 sec
2018-12-13 18:51:30,618 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d07} 0.001063 sec
2018-12-13 18:51:30,618 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d02} 0.012110 sec
2018-12-13 18:51:30,619 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d04} 0.012290 sec
2018-12-13 18:51:30,619 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d05} 0.012300 sec
2018-12-13 18:51:30,620 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d00} 0.013899 sec
2018-12-13 18:51:30,620 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d01} 0.014207 sec
2018-12-13 18:51:30,621 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d03} 0.014611 sec
2018-12-13 18:51:30,622 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d06} 0.014563 sec
2018-12-13 18:51:30,622 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d08}
2018-12-13 18:51:30,623 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d09}
2018-12-13 18:51:30,623 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d0a}
2018-12-13 18:51:30,628 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d0a} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,625 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d0b}
2018-12-13 18:51:30,626 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d0c}
2018-12-13 18:51:30,626 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d0d}
2018-12-13 18:51:30,627 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d0e}
2018-12-13 18:51:30,627 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d08} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,627 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d09} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,623 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d07} 0.016145 sec
2018-12-13 18:51:30,628 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d0a} ('!HsxjoYRFsDtWBgDQPh:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,635 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d0b} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,635 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d0c} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,635 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d0d} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,636 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d0e} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,636 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d08} ('!ozBZDXYtkodhYAndvz:jcg.re', 12145216, 12145625, 11)
2018-12-13 18:51:30,636 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d09} ('!xRuXIDgRrIZjeoRlWq:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,637 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d0f}
2018-12-13 18:51:30,638 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d0b} ('!arpgnczbwKdjqOwXRR:irc.hackint.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,638 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d0c} ('!JbPpaLPZXXczkQYgDa:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,639 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d0d} ('!WCTItCclMwzYvTxaKa:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,639 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d0a} 0.001195 sec
2018-12-13 18:51:30,639 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d0e} ('!DwmKuvGvRKciqyFcxv:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,640 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d0f} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,641 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d08} 0.001043 sec
2018-12-13 18:51:30,642 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d0b} 0.001128 sec
2018-12-13 18:51:30,642 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d0c} 0.001044 sec
2018-12-13 18:51:30,642 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d09} 0.002209 sec
2018-12-13 18:51:30,643 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d0d} 0.001149 sec
2018-12-13 18:51:30,643 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d0a} 0.019949 sec
2018-12-13 18:51:30,644 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d0f} ('!RXNcERlITUVsZBNIPW:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,644 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d0e} 0.001564 sec
2018-12-13 18:51:30,645 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d08} 0.022548 sec
2018-12-13 18:51:30,645 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d0b} 0.019994 sec
2018-12-13 18:51:30,646 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d0c} 0.020257 sec
2018-12-13 18:51:30,647 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d09} 0.023899 sec
2018-12-13 18:51:30,647 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d0d} 0.021129 sec
2018-12-13 18:51:30,648 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d10}
2018-12-13 18:51:30,649 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d0f} 0.001035 sec
2018-12-13 18:51:30,650 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d0e} 0.023299 sec
2018-12-13 18:51:30,650 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d11}
2018-12-13 18:51:30,651 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d12}
2018-12-13 18:51:30,652 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d13}
2018-12-13 18:51:30,656 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d10} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,657 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d11} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,659 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d12} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,659 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d0f} 0.022017 sec
2018-12-13 18:51:30,659 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d13} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,660 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d10} ('!HwocBmCtBcHQhILtYQ:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,660 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d11} ('!zXfJBqSUvXySmsZMtB:jki.re', 12145216, 12145625, 11)
2018-12-13 18:51:30,660 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d12} ('!PQpRtCUNPqDCLCLGiL:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,661 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d13} ('!BbUcoMPQhtUNJexFlJ:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,668 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d10} 0.000994 sec
2018-12-13 18:51:30,669 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d11} 0.001099 sec
2018-12-13 18:51:30,669 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d12} 0.001568 sec
2018-12-13 18:51:30,669 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d13} 0.001562 sec
2018-12-13 18:51:30,670 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d10} 0.021940 sec
2018-12-13 18:51:30,670 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d12} 0.019080 sec
2018-12-13 18:51:30,670 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d11} 0.020060 sec
2018-12-13 18:51:30,671 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d13} 0.018810 sec
2018-12-13 18:51:30,680 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d14}
2018-12-13 18:51:30,680 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d15}
2018-12-13 18:51:30,680 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d16}
2018-12-13 18:51:30,680 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d17}
2018-12-13 18:51:30,680 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d18}
2018-12-13 18:51:30,681 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d19}
2018-12-13 18:51:30,681 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d1a}
2018-12-13 18:51:30,681 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d1b}
2018-12-13 18:51:30,683 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d14} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,683 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d15} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,683 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d16} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,684 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d17} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,684 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d18} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,685 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d19} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,685 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d1a} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,685 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d1b} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,686 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d14} ('!QtykxKocfZaZOUrTwp:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,686 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d15} ('!IdPrwvoetMCpMxWmur:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,686 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d16} ('!JXmoIxArWgVvbKKqex:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,687 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d17} ('!OJnzGUgugpKiElfLXP:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,687 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d18} ('!WqtWmjLiOCJVrMhTQk:jcg.re', 12145216, 12145625, 11)
2018-12-13 18:51:30,687 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d19} ('!YkZelGRiqijtzXZODa:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,687 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d1a} ('!FasAQqcSDpYXgmLzvl:half-shot.uk', 12145216, 12145625, 11)
2018-12-13 18:51:30,688 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d1b} ('!zZxICgDdJhCObEHSQs:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,689 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d15} 0.001105 sec
2018-12-13 18:51:30,690 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d14} 0.002276 sec
2018-12-13 18:51:30,690 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d16} 0.001926 sec
2018-12-13 18:51:30,691 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d18} 0.001164 sec
2018-12-13 18:51:30,692 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d19} 0.001104 sec
2018-12-13 18:51:30,692 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d17} 0.003063 sec
2018-12-13 18:51:30,693 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d15} 0.012743 sec
2018-12-13 18:51:30,693 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d1a} 0.001838 sec
2018-12-13 18:51:30,693 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d1b} 0.001336 sec
2018-12-13 18:51:30,693 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d14} 0.013578 sec
2018-12-13 18:51:30,694 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d16} 0.013883 sec
2018-12-13 18:51:30,694 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d18} 0.013642 sec
2018-12-13 18:51:30,694 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d19} 0.013776 sec
2018-12-13 18:51:30,695 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d17} 0.015194 sec
2018-12-13 18:51:30,697 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d1c}
2018-12-13 18:51:30,697 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d1a} 0.016357 sec
2018-12-13 18:51:30,699 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d1d}
2018-12-13 18:51:30,699 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d1b} 0.017772 sec
2018-12-13 18:51:30,700 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d1e}
2018-12-13 18:51:30,700 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d1f}
2018-12-13 18:51:30,701 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d20}
2018-12-13 18:51:30,702 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d21}
2018-12-13 18:51:30,703 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d1c} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,704 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d1d} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,704 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d22}
2018-12-13 18:51:30,705 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d23}
2018-12-13 18:51:30,706 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d1e} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,706 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d1f} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,707 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d20} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,707 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d21} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,707 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d1c} ('!PcCidzjUKXHKImhTrB:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,708 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d1d} ('!hwiGbsdSTZIwSRfybq:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,708 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d22} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,708 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d23} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,709 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d1e} ('!BfPzMJuQMaOmBzFOdD:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,709 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d1f} ('!LCLiMJSFwJyNyVtqxj:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,711 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d1c} 0.001303 sec
2018-12-13 18:51:30,710 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d21} ('!ruaviCwHdJSWfKcBam:half-shot.uk', 12145216, 12145625, 11)
2018-12-13 18:51:30,711 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d22} ('!aZiFuvkhqSyDitTYre:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,711 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d23} ('!OYyXUbcTKVsDBUniNn:matrix.eclabs.de', 12145216, 12145625, 11)
2018-12-13 18:51:30,709 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d20} ('!flbfokeIIEkEnIIEVb:matrix.org', 12145216, 12145625, 11)
2018-12-13 18:51:30,712 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d1d} 0.001542 sec
2018-12-13 18:51:30,713 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d1e} 0.001009 sec
2018-12-13 18:51:30,714 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d1f} 0.000845 sec
2018-12-13 18:51:30,715 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d1e} 0.015264 sec
2018-12-13 18:51:30,714 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d1c} 0.017281 sec
2018-12-13 18:51:30,716 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d21} 0.001464 sec
2018-12-13 18:51:30,716 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d23} 0.001376 sec
2018-12-13 18:51:30,717 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d20} 0.001024 sec
2018-12-13 18:51:30,717 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d1d} 0.017963 sec
2018-12-13 18:51:30,718 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d1f} 0.017280 sec
2018-12-13 18:51:30,719 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d22} 0.002598 sec
2018-12-13 18:51:30,722 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d21} 0.019446 sec
2018-12-13 18:51:30,722 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d23} 0.017087 sec
2018-12-13 18:51:30,723 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d20} 0.021233 sec
2018-12-13 18:51:30,725 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d22} 0.020913 sec
2018-12-13 18:51:30,730 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:30,730 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d24}
2018-12-13 18:51:30,730 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_room_events_stream_for_room-d25}
2018-12-13 18:51:30,731 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447227188005108GQejA:matrix.org']
2018-12-13 18:51:30,731 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d24} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,732 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_room_events_stream_for_room-d25} SELECT event_id, stream_ordering FROM events WHERE room_id = ? AND not outlier AND stream_ordering > ? AND stream_ordering <= ? ORDER BY stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,741 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:30,741 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d24} ('!YztxsnzcdfOllJOvZA:jcg.re', 12145216, 12145220, 21)
2018-12-13 18:51:30,741 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_room_events_stream_for_room-d25} ('!nsCuueBtSKpKZyLWYU:jcg.re', 12145216, 12145219, 21)
2018-12-13 18:51:30,742 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_jcnmark6:matrix.org'): '$15447227018004904TAqFf:matrix.org'}...
2018-12-13 18:51:30,743 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_jcnmark6:matrix.org'): '$15447227018004904TAqFf:matrix.org'}
2018-12-13 18:51:30,744 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:30,745 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d25} 0.001989 sec
2018-12-13 18:51:30,745 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_room_events_stream_for_room-d24} 0.002525 sec
2018-12-13 18:51:30,745 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d26}
2018-12-13 18:51:30,745 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447234388013998MxaMO:matrix.org']
2018-12-13 18:51:30,746 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d25} 0.015678 sec
2018-12-13 18:51:30,746 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_room_events_stream_for_room-d24} 0.016068 sec
2018-12-13 18:51:30,747 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d26} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,785 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d26} [False, '!QtykxKocfZaZOUrTwp:matrix.org', 1]
2018-12-13 18:51:30,802 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d26} 0.006277 sec
2018-12-13 18:51:30,817 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:30,817 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d26} 0.072437 sec
2018-12-13 18:51:30,818 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d27}
2018-12-13 18:51:30,818 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447230278009045gzEVU:matrix.org']
2018-12-13 18:51:30,819 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d27} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,827 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:30,828 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d27} [False, '!WCTItCclMwzYvTxaKa:matrix.org', 1]
2018-12-13 18:51:30,828 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_cocoadaemon:matrix.org'): '$15447222157998828AHpLD:matrix.org', ('m.room.member', '@freenode_goliath:matrix.org'): '$15447209607982711NOgGh:matrix.org'}...
2018-12-13 18:51:30,829 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_cocoadaemon:matrix.org'): '$15447222157998828AHpLD:matrix.org', ('m.room.member', '@freenode_goliath:matrix.org'): '$15447209607982711NOgGh:matrix.org'}
2018-12-13 18:51:30,830 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:30,831 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d28}
2018-12-13 18:51:30,831 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d27} 0.002498 sec
2018-12-13 18:51:30,831 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447225342492110iKbRt:matrix.org']
2018-12-13 18:51:30,832 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d28} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,835 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:30,836 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d27} 0.017976 sec
2018-12-13 18:51:30,836 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d28} [False, '!zZxICgDdJhCObEHSQs:matrix.org', 1]
2018-12-13 18:51:30,836 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@ahupman:matrix.org'): '$15447225342492110iKbRt:matrix.org'}...
2018-12-13 18:51:30,837 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@ahupman:matrix.org'): '$15447225342492110iKbRt:matrix.org'}
2018-12-13 18:51:30,838 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:30,839 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d29}
2018-12-13 18:51:30,839 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:30,839 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d28} 0.001920 sec
2018-12-13 18:51:30,839 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d29} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:30,840 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:30,840 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d28} 0.009660 sec
2018-12-13 18:51:30,841 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d29} [False, '!JXmoIxArWgVvbKKqex:matrix.org', 1]
2018-12-13 18:51:30,842 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:30,843 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$154335603386cnSRo:half-shot.uk', '$15441842602664132aGAiG:matrix.org', '$15444929465595928vkFVR:matrix.org', '$15447234678014312ZtvKw:matrix.org']
2018-12-13 18:51:30,850 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d29} 0.006802 sec
2018-12-13 18:51:30,869 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d29} 0.030002 sec
2018-12-13 18:51:31,005 - synapse.state - 432 - DEBUG - GET-32- Invoked 'resolve_state_groups' with args: self=<synapse.state.StateResolutionHandler object at 0x..., room_id=!PcCidzjUKXHKImhTrB:matrix.org, room_version=1, state_groups_ids={3883537: {('m.room.aliases', 'matrix.org'): '$143..., event_map=None, state_res_store=StateResolutionStore(store=<__main__.SynchrotronSl...
2018-12-13 18:51:31,005 - synapse.state - 464 - DEBUG - GET-32- resolve_state_groups state_groups dict_keys([3883537, 3949530, 3936700, 3923125])
2018-12-13 18:51:31,005 - synapse.util.async_helpers - 205 - INFO - GET-32- Acquired uncontended linearizer lock 'state_resolve_lock' for key frozenset({3883537, 3949530, 3936700, 3923125})
2018-12-13 18:51:31,006 - synapse.util.async_helpers - 218 - INFO - GET-32- Releasing linearizer lock 'state_resolve_lock' for key frozenset({3883537, 3949530, 3936700, 3923125})
2018-12-13 18:51:31,079 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,079 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d2a}
2018-12-13 18:51:31,080 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447234492495649pyzXm:matrix.org']
2018-12-13 18:51:31,080 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d2a} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,082 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,082 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d2a} [False, '!PcCidzjUKXHKImhTrB:matrix.org', 1]
2018-12-13 18:51:31,083 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@beautiful__naw:matrix.org'): '$15446449032232534XqynN:matrix.org', ('m.room.member', '@trilobite17:matrix.org'): '$15446461292238557kHFRP:matrix.org'}...
2018-12-13 18:51:31,083 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@beautiful__naw:matrix.org'): '$15446449032232534XqynN:matrix.org', ('m.room.member', '@trilobite17:matrix.org'): '$15446461292238557kHFRP:matrix.org'}
2018-12-13 18:51:31,084 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,084 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447232308011496sDKnv:matrix.org']
2018-12-13 18:51:31,085 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d2b}
2018-12-13 18:51:31,090 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d2a} 0.007157 sec
2018-12-13 18:51:31,090 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d2b} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,093 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,094 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d2a} 0.014522 sec
2018-12-13 18:51:31,094 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d2b} [False, '!FasAQqcSDpYXgmLzvl:half-shot.uk', 1]
2018-12-13 18:51:31,094 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_alex_eri:matrix.org'): '$15447232308011496sDKnv:matrix.org'}...
2018-12-13 18:51:31,095 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_alex_eri:matrix.org'): '$15447232308011496sDKnv:matrix.org'}
2018-12-13 18:51:31,096 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,097 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d2b} 0.001472 sec
2018-12-13 18:51:31,097 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447231328010263XwZLT:matrix.org']
2018-12-13 18:51:31,097 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d2c}
2018-12-13 18:51:31,102 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,103 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d2b} 0.017867 sec
2018-12-13 18:51:31,103 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d2c} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,103 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@_foonetic_sntxrr:matrix.org'): '$15447229198007748IOveJ:matrix.org'}...
2018-12-13 18:51:31,104 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d2c} [False, '!flbfokeIIEkEnIIEVb:matrix.org', 1]
2018-12-13 18:51:31,104 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@_foonetic_sntxrr:matrix.org'): '$15447229198007748IOveJ:matrix.org'}
2018-12-13 18:51:31,106 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d2c} 0.001122 sec
2018-12-13 18:51:31,106 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d2d}
2018-12-13 18:51:31,109 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d2c} 0.011938 sec
2018-12-13 18:51:31,109 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d2d} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,111 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d2d} [False, '!sQalHldvNOJEUBoRjz:matrix.org', 1]
2018-12-13 18:51:31,112 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,113 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$1544722158331frcgm:half-shot.uk']
2018-12-13 18:51:31,114 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,114 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d2d} 0.001594 sec
2018-12-13 18:51:31,114 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@Half-Shot:half-shot.uk'): '$1544722158331frcgm:half-shot.uk'}...
2018-12-13 18:51:31,115 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d2d} 0.008813 sec
2018-12-13 18:51:31,115 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@Half-Shot:half-shot.uk'): '$1544722158331frcgm:half-shot.uk'}
2018-12-13 18:51:31,116 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,116 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d2e}
2018-12-13 18:51:31,117 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$1537608760248JGTdh:half-shot.uk', '$1544722159333dYweK:half-shot.uk']
2018-12-13 18:51:31,117 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d2e} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,118 - synapse.http.server - 85 - INFO - GET-32- <SynapseRequest at 0x7fa4dc2c5e10 method='GET' uri='/_matrix/client/r0/sync?filter=174&timeout=0&since=s12145216_128038192_54192_8787232_59407_747_68534_427436_41' clientproto='HTTP/1.0' site=8018> SynapseError: 404 - Unknown room
2018-12-13 18:51:31,119 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d2e} [False, '!nsCuueBtSKpKZyLWYU:jcg.re', 1]
2018-12-13 18:51:31,123 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,123 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@Arceliar:matrix.org'): '$15163885941699559CcDWR:matrix.org'}...
2018-12-13 18:51:31,124 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@Arceliar:matrix.org'): '$15163885941699559CcDWR:matrix.org'}
2018-12-13 18:51:31,127 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,127 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d2e} 0.004014 sec
2018-12-13 18:51:31,128 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@brainblasted:disroot.org'): '$15367174334137efPmf:disroot.org', ('m.room.member', '@iamjsparber:matrix.org'): '$15446529952269406LYybH:matrix.org', ('m.room.member', '@bertob:matrix.org'): '$1535620389618899EMBPi:matrix.org', ('m.room.member', '@gitlab:t2bot.io'): '$15223346174273PSDch:t2bot.io'}...
2018-12-13 18:51:31,128 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@brainblasted:disroot.org'): '$15367174334137efPmf:disroot.org', ('m.room.member', '@iamjsparber:matrix.org'): '$15446529952269406LYybH:matrix.org', ('m.room.member', '@bertob:matrix.org'): '$1535620389618899EMBPi:matrix.org', ('m.room.member', '@gitlab:t2bot.io'): '$15223346174273PSDch:t2bot.io'}
2018-12-13 18:51:31,129 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d2e} 0.012107 sec
2018-12-13 18:51:31,131 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,131 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,132 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,133 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,133 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447233348012750gZnQc:matrix.org']
2018-12-13 18:51:31,136 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,137 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_etue:matrix.org'): '$15447222197998892FRxur:matrix.org', ('m.room.member', '@freenode_[gibot]:matrix.org'): '$15440563721380370wamMr:matrix.org', ('m.room.member', '@freenode_purplepod:matrix.org'): '$15447123017871947RtSvk:matrix.org'}...
2018-12-13 18:51:31,137 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_etue:matrix.org'): '$15447222197998892FRxur:matrix.org', ('m.room.member', '@freenode_[gibot]:matrix.org'): '$15440563721380370wamMr:matrix.org', ('m.room.member', '@freenode_purplepod:matrix.org'): '$15447123017871947RtSvk:matrix.org'}
2018-12-13 18:51:31,138 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:31,138 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d2f}
2018-12-13 18:51:31,138 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:31,139 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d2f} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,151 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d2f} [False, '!HwocBmCtBcHQhILtYQ:matrix.org', 1]
2018-12-13 18:51:31,169 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d2f} 0.007350 sec
2018-12-13 18:51:31,171 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,171 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_treyp:matrix.org'): '$15447228528006868xDYvn:matrix.org', ('m.room.member', '@freenode_sivel:matrix.org'): '$15426242504258008nfaZZ:matrix.org', ('m.room.member', '@freenode_lidl_:matrix.org'): '$15447224008001215LeHJB:matrix.org', ('m.room.member', '@freenode_tkimball:matrix.org'): '$15447214487988890VPfyL:matrix.org', ('m.room.member', '@freenode_DNG:matrix.org'): '$15447155827913492mTREU:matrix.org', ('m.room.member', '@freenode_mmercer:matrix.org'): '$154352418320961123ypVZn:matrix.org', ('m.room.member', '@appservice-irc:matrix.org'): '$147766085632531NOtsu:matrix.org', ('m.room.member', '@freenode_mmccarthy:matrix.org'): '$15447228818007277knpwv:matrix.org'}...
2018-12-13 18:51:31,171 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d2f} 0.033644 sec
2018-12-13 18:51:31,172 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_treyp:matrix.org'): '$15447228528006868xDYvn:matrix.org', ('m.room.member', '@freenode_sivel:matrix.org'): '$15426242504258008nfaZZ:matrix.org', ('m.room.member', '@freenode_lidl_:matrix.org'): '$15447224008001215LeHJB:matrix.org', ('m.room.member', '@freenode_tkimball:matrix.org'): '$15447214487988890VPfyL:matrix.org', ('m.room.member', '@freenode_DNG:matrix.org'): '$15447155827913492mTREU:matrix.org', ('m.room.member', '@freenode_mmercer:matrix.org'): '$154352418320961123ypVZn:matrix.org', ('m.room.member', '@appservice-irc:matrix.org'): '$147766085632531NOtsu:matrix.org', ('m.room.member', '@freenode_mmccarthy:matrix.org'): '$15447228818007277knpwv:matrix.org'}
2018-12-13 18:51:31,176 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,176 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d30}
2018-12-13 18:51:31,177 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447234482495644QCnnX:matrix.org']
2018-12-13 18:51:31,177 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d30} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,179 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,180 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d30} [False, '!WCTItCclMwzYvTxaKa:matrix.org', 1]
2018-12-13 18:51:31,180 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@beautiful__naw:matrix.org'): '$15446326212177855EZvVf:matrix.org'}...
2018-12-13 18:51:31,181 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@beautiful__naw:matrix.org'): '$15446326212177855EZvVf:matrix.org'}
2018-12-13 18:51:31,182 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,183 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d31}
2018-12-13 18:51:31,183 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d30} 0.002330 sec
2018-12-13 18:51:31,183 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,183 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d31} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,184 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,184 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d30} 0.007708 sec
2018-12-13 18:51:31,185 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d31} [False, '!IdPrwvoetMCpMxWmur:matrix.org', 1]
2018-12-13 18:51:31,186 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,187 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@telegram_223490212:jcg.re'): '$15288119804526MbPCS:jcg.re'}...
2018-12-13 18:51:31,188 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@telegram_223490212:jcg.re'): '$15288119804526MbPCS:jcg.re'}
2018-12-13 18:51:31,188 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,189 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d31} 0.001397 sec
2018-12-13 18:51:31,189 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447232362494784cfmPJ:matrix.org']
2018-12-13 18:51:31,193 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,193 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d31} 0.010790 sec
2018-12-13 18:51:31,194 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@Half-Shot:matrix.org'): '$15447232362494784cfmPJ:matrix.org'}...
2018-12-13 18:51:31,194 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@Half-Shot:matrix.org'): '$15447232362494784cfmPJ:matrix.org'}
2018-12-13 18:51:31,195 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:31,195 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d32}
2018-12-13 18:51:31,196 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:31,196 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d32} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,207 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d32} [False, '!HsxjoYRFsDtWBgDQPh:matrix.org', 1]
2018-12-13 18:51:31,224 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d32} 0.006343 sec
2018-12-13 18:51:31,231 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,232 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@mozilla_GreenJello:matrix.org'): '$15447228738007172SqgJS:matrix.org', ('m.room.member', '@mozilla_synlestidae2:matrix.org'): '$15447232958012276BoIRI:matrix.org', ('m.room.member', '@mozilla_ted:matrix.org'): '$15437870061694941SKfiX:matrix.org', ('m.room.member', '@mozilla_sgift:matrix.org'): '$15447226658004491ADeHe:matrix.org', ('m.room.member', '@mozilla_eckhardt:matrix.org'): '$15446857037622974PQLoh:matrix.org', ('m.room.member', '@mozilla_ogham:matrix.org'): '$15447223318000369JMsjG:matrix.org', ('m.room.member', '@mozilla_rovar:matrix.org'): '$15447227278005228tvzgf:matrix.org', ('m.room.member', '@mozilla_srwalker101:matrix.org'): '$15447232888012197UiQAy:matrix.org', ('m.room.member', '@mozilla_fuji2:matrix.org'): '$15447226298004041bYoVD:matrix.org', ('m.room.member', '@mozilla_thvdburgt:matrix.org'): '$15447225538003141PeNIG:matrix.org', ('m.room.member', '@mozilla_cybai:matrix.org'): '$15447224038001251GweCP:matrix.org', ('m.room.member', '@mozilla_eyans:matrix.org'): '$15446838767608133iLnti:matrix.org', ('m.room.member', '@mozilla_xurtis:matrix.org'): '$15447224078001312imfxK:matrix.org', ('m.room.member', '@mozilla_sinclair:matrix.org'): '$15447232658011911IhmFZ:matrix.org', ('m.room.member', '@mozilla_srwalker_:matrix.org'): '$15447230858009735NDkci:matrix.org', ('m.room.member', '@mozilla_jsatk:matrix.org'): '$15447231648010679qAffS:matrix.org', ('m.room.member', '@mozilla_ralvessa:matrix.org'): '$15447229118007650jraQL:matrix.org', ('m.room.member', '@mozilla_niklasl:matrix.org'): '$15447228708007129wDBhT:matrix.org', ('m.room.member', '@mozilla_tehsis:matrix.org'): '$15447185357951146FLsmQ:matrix.org', ('m.room.member', '@mozilla_tbodt:matrix.org'): '$15447226558004362HxXTB:matrix.org', ('m.room.member', '@mozilla_eupp:matrix.org'): '$15447225418003013mwfIy:matrix.org', ('m.room.member', '@mozilla_spear2:matrix.org'): '$15447228168006407RKUKM:matrix.org', ('m.room.member', '@mozilla_shackra:matrix.org'): '$15447228868007319RPeMf:matrix.org', ('m.room.member', '@mozilla_zeenix:matrix.org'): '$15447224538001935YlmvQ:matrix.org', ('m.room.member', '@mozilla_callym:matrix.org'): '$15447222187998876NMVJp:matrix.org', ('m.room.member', '@mozilla_srwalke__:matrix.org'): '$15447232508011770IApzz:matrix.org', ('m.room.member', '@mozilla_Phrohdoh:matrix.org'): '$15447228338006647enNRt:matrix.org', ('m.room.member', '@mozilla_manishkk:matrix.org'): '$15447228978007444NAsSe:matrix.org', ('m.room.member', '@mozilla_tabyss:matrix.org'): '$15447228738007178dhNej:matrix.org'}...
2018-12-13 18:51:31,232 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d32} 0.037245 sec
2018-12-13 18:51:31,233 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@mozilla_GreenJello:matrix.org'): '$15447228738007172SqgJS:matrix.org', ('m.room.member', '@mozilla_synlestidae2:matrix.org'): '$15447232958012276BoIRI:matrix.org', ('m.room.member', '@mozilla_ted:matrix.org'): '$15437870061694941SKfiX:matrix.org', ('m.room.member', '@mozilla_sgift:matrix.org'): '$15447226658004491ADeHe:matrix.org', ('m.room.member', '@mozilla_eckhardt:matrix.org'): '$15446857037622974PQLoh:matrix.org', ('m.room.member', '@mozilla_ogham:matrix.org'): '$15447223318000369JMsjG:matrix.org', ('m.room.member', '@mozilla_rovar:matrix.org'): '$15447227278005228tvzgf:matrix.org', ('m.room.member', '@mozilla_srwalker101:matrix.org'): '$15447232888012197UiQAy:matrix.org', ('m.room.member', '@mozilla_fuji2:matrix.org'): '$15447226298004041bYoVD:matrix.org', ('m.room.member', '@mozilla_thvdburgt:matrix.org'): '$15447225538003141PeNIG:matrix.org', ('m.room.member', '@mozilla_cybai:matrix.org'): '$15447224038001251GweCP:matrix.org', ('m.room.member', '@mozilla_eyans:matrix.org'): '$15446838767608133iLnti:matrix.org', ('m.room.member', '@mozilla_xurtis:matrix.org'): '$15447224078001312imfxK:matrix.org', ('m.room.member', '@mozilla_sinclair:matrix.org'): '$15447232658011911IhmFZ:matrix.org', ('m.room.member', '@mozilla_srwalker_:matrix.org'): '$15447230858009735NDkci:matrix.org', ('m.room.member', '@mozilla_jsatk:matrix.org'): '$15447231648010679qAffS:matrix.org', ('m.room.member', '@mozilla_ralvessa:matrix.org'): '$15447229118007650jraQL:matrix.org', ('m.room.member', '@mozilla_niklasl:matrix.org'): '$15447228708007129wDBhT:matrix.org', ('m.room.member', '@mozilla_tehsis:matrix.org'): '$15447185357951146FLsmQ:matrix.org', ('m.room.member', '@mozilla_tbodt:matrix.org'): '$15447226558004362HxXTB:matrix.org', ('m.room.member', '@mozilla_eupp:matrix.org'): '$15447225418003013mwfIy:matrix.org', ('m.room.member', '@mozilla_spear2:matrix.org'): '$15447228168006407RKUKM:matrix.org', ('m.room.member', '@mozilla_shackra:matrix.org'): '$15447228868007319RPeMf:matrix.org', ('m.room.member', '@mozilla_zeenix:matrix.org'): '$15447224538001935YlmvQ:matrix.org', ('m.room.member', '@mozilla_callym:matrix.org'): '$15447222187998876NMVJp:matrix.org', ('m.room.member', '@mozilla_Phrohdoh:matrix.org'): '$15447228338006647enNRt:matrix.org'}
2018-12-13 18:51:31,237 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,238 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d33}
2018-12-13 18:51:31,238 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,238 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d33} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,239 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,239 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d33} [False, '!PcCidzjUKXHKImhTrB:matrix.org', 1]
2018-12-13 18:51:31,240 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,240 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,240 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,242 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,242 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d33} 0.001806 sec
2018-12-13 18:51:31,242 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,243 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,243 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d33} 0.005296 sec
2018-12-13 18:51:31,244 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,245 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,245 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,247 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,247 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@vaso:matrix.org'): '$1539960490295763jjhyV:matrix.org'}...
2018-12-13 18:51:31,247 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@vaso:matrix.org'): '$1539960490295763jjhyV:matrix.org'}
2018-12-13 18:51:31,249 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,249 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@hawkowl:matrix.org'): '$15269189982967685fpWMY:matrix.org', ('m.room.member', '@_neb_github_=40erikj=3ajki.re:matrix.org'): '$15258687681826110rvPEA:matrix.org', ('m.room.member', '@neilj:matrix.org'): '$15178227685439224UWBiH:matrix.org', ('m.room.member', '@richvdh:sw1v.org'): '$151741246626WjWoK:sw1v.org'}...
2018-12-13 18:51:31,250 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@hawkowl:matrix.org'): '$15269189982967685fpWMY:matrix.org', ('m.room.member', '@_neb_github_=40erikj=3ajki.re:matrix.org'): '$15258687681826110rvPEA:matrix.org', ('m.room.member', '@neilj:matrix.org'): '$15178227685439224UWBiH:matrix.org', ('m.room.member', '@richvdh:sw1v.org'): '$151741246626WjWoK:sw1v.org'}
2018-12-13 18:51:31,251 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,251 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,251 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,252 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,252 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447223258000292dABEB:matrix.org']
2018-12-13 18:51:31,256 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,256 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_maryjane:matrix.org'): '$15447221587998033auavv:matrix.org'}...
2018-12-13 18:51:31,256 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_maryjane:matrix.org'): '$15447221587998033auavv:matrix.org'}
2018-12-13 18:51:31,260 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,260 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@commagray:mle.party'): '$1544633867275gHuJF:mle.party', ('m.room.member', '@telegram_253461209:mle.party'): '$15415329232808meJmt:mle.party'}...
2018-12-13 18:51:31,261 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d34}
2018-12-13 18:51:31,261 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@commagray:mle.party'): '$1544633867275gHuJF:mle.party', ('m.room.member', '@telegram_253461209:mle.party'): '$15415329232808meJmt:mle.party'}
2018-12-13 18:51:31,261 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d34} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,262 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,263 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d34} [False, '!uDQoIebqsjEEtmWLrO:disroot.org', 1]
2018-12-13 18:51:31,263 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447226152xfnyj:z9.ru']
2018-12-13 18:51:31,269 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,269 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d34} 0.005274 sec
2018-12-13 18:51:31,269 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@snp:z9.ru'): '$15447226152xfnyj:z9.ru'}...
2018-12-13 18:51:31,269 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@snp:z9.ru'): '$15447226152xfnyj:z9.ru'}
2018-12-13 18:51:31,270 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d34} 0.009121 sec
2018-12-13 18:51:31,271 - synapse.access.http.8018 - 302 - INFO - GET-32- 127.0.0.1 - 8018 - {@Half-Shot:half-shot.uk} Processed request: 0.552sec/0.152sec (0.602sec, 0.079sec) (0.630sec/0.966sec/57) 48B 404 "GET /_matrix/client/r0/sync?filter=174&timeout=0&since=s12145216_128038192_54192_8787232_59407_747_68534_427436_41 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/0.17.6 Chrome/66.0.3359.181 Electron/3.0.5 Safari/537.36" [0 dbevts]
2018-12-13 18:51:31,271 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d35}
2018-12-13 18:51:31,272 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d35} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,275 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d35} [False, '!zXfJBqSUvXySmsZMtB:jki.re', 1]
2018-12-13 18:51:31,278 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,278 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,279 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,279 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,279 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d35} 0.001274 sec
2018-12-13 18:51:31,280 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447234768014414lKVOv:matrix.org']
2018-12-13 18:51:31,285 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d35} 0.014340 sec
2018-12-13 18:51:31,296 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,297 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_chargen:matrix.org'): '$15447211137984437GMPAz:matrix.org', ('m.room.member', '@freenode_jalalsfs_:matrix.org'): '$15441265402105785RmlLC:matrix.org', ('m.room.member', '@freenode_jalalsfs:matrix.org'): '$15446830317601304vQYry:matrix.org', ('m.room.member', '@freenode_thvdburgt:matrix.org'): '$15447225598003214BoiiE:matrix.org', ('m.room.member', '@freenode_FreeFull:matrix.org'): '$15446732367514614WjKxy:matrix.org'}...
2018-12-13 18:51:31,297 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_chargen:matrix.org'): '$15447211137984437GMPAz:matrix.org', ('m.room.member', '@freenode_jalalsfs_:matrix.org'): '$15441265402105785RmlLC:matrix.org', ('m.room.member', '@freenode_jalalsfs:matrix.org'): '$15446830317601304vQYry:matrix.org', ('m.room.member', '@freenode_thvdburgt:matrix.org'): '$15447225598003214BoiiE:matrix.org', ('m.room.member', '@freenode_FreeFull:matrix.org'): '$15446732367514614WjKxy:matrix.org'}
2018-12-13 18:51:31,298 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,298 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d36}
2018-12-13 18:51:31,299 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,300 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d36} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,300 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,300 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d36} [False, '!BfPzMJuQMaOmBzFOdD:matrix.org', 1]
2018-12-13 18:51:31,301 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,302 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,302 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d36} 0.000998 sec
2018-12-13 18:51:31,302 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,303 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,303 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d36} 0.004529 sec
2018-12-13 18:51:31,304 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,305 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@Bond_009:matrix.org'): '$15445631391964404Almnl:matrix.org'}...
2018-12-13 18:51:31,305 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@Bond_009:matrix.org'): '$15445631391964404Almnl:matrix.org'}
2018-12-13 18:51:31,307 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,308 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@Coffee:matrix.org'): '$1530896057361936oByjL:matrix.org', ('m.room.member', '@Half-Shot:matrix.org'): '$1530959346170409DezEN:matrix.org', ('m.room.member', '@travis:t2l.io'): '$15421316437861EsFwx:t2l.io', ('m.room.member', '@welcomeback:t2bot.io'): '$153135006871031RHnhc:t2bot.io'}...
2018-12-13 18:51:31,308 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@Coffee:matrix.org'): '$1530896057361936oByjL:matrix.org', ('m.room.member', '@Half-Shot:matrix.org'): '$1530959346170409DezEN:matrix.org', ('m.room.member', '@travis:t2l.io'): '$15421316437861EsFwx:t2l.io', ('m.room.member', '@welcomeback:t2bot.io'): '$153135006871031RHnhc:t2bot.io'}
2018-12-13 18:51:31,312 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,313 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d37}
2018-12-13 18:51:31,313 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@erikj:jki.re'): '$1528193491313SBLfV:jki.re', ('m.room.member', '@uhoreg:matrix.org'): '$15263882455855505lQyum:matrix.org'}...
2018-12-13 18:51:31,313 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d37} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,314 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@erikj:jki.re'): '$1528193491313SBLfV:jki.re', ('m.room.member', '@uhoreg:matrix.org'): '$15263882455855505lQyum:matrix.org'}
2018-12-13 18:51:31,314 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d37} [False, '!WCHwNGGsrVwPeRtAnq:matrix.org', 1]
2018-12-13 18:51:31,315 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,315 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447232058011217MnDKj:matrix.org']
2018-12-13 18:51:31,317 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,317 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d37} 0.002057 sec
2018-12-13 18:51:31,318 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@_gimpnet_vim24x7:matrix.org'): '$15447232058011206BXbdS:matrix.org'}...
2018-12-13 18:51:31,318 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@_gimpnet_vim24x7:matrix.org'): '$15447232058011206BXbdS:matrix.org'}
2018-12-13 18:51:31,318 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d37} 0.005507 sec
2018-12-13 18:51:31,324 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d38}
2018-12-13 18:51:31,327 - synapse.handlers.sync - 1740 - INFO - GET-32- Incremental gappy sync of !WCTItCclMwzYvTxaKa:matrix.org for user @Half-Shot:half-shot.uk with 8 state events
2018-12-13 18:51:31,327 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d38} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,328 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,329 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d38} [False, '!aZiFuvkhqSyDitTYre:matrix.org', 1]
2018-12-13 18:51:31,329 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$15447231148010068rqPWs:matrix.org']
2018-12-13 18:51:31,335 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d38} 0.005982 sec
2018-12-13 18:51:31,341 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d38} 0.017156 sec
2018-12-13 18:51:31,345 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,346 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d39}
2018-12-13 18:51:31,346 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d3a}
2018-12-13 18:51:31,347 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,347 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d39} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,347 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d3a} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,348 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,348 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d39} [False, '!BbUcoMPQhtUNJexFlJ:matrix.org', 1]
2018-12-13 18:51:31,348 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d3a} [False, '!WqtWmjLiOCJVrMhTQk:jcg.re', 1]
2018-12-13 18:51:31,351 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,352 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@_neb_rssbot_=40fractal=3amatrix.org:matrix.org'): '$1477804767458716swvcQ:matrix.org'}...
2018-12-13 18:51:31,352 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@_neb_rssbot_=40fractal=3amatrix.org:matrix.org'): '$1477804767458716swvcQ:matrix.org'}
2018-12-13 18:51:31,355 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,355 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d39} 0.004075 sec
2018-12-13 18:51:31,356 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d3a} 0.003796 sec
2018-12-13 18:51:31,356 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@delph:matrix.org'): '$1524489391154100axLoN:matrix.org'}...
2018-12-13 18:51:31,356 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d39} 0.010835 sec
2018-12-13 18:51:31,357 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@delph:matrix.org'): '$1524489391154100axLoN:matrix.org'}
2018-12-13 18:51:31,357 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d3a} 0.011097 sec
2018-12-13 18:51:31,358 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,359 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,359 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,384 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d3b}
2018-12-13 18:51:31,387 - synapse.handlers.sync - 1740 - INFO - GET-32- Incremental gappy sync of !PcCidzjUKXHKImhTrB:matrix.org for user @Half-Shot:half-shot.uk with 26 state events
2018-12-13 18:51:31,387 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d3b} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,394 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,394 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d3c}
2018-12-13 18:51:31,395 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d3b} [False, '!PQpRtCUNPqDCLCLGiL:matrix.org', 1]
2018-12-13 18:51:31,395 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,395 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d3c} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145216 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,396 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,396 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d3c} [False, '!OJnzGUgugpKiElfLXP:matrix.org', 1]
2018-12-13 18:51:31,397 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,398 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d3b} 0.001670 sec
2018-12-13 18:51:31,398 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,399 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,399 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d3b} 0.014814 sec
2018-12-13 18:51:31,399 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d3c} 0.000961 sec
2018-12-13 18:51:31,401 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,401 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,401 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d3c} 0.007013 sec
2018-12-13 18:51:31,402 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,404 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,404 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@imoteph:matrix.org'): '$15434588771841051eYAgc:matrix.org', ('m.room.member', '@trilobite17:matrix.org'): '$14775776842903MhAES:matrix.org', ('m.room.member', '@uhoreg:matrix.org'): '$14845855802091919Ybblu:matrix.org'}...
2018-12-13 18:51:31,404 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@imoteph:matrix.org'): '$15434588771841051eYAgc:matrix.org', ('m.room.member', '@trilobite17:matrix.org'): '$14775776842903MhAES:matrix.org', ('m.room.member', '@uhoreg:matrix.org'): '$14845855802091919Ybblu:matrix.org'}
2018-12-13 18:51:31,406 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,406 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@_neb_rssbot_=40travis=3at2l.io:matrix.org'): '$1494864791198852ueHpo:matrix.org'}...
2018-12-13 18:51:31,407 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@_neb_rssbot_=40travis=3at2l.io:matrix.org'): '$1494864791198852ueHpo:matrix.org'}
2018-12-13 18:51:31,407 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,408 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$154472348451fVuUI:linuxgaming.life']
2018-12-13 18:51:31,416 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,417 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@_discord_112625916781277184:linuxgaming.life'): '$1544400330167hAgNl:linuxgaming.life', ('m.room.member', '@_discord_312036504857739265:swedneck.xyz'): '$15421151581484ggJLR:swedneck.xyz', ('m.room.member', '@_discord_336686733267828738:linuxgaming.life'): '$1544463268769fTjIC:linuxgaming.life', ('m.room.member', '@swedneck:swedneck.xyz'): '$15406057228126GlXKs:swedneck.xyz', ('m.room.member', '@_discord_102795037498167296:linuxgaming.life'): '$15446695619756orZbC:linuxgaming.life'}...
2018-12-13 18:51:31,417 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@_discord_312036504857739265:swedneck.xyz'): '$15421151581484ggJLR:swedneck.xyz', ('m.room.member', '@_discord_102795037498167296:linuxgaming.life'): '$15446695619756orZbC:linuxgaming.life'}
2018-12-13 18:51:31,418 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d3d}
2018-12-13 18:51:31,424 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,424 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d3d} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,424 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@_neb_github_=40kegan=3amatrix.org:matrix.org'): '$14853420495286drDpe:matrix.org'}...
2018-12-13 18:51:31,424 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d3d} [False, '!JbPpaLPZXXczkQYgDa:matrix.org', 1]
2018-12-13 18:51:31,425 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@_neb_github_=40kegan=3amatrix.org:matrix.org'): '$14853420495286drDpe:matrix.org'}
2018-12-13 18:51:31,426 - synapse.state - 156 - DEBUG - GET-32- calling resolve_state_groups from get_current_state_ids
2018-12-13 18:51:31,427 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d3d} 0.001542 sec
2018-12-13 18:51:31,427 - synapse.state - 346 - DEBUG - GET-32- resolve_state_groups event_ids ['$154472343320060aqVFH:irc.hackint.org']
2018-12-13 18:51:31,430 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,430 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d3d} 0.012479 sec
2018-12-13 18:51:31,431 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@irc_Fuji:irc.hackint.org'): '$154471853819977musRH:irc.hackint.org', ('m.room.member', '@irc_MorrisFu1kt:irc.hackint.org'): '$154470614319824bTVeB:irc.hackint.org', ('m.room.member', '@irc_MorrisFunkt:irc.hackint.org'): '$154470635419828aVsSH:irc.hackint.org', ('m.room.member', '@irc_pie__:irc.hackint.org'): '$154472216820037lMdtp:irc.hackint.org', ('m.room.member', '@irc_Waithamai:irc.hackint.org'): '$154466430418923kEhgP:irc.hackint.org', ('m.room.member', '@irc_c0nfix:irc.hackint.org'): '$154471971820002dzkrZ:irc.hackint.org'}...
2018-12-13 18:51:31,431 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@irc_Fuji:irc.hackint.org'): '$154471853819977musRH:irc.hackint.org', ('m.room.member', '@irc_MorrisFu1kt:irc.hackint.org'): '$154470614319824bTVeB:irc.hackint.org', ('m.room.member', '@irc_MorrisFunkt:irc.hackint.org'): '$154470635419828aVsSH:irc.hackint.org', ('m.room.member', '@irc_pie__:irc.hackint.org'): '$154472216820037lMdtp:irc.hackint.org', ('m.room.member', '@irc_Waithamai:irc.hackint.org'): '$154466430418923kEhgP:irc.hackint.org', ('m.room.member', '@irc_c0nfix:irc.hackint.org'): '$154471971820002dzkrZ:irc.hackint.org'}
2018-12-13 18:51:31,435 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,436 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d3e}
2018-12-13 18:51:31,436 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {}...
2018-12-13 18:51:31,436 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d3e} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,437 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {}
2018-12-13 18:51:31,437 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d3e} [False, '!arpgnczbwKdjqOwXRR:irc.hackint.org', 1]
2018-12-13 18:51:31,439 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:31,440 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:31,441 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,441 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d3e} 0.002080 sec
2018-12-13 18:51:31,442 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@Amandine:matrix.org'): '$14889783243078492pFMKd:matrix.org', ('m.room.member', '@uhoreg:matrix.org'): '$15275171643586099HYkrk:matrix.org', ('m.room.member', '@brendan:abolivier.bzh'): '$1544551143533lPXYk:abolivier.bzh', ('m.room.member', '@delph:matrix.org'): '$1524489391154099mzLTq:matrix.org'}...
2018-12-13 18:51:31,442 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@Amandine:matrix.org'): '$14889783243078492pFMKd:matrix.org', ('m.room.member', '@uhoreg:matrix.org'): '$15275171643586099HYkrk:matrix.org', ('m.room.member', '@brendan:abolivier.bzh'): '$1544551143533lPXYk:abolivier.bzh', ('m.room.member', '@delph:matrix.org'): '$1524489391154099mzLTq:matrix.org'}
2018-12-13 18:51:31,442 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d3e} 0.006704 sec
2018-12-13 18:51:31,444 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:31,444 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d3f}
2018-12-13 18:51:31,445 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:31,445 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d3f} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,451 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,451 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d3f} [False, '!WCHwNGGsrVwPeRtAnq:matrix.org', 1]
2018-12-13 18:51:31,452 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_ImBrian:matrix.org'): '$15447027027769521ADreE:matrix.org', ('m.room.member', '@freenode_tim241:matrix.org'): '$15442033492890651dWpXV:matrix.org', ('m.room.member', '@freenode_psymin:matrix.org'): '$15446510097275530ycZYd:matrix.org', ('m.room.member', '@adam-stambaugh:matrix.org'): '$15435647602158365rwYaC:matrix.org'}...
2018-12-13 18:51:31,452 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_ImBrian:matrix.org'): '$15447027027769521ADreE:matrix.org', ('m.room.member', '@freenode_tim241:matrix.org'): '$15442033492890651dWpXV:matrix.org', ('m.room.member', '@freenode_psymin:matrix.org'): '$15446510097275530ycZYd:matrix.org', ('m.room.member', '@adam-stambaugh:matrix.org'): '$15435647602158365rwYaC:matrix.org'}
2018-12-13 18:51:31,453 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:31,453 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d3f} 0.001497 sec
2018-12-13 18:51:31,453 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:31,454 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d40}
2018-12-13 18:51:31,455 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,455 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d3f} 0.011138 sec
2018-12-13 18:51:31,455 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d40} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,456 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@telegram_205710844:jcg.re'): '$1544720105692uQWVC:jcg.re', ('m.room.member', '@telegram_315669365:jcg.re'): '$1544720123937bWsJw:jcg.re', ('m.room.member', '@telegram_601671230:jcg.re'): '$1537608422384jHLIJ:jcg.re', ('m.room.member', '@telegram_301775268:jcg.re'): '$1544720120900aETrA:jcg.re', ('m.room.member', '@tgbot:jcg.re'): '$1531992923661irIrE:jcg.re'}...
2018-12-13 18:51:31,456 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d40} [False, '!BbUcoMPQhtUNJexFlJ:matrix.org', 1]
2018-12-13 18:51:31,457 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@telegram_205710844:jcg.re'): '$1544720105692uQWVC:jcg.re', ('m.room.member', '@telegram_315669365:jcg.re'): '$1544720123937bWsJw:jcg.re', ('m.room.member', '@telegram_601671230:jcg.re'): '$1537608422384jHLIJ:jcg.re', ('m.room.member', '@telegram_301775268:jcg.re'): '$1544720120900aETrA:jcg.re', ('m.room.member', '@tgbot:jcg.re'): '$1531992923661irIrE:jcg.re'}
2018-12-13 18:51:31,458 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:31,458 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d40} 0.001118 sec
2018-12-13 18:51:31,458 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d41}
2018-12-13 18:51:31,459 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:31,459 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d41} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,460 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d40} 0.005726 sec
2018-12-13 18:51:31,472 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d41} [False, '!WqtWmjLiOCJVrMhTQk:jcg.re', 1]
2018-12-13 18:51:31,489 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,490 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_yabbes:matrix.org'): '$15447222027998666xbcdb:matrix.org', ('m.room.member', '@freenode_Pegasique:matrix.org'): '$15447228828007281mzxyE:matrix.org', ('m.room.member', '@freenode_iconz:matrix.org'): '$15447225488003094QTyNG:matrix.org', ('m.room.member', '@freenode_rocketmagnet:matrix.org'): '$15447224578001995yjSLI:matrix.org', ('m.room.member', '@freenode_checkbot:matrix.org'): '$15446586387381322YNMqB:matrix.org', ('m.room.member', '@freenode_tradar:matrix.org'): '$15447230678009545scPFB:matrix.org', ('m.room.member', '@freenode_maryo:matrix.org'): '$15442797543567257JlLrX:matrix.org', ('m.room.member', '@freenode_vishal:matrix.org'): '$15440342401113749GfHaN:matrix.org', ('m.room.member', '@freenode_greycat:matrix.org'): '$154359104527225349usgNC:matrix.org', ('m.room.member', '@freenode_Cuzner:matrix.org'): '$1543953610277690VtccE:matrix.org', ('m.room.member', '@freenode_Soliton:matrix.org'): '$15418027691483326GFtUv:matrix.org'}...
2018-12-13 18:51:31,491 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_yabbes:matrix.org'): '$15447222027998666xbcdb:matrix.org', ('m.room.member', '@freenode_Pegasique:matrix.org'): '$15447228828007281mzxyE:matrix.org', ('m.room.member', '@freenode_iconz:matrix.org'): '$15447225488003094QTyNG:matrix.org', ('m.room.member', '@freenode_rocketmagnet:matrix.org'): '$15447224578001995yjSLI:matrix.org', ('m.room.member', '@freenode_checkbot:matrix.org'): '$15446586387381322YNMqB:matrix.org', ('m.room.member', '@freenode_tradar:matrix.org'): '$15447230678009545scPFB:matrix.org', ('m.room.member', '@freenode_maryo:matrix.org'): '$15442797543567257JlLrX:matrix.org', ('m.room.member', '@freenode_vishal:matrix.org'): '$15440342401113749GfHaN:matrix.org', ('m.room.member', '@freenode_greycat:matrix.org'): '$154359104527225349usgNC:matrix.org', ('m.room.member', '@freenode_Cuzner:matrix.org'): '$1543953610277690VtccE:matrix.org', ('m.room.member', '@freenode_Soliton:matrix.org'): '$15418027691483326GFtUv:matrix.org'}
2018-12-13 18:51:31,493 - synapse.storage.stream - 361 - DEBUG - GET-32- stream before
2018-12-13 18:51:31,493 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d41} 0.003000 sec
2018-12-13 18:51:31,493 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d42}
2018-12-13 18:51:31,493 - synapse.storage.stream - 366 - DEBUG - GET-32- stream after
2018-12-13 18:51:31,494 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d42} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,494 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d41} 0.036078 sec
2018-12-13 18:51:31,499 - synapse.handlers.sync - 684 - DEBUG - GET-32- found LruCache for ('@Half-Shot:half-shot.uk', 'ERGXXQLHYS')
2018-12-13 18:51:31,500 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d42} [False, '!PQpRtCUNPqDCLCLGiL:matrix.org', 1]
2018-12-13 18:51:31,500 - synapse.handlers.sync - 841 - DEBUG - GET-32- filtering state from {('m.room.member', '@freenode_marvin2:matrix.org'): '$15447230608009459sKOKv:matrix.org', ('m.room.member', '@freenode_sp:matrix.org'): '$15443332194071174qbaJX:matrix.org', ('m.room.member', '@freenode_Aldem:matrix.org'): '$15447227588005670yIuLF:matrix.org'}...
2018-12-13 18:51:31,501 - synapse.handlers.sync - 847 - DEBUG - GET-32- ...to {('m.room.member', '@freenode_marvin2:matrix.org'): '$15447230608009459sKOKv:matrix.org', ('m.room.member', '@freenode_sp:matrix.org'): '$15443332194071174qbaJX:matrix.org', ('m.room.member', '@freenode_Aldem:matrix.org'): '$15447227588005670yIuLF:matrix.org'}
2018-12-13 18:51:31,505 - synapse.handlers.sync - 1740 - INFO - GET-32- Incremental gappy sync of !WCHwNGGsrVwPeRtAnq:matrix.org for user @Half-Shot:half-shot.uk with 4 state events
2018-12-13 18:51:31,506 - synapse.storage.txn - 235 - DEBUG - GET-32- [TXN START] {get_recent_event_ids_for_room-d43}
2018-12-13 18:51:31,506 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d42} 0.005424 sec
2018-12-13 18:51:31,508 - synapse.handlers.sync - 1740 - INFO - GET-32- Incremental gappy sync of !BbUcoMPQhtUNJexFlJ:matrix.org for user @Half-Shot:half-shot.uk with 4 state events
2018-12-13 18:51:31,509 - synapse.storage.SQL - 101 - DEBUG - GET-32- [SQL] {get_recent_event_ids_for_room-d43} SELECT event_id, topological_ordering, stream_ordering FROM events WHERE outlier = ? AND room_id = ? AND (12145625 >= stream_ordering) ORDER BY topological_ordering DESC, stream_ordering DESC LIMIT ?
2018-12-13 18:51:31,510 - synapse.handlers.sync - 1740 - INFO - GET-32- Incremental gappy sync of !WqtWmjLiOCJVrMhTQk:jcg.re for user @Half-Shot:half-shot.uk with 5 state events
2018-12-13 18:51:31,510 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d42} 0.017269 sec
2018-12-13 18:51:31,510 - synapse.storage.SQL - 108 - DEBUG - GET-32- [SQL values] {get_recent_event_ids_for_room-d43} [False, '!OJnzGUgugpKiElfLXP:matrix.org', 1]
2018-12-13 18:51:31,520 - synapse.handlers.sync - 1740 - INFO - GET-32- Incremental gappy sync of !PQpRtCUNPqDCLCLGiL:matrix.org for user @Half-Shot:half-shot.uk with 11 state events
2018-12-13 18:51:31,520 - synapse.storage.SQL - 125 - DEBUG - GET-32- [SQL time] {get_recent_event_ids_for_room-d43} 0.003056 sec
2018-12-13 18:51:31,521 - synapse.storage.txn - 291 - DEBUG - GET-32- [TXN END] {get_recent_event_ids_for_room-d43} 0.014811 sec
2018-12-13 18:51:31,524 - synapse.handlers.sync - 1740 - INFO - GET-32- Incremental gappy sync of !OJnzGUgugpKiElfLXP:matrix.org for user @Half-Shot:half-shot.uk with 3 state events

[richvdh]

is this still a problem?

[Half-Shot]

It got wedged some time ago, but I've not encountered it recently. Closing.