Skip to content
This repository has been archived by the owner on Nov 14, 2024. It is now read-only.

bot issues with latest dendrite #2902

Open
jostreff opened this issue Dec 2, 2022 · 17 comments
Open

bot issues with latest dendrite #2902

jostreff opened this issue Dec 2, 2022 · 17 comments
Labels
C-App-Services C-NATS C-Roomserver C-Sync-API T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.

Comments

@jostreff
Copy link

jostreff commented Dec 2, 2022 •
edited by S7evinK
Loading

Hi,
running dendrite 0.10.8 build from freebsd ports system with go version go1.19.3 freebsd/amd64. My bot is also go application taken from https://github.com/mautrix/whatsapp.git. This is second bot which has similar behavior.

The error message I see is:

[Dec  2, 2022 13:50:51] [Matrix/DEBUG] Starting handling of transaction 1669981851619219625 (2 PDUs)
[Dec  2, 2022 13:50:51] [Matrix/Bot/DEBUG] req #6: POST https://matrix.ostreff.info/_matrix/client/v3/rooms/%21NlumPAgUuZeRP54s:matrix.ostreff.info/join?user_id=%40whatsappbot%3Amatrix.ostreff.info <default empty object>
[Dec  2, 2022 13:50:51] [Matrix/Bot/DEBUG] req #6 (/v3/rooms/!NlumPAgUuZeRP54s:matrix.ostreff.info/join) completed in 221.753291ms with status 403 and 241 bytes of application/json body
[Dec  2, 2022 13:50:51] [Matrix/DEBUG] Failed to join room !NlumPAgUuZeRP54s:matrix.ostreff.info as @whatsappbot:matrix.ostreff.info with invite from @jostreff:matrix.ostreff.info: failed to POST /_matrix/client/v3/rooms/!NlumPAgUuZeRP54s:matrix.ostreff.info/join: M_FORBIDDEN (HTTP 403): InputRoomEvents auth failed: InputRoomEventsResponse: eventauth: "@whatsappbot:matrix.ostreff.info" is not allowed to change their membership from "leave" to "join" as join rule "invite" forbids it
[Dec  2, 2022 13:50:51] [Matrix/Bot/DEBUG] req #7: POST https://matrix.ostreff.info/_matrix/client/v3/rooms/%21NlumPAgUuZeRP54s:matrix.ostreff.info/join?user_id=%40whatsappbot%3Amatrix.ostreff.info <default empty object>
[Dec  2, 2022 13:50:51] [Matrix/DEBUG] Starting handling of transaction 1669981851956493680 (1 PDUs)
[Dec  2, 2022 13:50:51] [Matrix/Bot/DEBUG] req #7 (/v3/rooms/!NlumPAgUuZeRP54s:matrix.ostreff.info/join) completed in 149.886187ms with status 200 and 51 bytes of application/json body
[Dec  2, 2022 13:50:51] [Matrix/Bot/DEBUG] req #8: GET https://matrix.ostreff.info/_matrix/client/v3/rooms/%21NlumPAgUuZeRP54s:matrix.ostreff.info/joined_members?user_id=%40whatsappbot%3Amatrix.ostreff.info
[Dec  2, 2022 13:50:52] [Matrix/Bot/DEBUG] req #8 (/v3/rooms/!NlumPAgUuZeRP54s:matrix.ostreff.info/joined_members) completed in 98.404869ms with status 200 and 184 bytes of application/json body
[Dec  2, 2022 13:50:52] [Matrix/DEBUG] Leaving empty room !NlumPAgUuZeRP54s:matrix.ostreff.info after accepting invite from @jostreff:matrix.ostreff.info as @whatsappbot:matrix.ostreff.info
[Dec  2, 2022 13:50:52] [Matrix/Bot/DEBUG] req #9: POST https://matrix.ostreff.info/_matrix/client/v3/rooms/%21NlumPAgUuZeRP54s:matrix.ostreff.info/leave?user_id=%40whatsappbot%3Amatrix.ostreff.info {}
[Dec  2, 2022 13:50:52] [Matrix/DEBUG] Starting handling of transaction 1669981852188234221 (1 PDUs)
[Dec  2, 2022 13:50:52] [Matrix/Bot/DEBUG] req #9 (/v3/rooms/!NlumPAgUuZeRP54s:matrix.ostreff.info/leave) completed in 119.622302ms with status 200 and 2 bytes of application/json body
@HenrikSolver
Copy link
Contributor

I see the same problem with the the bot postmoogle.

Test environment

  • A completely fresh dendrite server Dendrite version 0.10.7+31f56ac3.master using SQLite.
  • User @moogle is the postmoogle bot
  • User @burk is human using gomuks as client
  • Federation disabled

The bot often fails to join the room when invited, but sometimes it succeeds. In the failing case a state reset happens when the bot joins. It also looks like the bot makes many rapid repeated join requests which seems strange. Maybe this causes dendrite to break.

Successful case

