createRoom with initial_state event to increase own power level fails ungracefully

[eph-eye-en]

Background information

• Dendrite version or git SHA: 2c9a390
• Monolith or Polylith?: Monolith
• SQLite3 or Postgres?: Postgres
• Running in Docker?: No
• go version: 1.16.5

Description

When creating a room, specifying an initial_state event that increases the creating user's power level causes an internal server error and a half configured room. This differs from Synapse which creates the room correctly and applies the new power level.

I tested this against two personal instances and dendrite.matrix.org.

Steps to reproduce

• Send a createRoom request to Dendrite with initial_state set to e.g.

[{
  "content": {
    "users": {
      "@user:example.com": 9001
    }
  },
  "type": "m.room.power_levels"
}]

• Alternatively, this Python code logs in and sends one: https://pastebin.com/HbkdQNbz.

Dendrite will respond with an internal server error rather than succeeding or giving a more useful error. It also only half configures the room (presumably stopping when the error occurs and not reverting the previous changes) rather than creating the room entirely and correctly or not creating the room at all.

Relevant section of log:

time="2021-06-19T15:37:19.263992890Z" level=info msg="Creating new room" func=github.com/matrix-org/dendrite/clientapi/routing.createRoom file="github.com/matrix-org/dendrite@/clientapi/routing/createroom.go:207" req.id=PvhzDGYJnGFs req.method=POST req.path=/_matrix/client/r0/createRoom roomID="!GysUZ6HcFSbaXJsg:example.com" roomVersion=6 userID="@user:example.com" user_id="@user:example.com"
time="2021-06-19T15:37:19.297055466Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).WriteOutputEvents" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input.go:104" adds_state=1 event_id="$PMMnmhZJAUbFc_4ES3PXHnmJEDHp2jbJeMSJx00WI7o" event_type=m.room.create removes_state=0 room_id="!GysUZ6HcFSbaXJsg:example.com" send_as_server="" sender="@user:example.com" type=new_room_event
time="2021-06-19T15:37:19.307340310Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$PMMnmhZJAUbFc_4ES3PXHnmJEDHp2jbJeMSJx00WI7o"
time="2021-06-19T15:37:19.358639437Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).WriteOutputEvents" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input.go:104" adds_state=2 event_id="$mD25qjA2qLn02piE_IAy7IDDqBIN_YTK62HazSUnsYI" event_type=m.room.member removes_state=0 room_id="!GysUZ6HcFSbaXJsg:example.com" send_as_server="" sender="@user:example.com" type=new_room_event
time="2021-06-19T15:37:19.370591714Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$PMMnmhZJAUbFc_4ES3PXHnmJEDHp2jbJeMSJx00WI7o"
time="2021-06-19T15:37:19.372467403Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$mD25qjA2qLn02piE_IAy7IDDqBIN_YTK62HazSUnsYI"
time="2021-06-19T15:37:19.446845303Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).WriteOutputEvents" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input.go:104" adds_state=3 event_id="$Y7aKq5hnTrnCKFSatiTfiGgacdbNMg8gMIQ4zEy2TeE" event_type=m.room.power_levels removes_state=0 room_id="!GysUZ6HcFSbaXJsg:example.com" send_as_server="" sender="@user:example.com" type=new_room_event
time="2021-06-19T15:37:19.459851089Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$PMMnmhZJAUbFc_4ES3PXHnmJEDHp2jbJeMSJx00WI7o"
time="2021-06-19T15:37:19.463092010Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$mD25qjA2qLn02piE_IAy7IDDqBIN_YTK62HazSUnsYI"
time="2021-06-19T15:37:19.464688680Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$Y7aKq5hnTrnCKFSatiTfiGgacdbNMg8gMIQ4zEy2TeE"
time="2021-06-19T15:37:19.521957635Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).WriteOutputEvents" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input.go:104" adds_state=4 event_id="$9UkgqCAXRDy6y35VTP0VG9eOBMmc-UBkwJ3ZMlxgwO8" event_type=m.room.join_rules removes_state=0 room_id="!GysUZ6HcFSbaXJsg:example.com" send_as_server="" sender="@user:example.com" type=new_room_event
time="2021-06-19T15:37:19.534571998Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$PMMnmhZJAUbFc_4ES3PXHnmJEDHp2jbJeMSJx00WI7o"
time="2021-06-19T15:37:19.538624081Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$mD25qjA2qLn02piE_IAy7IDDqBIN_YTK62HazSUnsYI"
time="2021-06-19T15:37:19.540463607Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$Y7aKq5hnTrnCKFSatiTfiGgacdbNMg8gMIQ4zEy2TeE"
time="2021-06-19T15:37:19.542111248Z" level=info msg="Already processed event; ignoring" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input_events.go:94" context=missing event_id="$9UkgqCAXRDy6y35VTP0VG9eOBMmc-UBkwJ3ZMlxgwO8"
time="2021-06-19T15:37:19.616094909Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).WriteOutputEvents" file="github.com/matrix-org/dendrite@/roomserver/internal/input/input.go:104" adds_state=5 event_id="$27OuU1eXP0jtdBVd7u7GwFxU6qxp-BJnnYYLllWplIs" event_type=m.room.history_visibility removes_state=0 room_id="!GysUZ6HcFSbaXJsg:example.com" send_as_server="" sender="@user:example.com" type=new_room_event
time="2021-06-19T15:37:19.635172225Z" level=error msg="gomatrixserverlib.Allowed failed" func=github.com/matrix-org/dendrite/clientapi/routing.createRoom file="github.com/matrix-org/dendrite@/clientapi/routing/createroom.go:345" error="eventauth: sender with level 100 is not allowed change user level from 100 to 9001 because the new level is above the level of the sender" req.id=PvhzDGYJnGFs req.method=POST req.path=/_matrix/client/r0/createRoom user_id="@user:example.com"

