send_join response with unverifiable auth events makes roomserver panic

[matrixbot]

This issue was originally created by @richvdh at matrix-org/dendrite#2028.

matrix-org/complement#216 adds a test which causes complement to return a send_join response with state events which rely on unverifiable auth_events.

This seems to make dendrite panic:

=== RUN   TestJoinFederatedRoomWithUnverifiableAuthEvents
    TestJoinFederatedRoomWithUnverifiableAuthEvents: federation_room_join_with_unverifiable_auth_events_test.go:22: Deploy times: 5.500485967s blueprints, 1.512442276s containers
=== RUN   TestJoinFederatedRoomWithUnverifiableAuthEvents//send_join_response_with_state_with_unverifiable_auth_events_shouldn't_block_room_join
    TestJoinFederatedRoomWithUnverifiableAuthEvents//send_join_response_with_state_with_unverifiable_auth_events_shouldn't_block_room_join: federation_room_join_with_unverifiable_auth_events_test.go:63: Created badly signed auth event $xMsk0uHLwrIdKxe52D0n4o22m5Cj5c70ah2C5WhLwxQ
    TestJoinFederatedRoomWithUnverifiableAuthEvents//send_join_response_with_state_with_unverifiable_auth_events_shouldn't_block_room_join: federation_room_join_with_unverifiable_auth_events_test.go:86: Created state event $56-g3o9Xp5c9P1UjrYiSf3DUcOuHnUDaC6MD_RFD9qE
    TestJoinFederatedRoomWithUnverifiableAuthEvents: server.go:96: Server.UnexpectedRequestsAreErrors=false received unexpected request to server: GET /_matrix/federation/v1/event/$xMsk0uHLwrIdKxe52D0n4o22m5Cj5c70ah2C5WhLwxQ
    TestJoinFederatedRoomWithUnverifiableAuthEvents//send_join_response_with_state_with_unverifiable_auth_events_shouldn't_block_room_join: client.go:368: POST hs1/_matrix/client/r0/join/#UnverifiableAuthEvents:host.docker.internal => error: EOF (779.688095ms)
    TestJoinFederatedRoomWithUnverifiableAuthEvents//send_join_response_with_state_with_unverifiable_auth_events_shouldn't_block_room_join: federation_room_join_with_unverifiable_auth_events_test.go:89: CSAPI.DoFunc response returned error: Post "http://localhost:49669/_matrix/client/r0/join/%23UnverifiableAuthEvents:host.docker.internal": EOF
2021/10/22 15:22:10 ============================================