<Creating room pm2>
time="2022-12-02T19:43:13.555612735Z" 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:214" req.id=5vQrCXHITQWR req.method=POST req.path=/_matrix/client/v3/createRoom roomID="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" roomVersion=9 userID="@burk:dtest.solver.nu" user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:43:13.704631546Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s14_0_7_0_4_4_0_9_0 device_id=W4zAvUMz limit=20 req.id=IAglQ1544vfF req.method=GET req.path=/_matrix/client/v3/sync since=s12_2_7_0_4_4_0_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:43:13.796445786Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s15_0_7_0_4_4_0_9_0 device_id=W4zAvUMz limit=20 req.id=fKFDjCqjshTJ req.method=GET req.path=/_matrix/client/v3/sync since=s14_0_7_0_4_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:43:13.869879643Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s16_0_7_0_4_4_0_9_0 device_id=W4zAvUMz limit=20 req.id=whbEffu0golS req.method=GET req.path=/_matrix/client/v3/sync since=s15_0_7_0_4_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:43:14.000812311Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s17_0_7_0_4_4_0_9_0 device_id=W4zAvUMz limit=20 req.id=k4JonXOJ6CDX req.method=GET req.path=/_matrix/client/v3/sync since=s16_0_7_0_4_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:43:14.025329309Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s18_0_7_0_4_4_0_9_0 device_id=W4zAvUMz limit=20 req.id=ibOPdEk9RJUR req.method=GET req.path=/_matrix/client/v3/sync since=s17_0_7_0_4_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:43:19.131876046Z" level=debug msg="Responding to sync since client gave up or timeout was reached" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest.func1" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:276" device_id=bFWqU9TY limit=50 req.id=E9BGEhsYLcPc req.method=GET req.path=/_matrix/client/v3/sync since=s11_0_7_0_3_4_10_8_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:43:19.220348873Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s18_0_7_0_4_4_0_9_0 device_id=bFWqU9TY limit=50 req.id=rkUaUFmR9sSO req.method=GET req.path=/_matrix/client/v3/sync since=s12_0_7_0_4_4_0_9_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:43:38.977685209Z" level=error msg="buildMembershipEvent failed" func=github.com/matrix-org/dendrite/clientapi/routing.sendInvite file="github.com/matrix-org/dendrite/clientapi/routing/membership.go:267" error="gomatrixserverlib: invalid ID \"moogle\" doesn't start with '@'" req.id=UsuaeiUKKlO0 req.method=POST req.path="/_matrix/client/v3/rooms/!uYXu4Ct7E7KD0xLP:dtest.solver.nu/invite" user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:43:44.038615798Z" level=debug msg="Responding to sync since client gave up or timeout was reached" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest.func1" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:276" device_id=W4zAvUMz limit=20 req.id=IGqk5i13yPhC req.method=GET req.path=/_matrix/client/v3/sync since=s18_0_7_0_4_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:43:49.291347588Z" level=debug msg="Responding to sync since client gave up or timeout was reached" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest.func1" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:276" device_id=bFWqU9TY limit=50 req.id=En2r3WBWUOhb req.method=GET req.path=/_matrix/client/v3/sync since=s18_0_7_0_4_4_10_9_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:14.041763155Z" level=debug msg="Responding to sync since client gave up or timeout was reached" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest.func1" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:276" device_id=W4zAvUMz limit=20 req.id=0pfEO7Vam3Y6 req.method=GET req.path=/_matrix/client/v3/sync since=s18_0_7_0_4_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:19.294721526Z" level=debug msg="Responding to sync since client gave up or timeout was reached" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest.func1" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:276" device_id=bFWqU9TY limit=50 req.id=HEiyYzAKu7Cd req.method=GET req.path=/_matrix/client/v3/sync since=s18_0_7_0_4_4_10_9_0 timeout=30s user_id="@moogle:dtest.solver.nu"
<Invite user moogle to room pm2>
time="2022-12-02T19:44:19.815962715Z" level=debug msg="processing invite event" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Inviter).PerformInvite" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_invite.go:94" event_id="$MURxV1l7xssIQVjXgh76H2tqmyEl_gLMMAhaywGxarw" invitee="@moogle:dtest.solver.nu" inviter="@burk:dtest.solver.nu" origin_local=true req.id=jJFLmiI3Mspg req.method=POST req.path="/_matrix/client/v3/rooms/!uYXu4Ct7E7KD0xLP:dtest.solver.nu/invite" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" room_info_exists=true room_version=9 target_local=true user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:19.849617986Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s18_0_7_0_5_4_0_9_0 device_id=bFWqU9TY limit=50 req.id=9J6UNZ8z8YXX req.method=GET req.path=/_matrix/client/v3/sync since=s18_0_7_0_4_4_10_9_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:19.877695508Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s19_0_7_0_5_4_0_9_0 device_id=W4zAvUMz limit=20 req.id=OStMBid6EsVi req.method=GET req.path=/_matrix/client/v3/sync since=s18_0_7_0_4_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:19.892747689Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s19_0_7_0_5_4_0_10_0 device_id=W4zAvUMz limit=20 req.id=WpIx76zCty9G req.method=GET req.path=/_matrix/client/v3/sync since=s19_0_7_0_5_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:19.966847465Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s19_0_7_0_5_4_0_10_0 device_id=bFWqU9TY limit=50 req.id=k4Q9U12gNQ8E req.method=GET req.path=/_matrix/client/v3/sync since=s18_0_7_0_5_4_10_9_0 timeout=30s user_id="@moogle:dtest.solver.nu"
<user moogle joins>
time="2022-12-02T19:44:20.077112363Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.096375947Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.096625378Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.116789724Z" level=info msg="User joined room successfully" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:77" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.118721824Z" level=info msg="User joined room successfully" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:77" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.123280631Z" level=info msg="User joined room successfully" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:77" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.150816691Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s20_0_7_0_5_4_0_10_0 device_id=W4zAvUMz limit=20 req.id=WpIx76zCty9G req.method=GET req.path=/_matrix/client/v3/sync since=s19_0_7_0_5_4_10_9_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:20.150855659Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s20_0_7_0_5_4_0_10_0 device_id=bFWqU9TY limit=50 req.id=k4Q9U12gNQ8E req.method=GET req.path=/_matrix/client/v3/sync since=s18_0_7_0_5_4_10_9_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.157139760Z" level=debug msg="Setting receipt" func=github.com/matrix-org/dendrite/clientapi/routing.SetReceipt file="github.com/matrix-org/dendrite/clientapi/routing/receipt.go:41" eventID="$Raqjziq-gSPdnTB8QUqaDamNCLVQRP2m5trf30T9jY8" receiptType=m.read roomID="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" timestamp=1670010260157 userId="@burk:dtest.solver.nu"
time="2022-12-02T19:44:20.166178313Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s20_0_8_0_5_4_0_10_0 device_id=W4zAvUMz limit=20 req.id=sVNyREmEZ6x6 req.method=GET req.path=/_matrix/client/v3/sync since=s20_0_7_0_5_4_10_10_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:20.234781967Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s20_0_8_0_5_4_0_11_0 device_id=bFWqU9TY limit=50 req.id=wQTGilmpnn8L req.method=GET req.path=/_matrix/client/v3/sync since=s20_0_7_0_5_4_10_10_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.313294402Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.322536173Z" level=info msg="User joined room successfully" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:77" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.360833094Z" level=info msg="Sent event to roomserver" func=github.com/matrix-org/dendrite/clientapi/routing.SendEvent file="github.com/matrix-org/dendrite/clientapi/routing/sendevent.go:203" event_id="$2uN27DxCDXbnbEZ7-0vN0lAzzui-uA6jQinixjutgwQ" req.id=wyu93I6mdggn req.method=PUT req.path="/_matrix/client/v3/rooms/!uYXu4Ct7E7KD0xLP:dtest.solver.nu/send/m.room.message/mautrix-go_1670010260313813462_1" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" room_version=9 user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.363717180Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s21_0_8_0_5_4_0_11_0 device_id=W4zAvUMz limit=20 req.id=y0MnCowIk4WZ req.method=GET req.path=/_matrix/client/v3/sync since=s20_0_8_0_5_4_10_11_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:20.380448270Z" level=debug msg="Setting receipt" func=github.com/matrix-org/dendrite/clientapi/routing.SetReceipt file="github.com/matrix-org/dendrite/clientapi/routing/receipt.go:41" eventID="$2uN27DxCDXbnbEZ7-0vN0lAzzui-uA6jQinixjutgwQ" receiptType=m.read roomID="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" timestamp=1670010260380 userId="@burk:dtest.solver.nu"
time="2022-12-02T19:44:20.389449385Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s21_0_9_0_5_4_0_11_0 device_id=W4zAvUMz limit=20 req.id=EPkyG87giSe9 req.method=GET req.path=/_matrix/client/v3/sync since=s21_0_8_0_5_4_10_11_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:20.400389586Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s21_0_9_0_5_4_0_12_0 device_id=bFWqU9TY limit=50 req.id=Pa4NpMBfRVUU req.method=GET req.path=/_matrix/client/v3/sync since=s20_0_8_0_5_4_10_11_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.448596742Z" level=info msg="Sent event to roomserver" func=github.com/matrix-org/dendrite/clientapi/routing.SendEvent file="github.com/matrix-org/dendrite/clientapi/routing/sendevent.go:203" event_id="$4GTfc5gDBnPoOgmtWQ1JaD398Fz_jFFj3_IChOWFbRk" req.id=LJRXlrZixmOS req.method=PUT req.path="/_matrix/client/v3/rooms/!uYXu4Ct7E7KD0xLP:dtest.solver.nu/send/m.room.message/mautrix-go_1670010260391556345_2" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" room_version=9 user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.467177151Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s22_0_9_0_5_4_0_12_0 device_id=W4zAvUMz limit=20 req.id=coZ0prwaAur3 req.method=GET req.path=/_matrix/client/v3/sync since=s21_0_9_0_5_4_10_12_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:44:20.479301190Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s22_0_9_0_5_4_0_12_0 device_id=bFWqU9TY limit=50 req.id=6cN9Mo0GTecW req.method=GET req.path=/_matrix/client/v3/sync since=s21_0_9_0_5_4_10_12_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:44:20.497181147Z" level=debug msg="Setting receipt" func=github.com/matrix-org/dendrite/clientapi/routing.SetReceipt file="github.com/matrix-org/dendrite/clientapi/routing/receipt.go:41" eventID="$4GTfc5gDBnPoOgmtWQ1JaD398Fz_jFFj3_IChOWFbRk" receiptType=m.read roomID="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" timestamp=1670010260497 userId="@burk:dtest.solver.nu"
time="2022-12-02T19:44:20.503299811Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s22_0_10_0_5_4_0_12_0 device_id=W4zAvUMz limit=20 req.id=Lb3FJYPj8FPc req.method=GET req.path=/_matrix/client/v3/sync since=s22_0_9_0_5_4_10_12_0 timeout=30s user_id="@burk:dtest.solver.nu"