Note: I am new to Matrix and not totally sure what the correct behaviour is here, particularly because increasing a power level that defaults to 100 seems like a strange thing to do. The mautrix-signal bridge does this, however, and expects a correctly configured room.

[kegsay]

eventauth: sender with level 100 is not allowed change user level from 100 to 9001 because the new level is above the level of the sender is the main problem here.

I guess that Dendrite is making the normal PL event then applying the events in initial_state over-the-top. Should be easy to test and fix.

[neilalexander]

The canonical way to do this is via power_level_content_override rather than initial_state, but in either case I'm working on a PR which should fix it for initial_state too.

[alistair23]

I still see this error when using the signal bridge on dendrite 0.4.1

[ArnoPoitt]

I also have this error with the signal bridge on dendrite 0.4.1 in docker monolith
Here are the logs from my homeserver following a invite request from a signal PM:

I replaced my account by @$MYACCOUNT$:$MYSERVER$.tld and the bridge server by $BRIDGESERVER$.tld

dentrite | time="2021-08-07T15:48:50.089392580Z" level=info msg="received data from client API server" func="onMessage\n\t" file=" [clientapi.go:89]" room_id="" type=im.vector.setting.breadcrumbs
dentrite | time="2021-08-07T15:48:52.933145593Z" level=info msg="Received transaction \"1628342442615\" from \"$BRIDGESERVER$.tld\" containing 0 PDUs, 1 EDUs" func="Send\n\t" file=" [send.go:206]" req.id=NBSUGY4uu24v req.method=PUT req.path=/_matrix/federation/v1/send/1628342442615
dentrite | time="2021-08-07T15:48:52.944073619Z" level=info msg="Checking event signatures for 14 events of room state" func="Check\n\t" file=" [federationtypes.go:489]" context=missing
dentrite | time="2021-08-07T15:48:52.974127673Z" level=error msg="Event \"$gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc\" is not allowed by its auth events" func="Check\n\t" file=" [federationtypes.go:518]" error="gomatrixserverlib: event with ID \"$gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc\" is not allowed by its auth_events: eventauth: sender with level 100 is not allowed change user level from 100 to 9001 because the new level is above the level of the sender"
dentrite | time="2021-08-07T15:48:52.974234831Z" level=error msg="Event \"$gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc\" is not allowed by its auth events" func="Check\n\t" file=" [federationtypes.go:518]" error="gomatrixserverlib: event with ID \"$gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc\" is not allowed by its auth_events: eventauth: sender with level 100 is not allowed change user level from 100 to 9001 because the new level is above the level of the sender"
dentrite | time="2021-08-07T15:48:52.974483708Z" level=warning msg="Discarding 1 auth/state event(s) due to invalid signatures" func="Check\n\t" file=" [federationtypes.go:526]" context=missing
dentrite | time="2021-08-07T15:48:53.183057018Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$BWTXyDe2mX149rgVnZ2jaIQX3T27uNgJfp-_daqsFYw $pixruZKarWEuUOcWtQ-CVJEk_-qGdXLoxBxHU_c9cqk $gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (2 != 3)" event_id="$ntLpjV-wGLTitM0oKA40FKm1OJgee_TaT13XRW3TolA"
dentrite | time="2021-08-07T15:48:53.230620706Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$BWTXyDe2mX149rgVnZ2jaIQX3T27uNgJfp-_daqsFYw $pixruZKarWEuUOcWtQ-CVJEk_-qGdXLoxBxHU_c9cqk $gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (2 != 3)" event_id="$grlSz6tZ0IjRv7qpo4AuSwdNSNzEKLPJqa78IUjbofc"
dentrite | time="2021-08-07T15:48:53.300292530Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$BWTXyDe2mX149rgVnZ2jaIQX3T27uNgJfp-_daqsFYw $pixruZKarWEuUOcWtQ-CVJEk_-qGdXLoxBxHU_c9cqk $gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (2 != 3)" event_id="$EOpKd3WeBzUOvJ3bOE9yASpPCwPQZgwNAAa-WMIqCR8"
dentrite | time="2021-08-07T15:48:53.351217440Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$BWTXyDe2mX149rgVnZ2jaIQX3T27uNgJfp-_daqsFYw $pixruZKarWEuUOcWtQ-CVJEk_-qGdXLoxBxHU_c9cqk $gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (2 != 3)" event_id="$XKymcLcdtHN0peZy-foLfy-ErAeV_GuStDg-SsdncLc"
dentrite | time="2021-08-07T15:48:53.397519312Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$BWTXyDe2mX149rgVnZ2jaIQX3T27uNgJfp-_daqsFYw $pixruZKarWEuUOcWtQ-CVJEk_-qGdXLoxBxHU_c9cqk $gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (2 != 3)" event_id="$qwrAneJ6CReS2oXZzviHTqRI4AoRtSlItjGj_6wuWK4"
dentrite | time="2021-08-07T15:48:53.453119006Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$BWTXyDe2mX149rgVnZ2jaIQX3T27uNgJfp-_daqsFYw $pixruZKarWEuUOcWtQ-CVJEk_-qGdXLoxBxHU_c9cqk $grlSz6tZ0IjRv7qpo4AuSwdNSNzEKLPJqa78IUjbofc $gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (3 != 4)" event_id="$xuQKpfh_ns0kANBqqtsY6Xf5t7t5m8vpbgvj2lMw6Ak"
dentrite | time="2021-08-07T15:48:53.497662166Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$BWTXyDe2mX149rgVnZ2jaIQX3T27uNgJfp-_daqsFYw $pixruZKarWEuUOcWtQ-CVJEk_-qGdXLoxBxHU_c9cqk $gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (2 != 3)" event_id="$gov23IYVEIcKxt_KMmz-Z3hhWOOah2Wx5g94UxPhhS0"
dentrite | time="2021-08-07T15:48:53.530282699Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$grlSz6tZ0IjRv7qpo4AuSwdNSNzEKLPJqa78IUjbofc $BWTXyDe2mX149rgVnZ2jaIQX3T27uNgJfp-_daqsFYw $gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc $xuQKpfh_ns0kANBqqtsY6Xf5t7t5m8vpbgvj2lMw6Ak]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (3 != 4)" event_id="$dcw19LlLGgdGi2Odef8deVC5yPBRn0pwhKr47bL1w0U"
dentrite | time="2021-08-07T15:48:53.586039970Z" level=error msg="Failed to send room join response to roomserver" func="func1\n\t" file=" [perform.go:257]" error="InputRoomEventsResponse: r.calculateAndSetState: roomState.CalculateAndStoreStateBeforeEvent: storage: missing state for event NID 124571" room_id="!KJDQhafvLmPEaZdcZu:$BRIDGESERVER$.tld" user_id="@$MYACCOUNT$:$MYSERVER$.tld"
dentrite | time="2021-08-07T15:49:04.802860609Z" level=info msg="Producing to topic 'DendriteOutputClientData'" func="SendData\n\t" file=" [syncapi.go:51]" data_type=m.direct room_id="" user_id="@$MYACCOUNT$:$MYSERVER$.tld"