2021/10/22 15:22:10 86fbf7f35bf54b4d29760114ec51db0f7db026b23c4ea3227f76d8da0a99fdd4 : Server logs:
time="2021-10-22T14:22:01.890539909Z" level=info msg="Dendrite version 0.5.0" func="NewBaseDendrite\n\t" file=" [base.go:114]"
time="2021-10-22T14:22:02.091964742Z" level=info msg="Enabling MSC" func="Enable\n\t" file=" [mscs.go:31]" context=missing msc=msc2836
time="2021-10-22T14:22:02.109212946Z" level=info msg="Enabling MSC" func="Enable\n\t" file=" [mscs.go:31]" context=missing msc=msc2946
time="2021-10-22T14:22:02.111915723Z" level=info msg="Enabling MSC" func="Enable\n\t" file=" [mscs.go:31]" context=missing msc=msc2444
time="2021-10-22T14:22:02.112106283Z" level=info msg="Enabling MSC" func="Enable\n\t" file=" [mscs.go:31]" context=missing msc=msc2753
time="2021-10-22T14:22:02.113100401Z" level=info msg="Starting external Monolith listener on :8448" func="func2\n\t" file=" [base.go:432]"
time="2021-10-22T14:22:02.113194699Z" level=info msg="Starting external Monolith listener on :8008" func="func2\n\t" file=" [base.go:432]"
time="2021-10-22T14:22:02.161080194Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=gGSL5jG0RzDa req.method=GET req.path=/_matrix/client/versions
time="2021-10-22T14:22:02.161793844Z" level=trace msg="Responding (239 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=gGSL5jG0RzDa req.method=GET req.path=/_matrix/client/versions
time="2021-10-22T14:22:09.871360151Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=aZvVEGLuLAas req.method=POST req.path="/_matrix/client/r0/join/#UnverifiableAuthEvents:host.docker.internal"
time="2021-10-22T14:22:09.871941870Z" level=trace msg="Outgoing request" func="DoHTTPRequest\n\t" file=" [client.go:500]" out.req.ID=J8teq739INRV out.req.method=GET out.req.uri="matrix://host.docker.internal/_matrix/federation/v1/query/directory?room_alias=%23UnverifiableAuthEvents%3Ahost.docker.internal" req.id=aZvVEGLuLAas req.method=POST req.path="/_matrix/client/r0/join/#UnverifiableAuthEvents:host.docker.internal" user_id="@alice:hs1"
time="2021-10-22T14:22:10.131524306Z" level=trace msg="Outgoing request returned" func="DoHTTPRequest\n\t" file=" [client.go:517]" out.req.ID=J8teq739INRV out.req.code=200 out.req.duration_ms=259 out.req.method=GET out.req.uri="matrix://host.docker.internal/_matrix/federation/v1/query/directory?room_alias=%23UnverifiableAuthEvents%3Ahost.docker.internal" req.id=aZvVEGLuLAas req.method=POST req.path="/_matrix/client/r0/join/#UnverifiableAuthEvents:host.docker.internal" user_id="@alice:hs1"
time="2021-10-22T14:22:10.132256828Z" level=trace msg="Outgoing request" func="DoHTTPRequest\n\t" file=" [client.go:500]" out.req.ID=xjkbIScOGqhk out.req.method=GET out.req.uri="matrix://host.docker.internal/_matrix/federation/v1/make_join/%210:host.docker.internal/@alice:hs1?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=7" req.id=aZvVEGLuLAas req.method=POST req.path="/_matrix/client/r0/join/#UnverifiableAuthEvents:host.docker.internal" user_id="@alice:hs1"
time="2021-10-22T14:22:10.158945020Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=yvIeuW8Ohbly req.method=GET req.path=/_matrix/key/v2/server
time="2021-10-22T14:22:10.159302127Z" level=trace msg="Responding (289 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=yvIeuW8Ohbly req.method=GET req.path=/_matrix/key/v2/server
time="2021-10-22T14:22:10.160185932Z" level=trace msg="Outgoing request returned" func="DoHTTPRequest\n\t" file=" [client.go:517]" out.req.ID=xjkbIScOGqhk out.req.code=200 out.req.duration_ms=27 out.req.method=GET out.req.uri="matrix://host.docker.internal/_matrix/federation/v1/make_join/%210:host.docker.internal/@alice:hs1?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=7" req.id=aZvVEGLuLAas req.method=POST req.path="/_matrix/client/r0/join/#UnverifiableAuthEvents:host.docker.internal" user_id="@alice:hs1"
time="2021-10-22T14:22:10.161615676Z" level=trace msg="Outgoing request" func="DoHTTPRequest\n\t" file=" [client.go:500]" context=missing out.req.ID=KmE91LpVOKeA out.req.method=PUT out.req.uri="matrix://host.docker.internal/_matrix/federation/v2/send_join/%210:host.docker.internal/$o56xizY_6obONrMBYkKR8huPoB1aip5VMRHnnNNst-o"
time="2021-10-22T14:22:10.186838601Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=AfdQu1Dx3R4A req.method=GET req.path=/_matrix/key/v2/server
time="2021-10-22T14:22:10.187095348Z" level=trace msg="Responding (289 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=AfdQu1Dx3R4A req.method=GET req.path=/_matrix/key/v2/server
time="2021-10-22T14:22:10.188262902Z" level=trace msg="Outgoing request returned" func="DoHTTPRequest\n\t" file=" [client.go:517]" context=missing out.req.ID=KmE91LpVOKeA out.req.code=200 out.req.duration_ms=26 out.req.method=PUT out.req.uri="matrix://host.docker.internal/_matrix/federation/v2/send_join/%210:host.docker.internal/$o56xizY_6obONrMBYkKR8huPoB1aip5VMRHnnNNst-o"
time="2021-10-22T14:22:10.190150762Z" level=info msg="Checking event signatures for 10 events of room state" func="Check\n\t" file=" [federationtypes.go:492]" context=missing
time="2021-10-22T14:22:10.190709858Z" level=info msg="Fetching 1 key(s)" func="handleFetcherKeys\n\t" file=" [api.go:208]" fetcher_name=DirectKeyFetcher
time="2021-10-22T14:22:10.191137940Z" level=trace msg="Outgoing request" func="DoHTTPRequest\n\t" file=" [client.go:500]" context=missing out.req.ID=vsaMkSJTVJRm out.req.method=GET out.req.uri="matrix://host.docker.internal/_matrix/key/v2/server"
time="2021-10-22T14:22:10.203958599Z" level=trace msg="Outgoing request returned" func="DoHTTPRequest\n\t" file=" [client.go:517]" context=missing out.req.ID=vsaMkSJTVJRm out.req.code=200 out.req.duration_ms=12 out.req.method=GET out.req.uri="matrix://host.docker.internal/_matrix/key/v2/server"
time="2021-10-22T14:22:10.222840762Z" level=info msg="Updated 1 of 2 key(s) in database (0 keys remaining)" func="handleFetcherKeys\n\t" file=" [api.go:262]" fetcher_name=DirectKeyFetcher
time="2021-10-22T14:22:10.244357023Z" level=error msg="Signature validation failed for event \"$xMsk0uHLwrIdKxe52D0n4o22m5Cj5c70ah2C5WhLwxQ\"" func="Check\n\t" file=" [federationtypes.go:505]" error="Bad signature from \"host.docker.internal\" with ID \"ed25519:complement\""
time="2021-10-22T14:22:10.246389282Z" level=trace msg="Outgoing request" func="DoHTTPRequest\n\t" file=" [client.go:500]" context=missing out.req.ID=2ONfZc0eKxVd out.req.method=GET out.req.uri="matrix://host.docker.internal/_matrix/federation/v1/event/$xMsk0uHLwrIdKxe52D0n4o22m5Cj5c70ah2C5WhLwxQ"
time="2021-10-22T14:22:10.284830936Z" level=trace msg="Outgoing request returned" func="DoHTTPRequest\n\t" file=" [client.go:517]" context=missing out.req.ID=2ONfZc0eKxVd out.req.code=404 out.req.duration_ms=38 out.req.method=GET out.req.uri="matrix://host.docker.internal/_matrix/federation/v1/event/$xMsk0uHLwrIdKxe52D0n4o22m5Cj5c70ah2C5WhLwxQ"
time="2021-10-22T14:22:10.285313712Z" level=warning msg="Discarding 1 auth/state event(s) due to invalid signatures" func="Check\n\t" file=" [federationtypes.go:529]" context=missing
time="2021-10-22T14:22:10.303868127Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$fHOxns6iDBf0tK57g6R7th4tOc5AlqE_yDXGVE19eRM" room="!0:host.docker.internal" sender="@charlie:host.docker.internal" type=m.room.create
time="2021-10-22T14:22:10.339721640Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$Hzv2MPFN6HEV4cBmmfiMlJjDccqRwBmx3QUaZATnTIo" room="!0:host.docker.internal" sender="@charlie:host.docker.internal" type=m.room.member
time="2021-10-22T14:22:10.385361850Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$KVnCNcThBzzDBLj-6xsgNJNiOiun5gDRhgwBZQ72F4M" room="!0:host.docker.internal" sender="@charlie:host.docker.internal" type=m.room.power_levels
time="2021-10-22T14:22:10.426644862Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$YCC4wj-HmXpGAIqJj54CK_SJMqZt_LO22fePCkhSC0U" room="!0:host.docker.internal" sender="@charlie:host.docker.internal" type=m.room.join_rules
time="2021-10-22T14:22:10.477681491Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$o56xizY_6obONrMBYkKR8huPoB1aip5VMRHnnNNst-o" room="!0:host.docker.internal" sender="@alice:hs1" type=m.room.member
time="2021-10-22T14:22:10.481296216Z" level=error msg="helpers.CheckAuthEvents failed for event, rejecting event" func="processRoomEvent\n\t" file=" [input_events.go:106]" auth_event_ids="[$fHOxns6iDBf0tK57g6R7th4tOc5AlqE_yDXGVE19eRM $KVnCNcThBzzDBLj-6xsgNJNiOiun5gDRhgwBZQ72F4M $xMsk0uHLwrIdKxe52D0n4o22m5Cj5c70ah2C5WhLwxQ]" error="db.StateEntriesForEventIDs: storage: state event IDs missing from the database (2 != 3)" event_id="$56-g3o9Xp5c9P1UjrYiSf3DUcOuHnUDaC6MD_RFD9qE"
time="2021-10-22T14:22:10.522509301Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$56-g3o9Xp5c9P1UjrYiSf3DUcOuHnUDaC6MD_RFD9qE" room="!0:host.docker.internal" sender="@charlie:host.docker.internal" type=m.room.member
panic: runtime error: index out of range [0] with length 0