Failing case

<Creating room pm3>
time="2022-12-02T19:50:51.458032428Z" 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:214" req.id=e1kWGQzBKhu4 req.method=POST req.path=/_matrix/client/v3/createRoom roomID="!GfZHuH7xBitAzYdo:dtest.solver.nu" roomVersion=9 userID="@burk:dtest.solver.nu" user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:50:51.598082103Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s33_16_19_0_5_8_0_27_0 device_id=W4zAvUMz limit=20 req.id=Zy9Vv3LP0lSW req.method=GET req.path=/_matrix/client/v3/sync since=s31_16_19_0_5_8_10_27_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:50:52.064921548Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s37_16_19_0_5_8_0_27_0 device_id=W4zAvUMz limit=20 req.id=lVqk9UJuu7cY req.method=GET req.path=/_matrix/client/v3/sync since=s33_16_19_0_5_8_10_27_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:01.051453291Z" level=debug msg="Responding to sync since client gave up or timeout was reached" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest.func1" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:276" device_id=bFWqU9TY limit=50 req.id=XZsOt46wMFgx req.method=GET req.path=/_matrix/client/v3/sync since=s31_16_19_0_5_8_10_27_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:01.053761149Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s37_16_19_0_5_8_0_27_0 device_id=bFWqU9TY limit=50 req.id=fQaujuY3U7ik req.method=GET req.path=/_matrix/client/v3/sync since=s31_16_19_0_5_8_10_27_0 timeout=30s user_id="@moogle:dtest.solver.nu"
<Accidentally inviting user moogle to room pm2 again>
time="2022-12-02T19:51:16.118719840Z" level=debug msg="processing invite event" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Inviter).PerformInvite" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_invite.go:94" event_id="$_a07Z2_dAKFakJTguRCIftQYaZwqQ76oy6d0ym5Smb0" invitee="@moogle:dtest.solver.nu" inviter="@burk:dtest.solver.nu" origin_local=true req.id=weJjOfAoEzHa req.method=POST req.path="/_matrix/client/v3/rooms/!uYXu4Ct7E7KD0xLP:dtest.solver.nu/invite" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" room_info_exists=true room_version=9 target_local=true user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:16.119644190Z" level=debug msg="user already joined" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Inviter).PerformInvite" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_invite.go:180" event_id="$_a07Z2_dAKFakJTguRCIftQYaZwqQ76oy6d0ym5Smb0" invitee="@moogle:dtest.solver.nu" inviter="@burk:dtest.solver.nu" req.id=weJjOfAoEzHa req.method=POST req.path="/_matrix/client/v3/rooms/!uYXu4Ct7E7KD0xLP:dtest.solver.nu/invite" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:22.081588380Z" level=debug msg="Responding to sync since client gave up or timeout was reached" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest.func1" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:276" device_id=W4zAvUMz limit=20 req.id=7ZklzlEFaIn3 req.method=GET req.path=/_matrix/client/v3/sync since=s37_16_19_0_5_8_10_27_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:31.053924478Z" level=debug msg="Responding to sync since client gave up or timeout was reached" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest.func1" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:276" device_id=bFWqU9TY limit=50 req.id=fQaujuY3U7ik req.method=GET req.path=/_matrix/client/v3/sync since=s31_16_19_0_5_8_10_27_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:36.434818590Z" level=debug msg="syncapi received EDU data from client api" func="github.com/matrix-org/dendrite/syncapi/consumers.(*OutputTypingEventConsumer).onMessage" file="github.com/matrix-org/dendrite/syncapi/consumers/typing.go:93" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" timeout=20000 typing=true user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:36.435335004Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s37_17_19_0_5_8_0_27_0 device_id=W4zAvUMz limit=20 req.id=2IqE5Z56BBRd req.method=GET req.path=/_matrix/client/v3/sync since=s37_16_19_0_5_8_10_27_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:36.435992506Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s37_17_19_0_5_8_0_27_0 device_id=bFWqU9TY limit=50 req.id=NR1slfuupUfL req.method=GET req.path=/_matrix/client/v3/sync since=s37_16_19_0_5_8_0_27_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:37.252715946Z" level=debug msg="syncapi received EDU data from client api" func="github.com/matrix-org/dendrite/syncapi/consumers.(*OutputTypingEventConsumer).onMessage" file="github.com/matrix-org/dendrite/syncapi/consumers/typing.go:93" room_id="!uYXu4Ct7E7KD0xLP:dtest.solver.nu" timeout=0 typing=false user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:37.253210212Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s37_18_19_0_5_8_0_27_0 device_id=bFWqU9TY limit=50 req.id=Q98gBbQFomVr req.method=GET req.path=/_matrix/client/v3/sync since=s37_17_19_0_5_8_10_27_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:37.253977543Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s37_18_19_0_5_8_0_27_0 device_id=W4zAvUMz limit=20 req.id=U9C8HmxPgI8Q req.method=GET req.path=/_matrix/client/v3/sync since=s37_17_19_0_5_8_10_27_0 timeout=30s user_id="@burk:dtest.solver.nu"
<Inviting user moogle to room pm3>
time="2022-12-02T19:51:54.846380582Z" level=debug msg="processing invite event" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Inviter).PerformInvite" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_invite.go:94" event_id="$YV2iz6TUpOqzj8IGEb4NlsQvSNVfQpZyk8EDF4v3lGo" invitee="@moogle:dtest.solver.nu" inviter="@burk:dtest.solver.nu" origin_local=true req.id=wKy1dkHmrIbQ req.method=POST req.path="/_matrix/client/v3/rooms/!GfZHuH7xBitAzYdo:dtest.solver.nu/invite" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" room_info_exists=true room_version=9 target_local=true user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:54.896621035Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s37_18_19_0_7_8_0_27_0 device_id=bFWqU9TY limit=50 req.id=l98kYTVAy5Km req.method=GET req.path=/_matrix/client/v3/sync since=s37_18_19_0_5_8_10_27_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:54.902144983Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s38_18_19_0_7_8_0_27_0 device_id=W4zAvUMz limit=20 req.id=ileO48EtsuZz req.method=GET req.path=/_matrix/client/v3/sync since=s37_18_19_0_5_8_10_27_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:54.944630882Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s38_18_19_0_7_8_0_28_0 device_id=W4zAvUMz limit=20 req.id=AsZNHglg6YR8 req.method=GET req.path=/_matrix/client/v3/sync since=s38_18_19_0_7_8_10_27_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:55.030523761Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s38_18_19_0_7_8_0_28_0 device_id=bFWqU9TY limit=50 req.id=XsQyZn9uVL5I req.method=GET req.path=/_matrix/client/v3/sync since=s37_18_19_0_7_8_10_27_0 timeout=30s user_id="@moogle:dtest.solver.nu"
<user moogle atempts to join but fails>
time="2022-12-02T19:51:55.156553665Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.160772928Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.161232816Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.191028297Z" level=info msg="User joined room successfully" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:77" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.198058992Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s39_18_19_0_7_8_0_28_0 device_id=W4zAvUMz limit=20 req.id=AsZNHglg6YR8 req.method=GET req.path=/_matrix/client/v3/sync since=s38_18_19_0_7_8_10_27_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:55.198110759Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s39_18_19_0_7_8_0_28_0 device_id=bFWqU9TY limit=50 req.id=XsQyZn9uVL5I req.method=GET req.path=/_matrix/client/v3/sync since=s37_18_19_0_7_8_10_27_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.251530052Z" level=warning msg="State reset detected (removing 1 events)" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*latestEventsUpdater).latestState" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_latest_events.go:298" event_id="$l44UlMT0yL6hmthxYudh3b-AhsfKjQ3olIhaZbYc0tY" new_latest="[$l44UlMT0yL6hmthxYudh3b-AhsfKjQ3olIhaZbYc0tY $0cCSl36tvwnQ12TDzcEzGpqonsjB0nAKuAFVL6mLYuk]" new_state_nid=69 old_latest="[$0cCSl36tvwnQ12TDzcEzGpqonsjB0nAKuAFVL6mLYuk]" old_state_nid=67 room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu"
time="2022-12-02T19:51:55.263418305Z" level=debug msg="Setting receipt" func=github.com/matrix-org/dendrite/clientapi/routing.SetReceipt file="github.com/matrix-org/dendrite/clientapi/routing/receipt.go:41" eventID="$0cCSl36tvwnQ12TDzcEzGpqonsjB0nAKuAFVL6mLYuk" receiptType=m.read roomID="!GfZHuH7xBitAzYdo:dtest.solver.nu" timestamp=1670010715263 userId="@burk:dtest.solver.nu"
time="2022-12-02T19:51:55.316314746Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s39_18_20_0_7_8_0_28_0 device_id=W4zAvUMz limit=20 req.id=F3CPPBSmfpy3 req.method=GET req.path=/_matrix/client/v3/sync since=s39_18_19_0_7_8_10_28_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:55.318212203Z" level=info msg="User joined room successfully" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:77" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.324945717Z" level=warning msg="Error authing soft-failed event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:250" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$78iKCIqiQ6OpaKymkRn0GPCdk1ew6I6x13mkNCsonxM" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:51:55.339349193Z" level=debug msg="Responding to sync after wake-up" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:303" currentPos=s40_18_20_0_7_8_0_29_0 device_id=W4zAvUMz limit=20 req.id=iGqch1dyU7a1 req.method=GET req.path=/_matrix/client/v3/sync since=s39_18_20_0_7_8_10_29_0 timeout=30s user_id="@burk:dtest.solver.nu"
time="2022-12-02T19:51:55.349774965Z" level=warning msg="Stored soft-failed event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:381" context=missing error="<nil>" event_id="$78iKCIqiQ6OpaKymkRn0GPCdk1ew6I6x13mkNCsonxM" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:51:55.350123093Z" level=info msg="User joined room successfully" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:77" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.457585679Z" level=debug msg="Responding to sync immediately" func="github.com/matrix-org/dendrite/syncapi/sync.(*RequestPool).OnIncomingSyncRequest" file="github.com/matrix-org/dendrite/syncapi/sync/requestpool.go:306" currentPos=s40_18_20_0_7_8_0_29_0 device_id=bFWqU9TY limit=50 req.id=xIhPuYjDAaGV req.method=GET req.path=/_matrix/client/v3/sync since=s39_18_19_0_7_8_10_28_0 timeout=30s user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.536485670Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:51:55.546967314Z" level=warning msg="Event $sMGqJo_0CxoSppPx7kOCM8NuiKvNULhnlBGJfy7FYWw not allowed by auth events" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:214" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$sMGqJo_0CxoSppPx7kOCM8NuiKvNULhnlBGJfy7FYWw" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:51:55.548822794Z" level=warning msg="Error authing soft-failed event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:250" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$sMGqJo_0CxoSppPx7kOCM8NuiKvNULhnlBGJfy7FYWw" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:51:55.573198362Z" level=warning msg="Stored rejected event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:374" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$sMGqJo_0CxoSppPx7kOCM8NuiKvNULhnlBGJfy7FYWw" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:51:55.573374656Z" level=warning msg="Roomserver rejected event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*worker)._next" file="github.com/matrix-org/dendrite/roomserver/internal/input/input.go:293" error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$sMGqJo_0CxoSppPx7kOCM8NuiKvNULhnlBGJfy7FYWw" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:51:55.573708850Z" level=error msg="Failed to join room" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:65" error="1 : InputRoomEvents auth failed: InputRoomEventsResponse: eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:52:00.580312182Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:52:00.586620050Z" level=warning msg="Event $IoWjBRndfvZzFtRJpbzvAX8mzUEfGfjPQ2MqGh1zB_M not allowed by auth events" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:214" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$IoWjBRndfvZzFtRJpbzvAX8mzUEfGfjPQ2MqGh1zB_M" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:00.587114266Z" level=warning msg="Error authing soft-failed event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:250" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$IoWjBRndfvZzFtRJpbzvAX8mzUEfGfjPQ2MqGh1zB_M" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:00.605665599Z" level=warning msg="Stored rejected event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:374" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$IoWjBRndfvZzFtRJpbzvAX8mzUEfGfjPQ2MqGh1zB_M" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:00.605735258Z" level=warning msg="Roomserver rejected event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*worker)._next" file="github.com/matrix-org/dendrite/roomserver/internal/input/input.go:293" error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$IoWjBRndfvZzFtRJpbzvAX8mzUEfGfjPQ2MqGh1zB_M" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:00.605819753Z" level=error msg="Failed to join room" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:65" error="1 : InputRoomEvents auth failed: InputRoomEventsResponse: eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:52:05.611047605Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:52:05.621616865Z" level=warning msg="Event $fOcH6wjZgx3YXw4hHDclHammkWbkEigO4ktTpIGhiIc not allowed by auth events" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:214" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$fOcH6wjZgx3YXw4hHDclHammkWbkEigO4ktTpIGhiIc" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:05.623549123Z" level=warning msg="Error authing soft-failed event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:250" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$fOcH6wjZgx3YXw4hHDclHammkWbkEigO4ktTpIGhiIc" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:05.641258723Z" level=warning msg="Stored rejected event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:374" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$fOcH6wjZgx3YXw4hHDclHammkWbkEigO4ktTpIGhiIc" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:05.641295467Z" level=warning msg="Roomserver rejected event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*worker)._next" file="github.com/matrix-org/dendrite/roomserver/internal/input/input.go:293" error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$fOcH6wjZgx3YXw4hHDclHammkWbkEigO4ktTpIGhiIc" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:05.641398153Z" level=error msg="Failed to join room" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:65" error="1 : InputRoomEvents auth failed: InputRoomEventsResponse: eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:52:10.642854997Z" level=info msg="User requested to room join" func="github.com/matrix-org/dendrite/roomserver/internal/perform.(*Joiner).PerformJoin" file="github.com/matrix-org/dendrite/roomserver/internal/perform/perform_join.go:62" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" servers="[]" user_id="@moogle:dtest.solver.nu"
time="2022-12-02T19:52:10.650715636Z" level=warning msg="Event $42Y_eavx4nDerdW5DNF7U_-HrqVPXN4FY3eUtAvTtQw not allowed by auth events" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:214" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$42Y_eavx4nDerdW5DNF7U_-HrqVPXN4FY3eUtAvTtQw" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member
time="2022-12-02T19:52:10.651101833Z" level=warning msg="Error authing soft-failed event" func="github.com/matrix-org/dendrite/roomserver/internal/input.(*Inputer).processRoomEvent" file="github.com/matrix-org/dendrite/roomserver/internal/input/input_events.go:250" context=missing error="eventauth: \"@moogle:dtest.solver.nu\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$42Y_eavx4nDerdW5DNF7U_-HrqVPXN4FY3eUtAvTtQw" kind=KindNew origin="" room_id="!GfZHuH7xBitAzYdo:dtest.solver.nu" type=m.room.member