[kegsay]

Interesting, so it causes a cascading failure. The PL event is treated as invalid which means it gets dropped but then all subsequent events reference it in auth events which then fail with storage: state event IDs missing from the database (2 != 3). We probably should NOT be dropping the event entirely here, as it will be correctly signed but fail auth checks (so it's a rejected event). This won't fix the issue but it will at least make subsequent errors far less opaque (as it'll fail with gomatrixserverlib: event with ID \"$gdzUf8gGUxP3vXlGDTcxRL1UyLISPVW-D8dr5qSKbAc\" is not allowed by its auth_events: eventauth: sender with level 100 is not allowed change user level from 100 to 9001 because the new level is above the level of the sender over and over.

[Notmarrco]

I have the same error. Is there a workaround for now please ?

[nash-pillai]

Yes, see my comment at mautrix/signal#106.

[MayeulC]

I think this brought a cascading failure to the federation between our servers: @ArnoPoitt cannot see my encrypted messages anymore (whether DM or in an E2EE room).

synapse.federation.sender.per_destination_queue - 354 - WARNING - federation_transaction_transmission_loop-21109482- TX [$MYSERVER$.tld] Failed to send transaction: Failed to send request: TimeoutError: User timeout caused connection failure.
synapse.federation.federation_server - 249 - WARNING - PUT-6166836- Received another txn 1634816968887-13 from $MYSERVER$.tld while still processing 1634816968846-13
synapse.federation.federation_server - 249 - WARNING - PUT-6168829- Received another txn 1634817506390-27 from $MYSERVER$.tld while still processing 1634817502881-27
synapse.federation.federation_server - 249 - WARNING - PUT-6168830- Received another txn 1634817506867-27 from $MYSERVER$.tld while still processing 1634817502881-27

server: synapse 1.42.0

[neilalexander]

This should be fixed as of 562d742, so both 0.8.0 and 0.8.1 should contain the fix.