goroutine 193 [running]:
github.com/matrix-org/dendrite/roomserver/storage/shared.(*Database).AddState(0xc000330240, 0x146a7c0, 0xc000038058, 0x1, 0xc0004bd620, 0x1, 0x4, 0xc0004bd6e0, 0x0, 0x1, ...)
	/build/roomserver/storage/shared/storage.go:171 +0x6fa
github.com/matrix-org/dendrite/roomserver/state.(*StateResolution).CalculateAndStoreStateAfterEvents(0xc000786bd8, 0x146a7c0, 0xc000038058, 0xc00009b590, 0x1, 0x1, 0xffffffffffffffff, 0xffffffffffffffff, 0xffffffffffffffff)
	/build/roomserver/state/state.go:587 +0x530
github.com/matrix-org/dendrite/roomserver/internal/input.(*latestEventsUpdater).latestState(0xc000787000, 0x1d2e270, 0x0)
	/build/roomserver/internal/input/input_latest_events.go:246 +0x28c
github.com/matrix-org/dendrite/roomserver/internal/input.(*latestEventsUpdater).doUpdateLatestEvents(0xc000787000, 0x146a7c0, 0xc000038058)
	/build/roomserver/internal/input/input_latest_events.go:158 +0x379
github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).updateLatestEvents(0xc00031c7e0, 0x146a7c0, 0xc000038058, 0xc0006d9680, 0x1, 0x1, 0x0, 0x5, 0x3, 0x5, ...)
	/build/roomserver/internal/input/input_latest_events.go:77 +0x2eb
github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent(0xc00031c7e0, 0x146a7c0, 0xc000038058, 0xc00061a240, 0x0, 0x0, 0x0, 0x0)
	/build/roomserver/internal/input/input_events.go:195 +0x1773
github.com/matrix-org/dendrite/roomserver/internal/input.(*inputWorker).start(0xc000121520)
	/build/roomserver/internal/input/input.go:79 +0x286
created by github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).InputRoomEvents
	/build/roomserver/internal/input/input.go:201 +0x4e7
2021/10/22 15:22:10 ============== 86fbf7f35bf54b4d29760114ec51db0f7db026b23c4ea3227f76d8da0a99fdd4 : END LOGS ==============

[matrixbot]

This comment was originally posted by @kegsay at matrix-org/dendrite#2028 (comment).

Not fixed - matrix-org/dendrite#2800