@kegsay kegsay added T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. and removed bug labels Dec 5, 2022
@Notmarrco
Copy link

I think I have the same issue with Mautrix-signal bridge.
I cannot invite the bot to any room, either a DM or a normal room, and I get the Power level of @signalbot:tld is not enough for m.room.message in !xxxxxxXXX:tld in the Mautrix logs and InputRoomEventsResponse: eventauth: "@signalbot:tld" is not allowed to change their membership from "leave" to "join" as join rule "invite" forbids it in monolith logs.
Sometimes (1 every 10 invites) though the join is accepted.

For all the other bridges it seems that it doesn't break anything.

@Xinayder
Copy link
Contributor

I have the same issue, setup Dendrite last weekend and installed mautrix bridges. The Go whatsapp bridge worked but the python based one didn't. It seems like the bot tries to join several times in a row, the first time succeeds but the subsequent ones fail and the bot just crashes saying it doesn't have enough power level to join the room or query its members.

@cyberb
Copy link
Contributor

cyberb commented Mar 4, 2023

I have this issue with whatsapp go, they also think it is a bug in dendrite: mautrix/whatsapp#573

@cyberb
Copy link
Contributor

cyberb commented Mar 4, 2023 

matrix[2596]: time="2023-03-03T23:39:18.371763425Z" level=warning msg="Roomserver rejected event" error="eventauth: \"@whatsappbot:matrix.buster.com\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" event_id="$iMWAAQ7h-hsb1qrF5UNxvPfWUeBlOFL9UYZjz55CNRo" room_id="!2laTThkDZUsUBRdx:matrix.buster.com" type=m.room.member
matrix[2596]: time="2023-03-03T23:39:18.372027928Z" level=error msg="Failed to join room" error="1 : InputRoomEvents auth failed: InputRoomEventsResponse: eventauth: \"@whatsappbot:matrix.buster.com\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" room_id="!2laTThkDZUsUBRdx:matrix.buster.com" servers="[]" user_id="@whatsappbot:matrix.buster.com"
whatsapp[2804]: 2023-03-03T23:39:18Z DBG Request completed as_user_id=@whatsappbot:matrix.buster.com duration=39.749083ms method=POST path=/v3/rooms/!2laTThkDZUsUBRdx:matrix.buster.com/join req_id=9 response_length=239 response_mime=application/json status_code=403
whatsapp[2804]: 2023-03-03T23:39:18Z WRN Failed to join room with invite error="failed to POST /_matrix/client/v3/rooms/!2laTThkDZUsUBRdx:matrix.buster.com/join: M_FORBIDDEN (HTTP 403): InputRoomEvents auth failed: InputRoomEventsResponse: eventauth: \"@whatsappbot:matrix.buster.com\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" room_id=!2laTThkDZUsUBRdx:matrix.buster.com sender=@user:matrix.buster.com target=@whatsappbot:matrix.buster.com

I would like to fix it, @kegsay is there any hints at where it may be?

@cyberb
Copy link
Contributor

cyberb commented Mar 4, 2023

What I see so far is this code: https://github.com/matrix-org/gomatrixserverlib/blob/main/eventauth.go#L1211

case Join:
	if m.oldMember.Membership == Leave && (m.joinRule.JoinRule == Restricted || m.joinRule.JoinRule == KnockRestricted) {
		if err := m.membershipAllowedSelfForRestrictedJoin(); err != nil {
			return err
		}
	}
	// A user that is not in the room is allowed to join if the room
	// join rules are "public".
	if m.oldMember.Membership == Leave && m.joinRule.JoinRule == Public {
		return nil
	}
	// An invited user is always allowed to join, regardless of the join rule
	if m.oldMember.Membership == Invite {
		return nil
	}
	// A joined user is allowed to update their join.
	if m.oldMember.Membership == Join {
		return nil
	}
	return m.membershipFailed(
		"join rule %q forbids it", m.joinRule.JoinRule,
	)

I think bot comes here with

m.joinRule.JoinRule = Invite
m.oldMember.Membership = Leave

I am not sure what values are expected for a bot and if they are wrong or logic is wrong

@cyberb cyberb mentioned this issue Mar 7, 2023
Closed
@nlpn00b
Copy link

nlpn00b commented Mar 18, 2023 •
edited
Loading

Same problem here with mautrix-signal on Dendrite. Fixing it for an affected room is possible by removing references to the room in the bots database like this:

sudo -u postgres psql

\c mautrix-signal

DELETE FROM portal WHERE room_id = '!123xyz:example.com';
DELETE FROM mx_room_state WHERE room_id = '!123xyz:example.com';
DELETE FROM mx_user_profile WHERE room_id = '!123xyz:example.com';

save

\q

No issues with the other mautrix bots, only mautrix-signal

@cyberb
Copy link
Contributor

cyberb commented Mar 18, 2023 •
edited
Loading

for whatsapp this does not help, in my test install with single user, portal and mx_room_state are empty. mx_user_profile contains one line for the bot with membership leave, removing the record does not help, cannot chat with the bot and record is created again.

matrix.matrix[8767]: time="2023-03-18T16:48:03.449738585Z" level=error msg="Failed to join room" error="1 : InputRoomEvents auth failed: InputRoomEventsResponse: eventauth: \"@whatsappbot:matrix.***\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" room_id="!1dGUySkP54OzFHEW:matrix.***" servers="[]" user_id="@whatsappbot:matrix.***"
matrix.whatsapp[8772]: 2023-03-18T16:48:03Z DBG Request completed as_user_id=@whatsappbot:matrix.*** duration=114.776731 method=POST path=/v3/rooms/!1dGUySkP54OzFHEW:matrix.***/join req_id=16 response_length=251 response_mime=application/json status_code=403
matrix.whatsapp[8772]: 2023-03-18T16:48:03Z WRN Failed to join room with invite error="failed to POST /_matrix/client/v3/rooms/!1dGUySkP54OzFHEW:matrix.***/join: M_FORBIDDEN (HTTP 403): InputRoomEvents auth failed: InputRoomEventsResponse: eventauth: \"@whatsappbot:matrix.***\" is not allowed to change their membership from \"leave\" to \"join\" as join rule \"invite\" forbids it" room_id=!1dGUySkP54OzFHEW:matrix.*** sender=@test:matrix.*** target=@whatsappbot:matrix.***


whatsapp=# select * from mx_user_profile ;
             room_id          |         user_id         | membership | displayname | avatar_url 
------------------------------+-------------------------+------------+-------------+------------
 !1dGUySkP54OzFHEW:matrix.*** | @whatsappbot:matrix.*** | leave      |             |

@tux93
Copy link

tux93 commented Mar 19, 2023

I ran into the same issue while trying to set up mautrix-discord today and found a workaround:
Manually create a public room, invite the bot, switch to invite only afterwards.

@cyberb
Copy link
Contributor

cyberb commented Mar 19, 2023

Manually create a public room, invite the bot, switch to invite only afterwards.

Nice, this helped with whatsapp as well, I had to invite twice (bot is very shy).

@S7evinK
Copy link
Contributor

S7evinK commented Mar 30, 2023

We've recently merged #3020, were we fixed an issue with invitations being sent twice to bridges (or worse, more than twice). That possibly resulted in the behavior mentioned above.
Would it be possible for someone to test if that may resolved the issues?

@HenrikSolver
Copy link
Contributor

Just tried Dendrite 28d3e29 with postmoogle (same setup used when reporting), and it seems to work fine.
Thanks a lot.

@cyberb
Copy link
Contributor

cyberb commented Apr 6, 2023

with whatstapp bot it is the same if not worse even public room workaround does not work any more, Also I think it is not 100% not working I saw once bot actually responded in a direct chat.

my logs:

Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Sending request as_user_id=@whatsappbot:matrix.buster.com body={} method=POST req_id=9 url=http://unix/_matrix/client/v3/rooms/%21WrX4lNJLWw7CPJku:matrix.buster.com/join?user_id=%40whatsappbot%3Amatrix.buster.com
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.855455061Z" level=info msg="User requested to room join" room_id="!WrX4lNJLWw7CPJku:matrix.buster.com" servers="[]" user_id="@whatsappbot:matrix.buster.com"
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.870132029Z" level=debug msg="Received data from client API server" room_id="!WrX4lNJLWw7CPJku:matrix.buster.com" type=m.fully_read
Apr 05 22:21:13 2871ebd9569c nginx[2812]: 2871ebd9569c nginx: 192.168.176.5 - - [05/Apr/2023:22:21:13 +0000] "POST /_matrix/client/r0/rooms/!WrX4lNJLWw7CPJku%3Amatrix.buster.com/read_markers HTTP/1.1" 200 2 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:104.0) Gecko/20100101 Firefox/100.0"
Apr 05 22:21:13 2871ebd9569c nginx[963]: 2871ebd9569c nginx: 192.168.176.5 - - [05/Apr/2023:22:21:13 +0000] "POST /_matrix/client/r0/rooms/!WrX4lNJLWw7CPJku%3Amatrix.buster.com/read_markers HTTP/2.0" 200 2 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:104.0) Gecko/20100101 Firefox/100.0"
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.872624818Z" level=debug msg="Responding to sync after wake-up" currentPos=s37_2_0_0_34_42_7_9_0 device_id=AvYfIt-s limit=20 req.id=EQ1ffZv6juiN req.method=GET req.path=/_matrix/client/r0/sync since=s37_2_0_0_34_40_7_9_0 timeout=30s user_id="@user:matrix.buster.com"
Apr 05 22:21:13 2871ebd9569c nginx[2812]: 2871ebd9569c nginx: 192.168.176.5 - - [05/Apr/2023:22:21:13 +0000] "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s37_2_0_0_34_40_7_9_0 HTTP/1.1" 200 342 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:104.0) Gecko/20100101 Firefox/100.0"
Apr 05 22:21:13 2871ebd9569c nginx[963]: 2871ebd9569c nginx: 192.168.176.5 - - [05/Apr/2023:22:21:13 +0000] "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s37_2_0_0_34_40_7_9_0 HTTP/2.0" 200 342 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:104.0) Gecko/20100101 Firefox/100.0"
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.896429127Z" level=debug msg="Appservice worker sending 1 events(s) from roomserver" appservice=whatsapp
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Starting handling of transaction content={"pdu":1} transaction_id=1680733273895257076
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.903063593Z" level=info msg="User joined room successfully" room_id="!WrX4lNJLWw7CPJku:matrix.buster.com" servers="[]" user_id="@whatsappbot:matrix.buster.com"
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Request completed as_user_id=@whatsappbot:matrix.buster.com duration=50.613707 method=POST path=/v3/rooms/!WrX4lNJLWw7CPJku:matrix.buster.com/join req_id=9 response_length=49 response_mime=application/json status_code=200
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Sending request as_user_id=@whatsappbot:matrix.buster.com method=GET req_id=10 url=http://unix/_matrix/client/v3/rooms/%21WrX4lNJLWw7CPJku:matrix.buster.com/joined_members?user_id=%40whatsappbot%3Amatrix.buster.com
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Finished dispatching events from transaction transaction_id=1680733273895257076
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Request completed as_user_id=@whatsappbot:matrix.buster.com duration=3.809919 method=GET path=/v3/rooms/!WrX4lNJLWw7CPJku:matrix.buster.com/joined_members req_id=10 response_length=78 response_mime=application/json status_code=200
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Leaving empty room after accepting invite room_id=!WrX4lNJLWw7CPJku:matrix.buster.com sender=@user:matrix.buster.com target=@whatsappbot:matrix.buster.com
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Sending request as_user_id=@whatsappbot:matrix.buster.com body={} method=POST req_id=11 url=http://unix/_matrix/client/v3/rooms/%21WrX4lNJLWw7CPJku:matrix.buster.com/leave?user_id=%40whatsappbot%3Amatrix.buster.com
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.908059459Z" level=info msg="User requested to leave join" room_id="!WrX4lNJLWw7CPJku:matrix.buster.com" user_id="@whatsappbot:matrix.buster.com"
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.915285450Z" level=debug msg="Responding to sync immediately" currentPos=s44_2_0_0_34_42_7_11_0 device_id=AvYfIt-s limit=20 req.id=yERUwk3fn5kJ req.method=GET req.path=/_matrix/client/r0/sync since=s37_2_0_0_34_42_7_11_0 timeout=30s user_id="@user:matrix.buster.com"
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.918684594Z" level=debug msg="Applied history visibility (sync)" after=1 before=1 duration=1.352186ms room_id="!WrX4lNJLWw7CPJku:matrix.buster.com"
Apr 05 22:21:13 2871ebd9569c nginx[2811]: 2871ebd9569c nginx: 192.168.176.5 - - [05/Apr/2023:22:21:13 +0000] "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s37_2_0_0_34_42_7_11_0 HTTP/1.1" 200 1052 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:104.0) Gecko/20100101 Firefox/100.0"
Apr 05 22:21:13 2871ebd9569c nginx[963]: 2871ebd9569c nginx: 192.168.176.5 - - [05/Apr/2023:22:21:13 +0000] "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s37_2_0_0_34_42_7_11_0 HTTP/2.0" 200 1052 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:104.0) Gecko/20100101 Firefox/100.0"
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.933698699Z" level=debug msg="Appservice worker sending 1 events(s) from roomserver" appservice=whatsapp
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Starting handling of transaction content={"pdu":1} transaction_id=1680733273933375099
Apr 05 22:21:13 2871ebd9569c matrix.matrix[2699]: time="2023-04-05T22:21:13.936990156Z" level=info msg="User left room successfully" room_id="!WrX4lNJLWw7CPJku:matrix.buster.com" user_id="@whatsappbot:matrix.buster.com"
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Request completed as_user_id=@whatsappbot:matrix.buster.com duration=29.592432 method=POST path=/v3/rooms/!WrX4lNJLWw7CPJku:matrix.buster.com/leave req_id=11 response_length=2 response_mime=application/json status_code=200
Apr 05 22:21:13 2871ebd9569c matrix.whatsapp[2690]: 2023-04-05T22:21:13Z DBG Finished dispatching events from transaction

@Xinayder
Copy link
Contributor

Just tried this commit with the instagram bridge, the bot worked without any issues so far. I also tried the workaround mentioned by @tux93 to create a room and invite the bot (I tried it before this commit was merged) and it also worked.

@ibeckermayer ibeckermayer mentioned this issue Apr 16, 2023
Closed
@ibeckermayer ibeckermayer mentioned this issue May 8, 2023
Merged
@S7evinK
Copy link
Contributor

S7evinK commented Nov 29, 2023

From the looks of mautrix/slack#41, this is most likely a race condition between the syncapi (handling /joined_members) and the appservice. (and probably explains more of the bridge issues)
If the AS handles the event before the syncapi had a chance, the bridge will be sad that there are no users and issues a /leave

@cyberb
Copy link
Contributor

cyberb commented Nov 29, 2023

FYI: good news, this seems to have fixed all my go bridge bot invite issues (whatsapp/slack): #3078

@S7evinK
Copy link
Contributor

S7evinK commented Dec 2, 2023

So, according to my investigation, this is caused by #2827
A possible solution is in #3277

@matrixbot matrixbot mentioned this issue Nov 1, 2024
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
C-App-Services C-NATS C-Roomserver C-Sync-API T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
9 participants
@cyberb @Xinayder @tux93 @Notmarrco @S7evinK @kegsay @HenrikSolver @jostreff @nlpn00b