Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add test case reproducing matrix-org/synapse#5677 for local users #199

Merged
merged 26 commits into from
Nov 15, 2021

Conversation

DMRobertson
Copy link
Contributor

Limited golang experience; feedback graciously accepted

@DMRobertson DMRobertson requested a review from a team August 23, 2021 15:39
surprised that's not part of the standard "go" executable if go fmt is!
@DMRobertson
Copy link
Contributor Author

The new test case seems to fail when ran against dendrite, because the first request to /register gets a 400. Am I doing something obviously wrong here?

@@ -0,0 +1,64 @@
// +build !synapse_blacklist

// Rationale for being included in Synapse's blacklist: https://github.com/matrix-org/synapse/issues/5677
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You probably don't want this on Synapse's blacklist.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My thinking was that I wouldn't want synapse CI to suddenly light up red. But maybe your point is "it should do!"


alice := deployment.Client(t, "hs1", "@alice:hs1")
bob := deployment.RegisterUser(t, "hs1", "bob", "bob-pw")
eve := deployment.RegisterUser(t, "hs1", "eve", "eve-pw")
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These passwords will be too short for some servers, which is probably why it 400s on Dendrite.

alice.JoinRoom(t, privateRoom, nil)

// Alice reveals her private name to Bob
alice.MustDo(
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Prefer MustDoFunc. MustDo is the older format which doesn't allow for vargs and will be removed in the future. MustDoFunc also logs HTTP response bodies on error.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will do, thanks. Mind if I mark MustDo as deprecated?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yup!

tests/csapi/user_directory_display_names_test.go Outdated Show resolved Hide resolved
tests/csapi/user_directory_display_names_test.go Outdated Show resolved Hide resolved
bob := deployment.RegisterUser(t, "hs1", "bob", "bob-pw")
eve := deployment.RegisterUser(t, "hs1", "eve", "eve-pw")

t.Run("Usernames specific to a room aren't leaked in the user directory", func(t *testing.T) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's no real need to do this as a subtest, unless you plan to add more tests around username leaks?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's fair. Could add one for avatar leaks too perhaps.

@DMRobertson
Copy link
Contributor Author

Dendrite now failing with

2021-08-24T17:40:09.2705186Z === RUN   TestRoomSpecificUsernameNotLeaked
2021-08-24T17:40:09.2706068Z     user_directory_display_names_test.go:26: Deploy times: 5.884971ms blueprints, 742.587855ms containers
2021-08-24T17:40:09.2706820Z     client.go:407: POST hs1/_matrix/client/r0/register => 200 OK (15.151724ms)
2021-08-24T17:40:09.2707457Z     client.go:407: POST hs1/_matrix/client/r0/register => 200 OK (18.278508ms)
2021-08-24T17:40:09.2708093Z     client.go:407: POST hs1/_matrix/client/r0/createRoom => 200 OK (196.555509ms)
2021-08-24T17:40:09.2708755Z     client.go:407: POST hs1/_matrix/client/r0/createRoom => 200 OK (186.582759ms)
2021-08-24T17:40:09.2709359Z     client.go:407: GET hs1/_matrix/client/r0/sync => 200 OK (11.752541ms)
2021-08-24T17:40:09.2710039Z     client.go:407: POST hs1/_matrix/client/r0/join/!34PPQGpLUub2aLe2:hs1 => 200 OK (39.789099ms)
2021-08-24T17:40:09.2710905Z     client.go:407: PUT hs1/_matrix/client/r0/rooms/!34PPQGpLUub2aLe2:hs1/state/m.room.member/@alice:hs1 => 200 OK (55.788718ms)
2021-08-24T17:40:09.2712276Z     client.go:407: POST hs1/_matrix/client/r0/user_directory/search => 500 Internal Server Error (3.236384ms)
2021-08-24T17:40:09.2714039Z     user_directory_display_names_test.go:59: CSAPI.MustDoFunc response return non-2xx code: 500 Internal Server Error - body: {"message":"rsAPI.QueryKnownUsers: sql: no rows in result set"}
Logs
2021-08-24T17:40:09.2715360Z 2021/08/24 17:39:26 ============================================
2021-08-24T17:40:09.2715624Z 
2021-08-24T17:40:09.2715822Z 
2021-08-24T17:40:09.2716691Z 2021/08/24 17:39:26 013673f35bbc9ea8fb2dd61dfc3fc903e36857b69b623d7a66e8f206ca02eecb : Server logs:
2021-08-24T17:40:09.2718163Z time="2021-08-24T17:39:26.119102108Z" level=info msg="Dendrite version 0.5.0" func="NewBaseDendrite\n\t" file=" [base.go:113]"
2021-08-24T17:40:09.2719717Z time="2021-08-24T17:39:26.162532389Z" level=info msg="Enabling MSC" func="Enable\n\t" file=" [mscs.go:31]" context=missing msc=msc2836
2021-08-24T17:40:09.2721114Z time="2021-08-24T17:39:26.164854078Z" level=info msg="Enabling MSC" func="Enable\n\t" file=" [mscs.go:31]" context=missing msc=msc2946
2021-08-24T17:40:09.2722947Z time="2021-08-24T17:39:26.165551174Z" level=info msg="Enabling MSC" func="Enable\n\t" file=" [mscs.go:31]" context=missing msc=msc2444
2021-08-24T17:40:09.2724338Z time="2021-08-24T17:39:26.165601574Z" level=info msg="Enabling MSC" func="Enable\n\t" file=" [mscs.go:31]" context=missing msc=msc2753
2021-08-24T17:40:09.2725992Z time="2021-08-24T17:39:26.165942572Z" level=info msg="Starting external Monolith listener on :8448" func="func2\n\t" file=" [base.go:429]"
2021-08-24T17:40:09.2727169Z time="2021-08-24T17:39:26.166092271Z" level=info msg="Starting external Monolith listener on :8008" func="func2\n\t" file=" [base.go:429]"
2021-08-24T17:40:09.2728652Z time="2021-08-24T17:39:26.174841027Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=CvHgppkVX06R req.method=GET req.path=/_matrix/client/versions
2021-08-24T17:40:09.2730376Z time="2021-08-24T17:39:26.174981427Z" level=trace msg="Responding (239 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=CvHgppkVX06R req.method=GET req.path=/_matrix/client/versions
2021-08-24T17:40:09.2732326Z time="2021-08-24T17:39:26.175961622Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=VLo845EiMixZ req.method=POST req.path=/_matrix/client/r0/register
2021-08-24T17:40:09.2734553Z time="2021-08-24T17:39:26.176264420Z" level=info msg="Processing registration request" func="Register\n\t" file=" [register.go:523]" auth.type=m.login.dummy req.id=VLo845EiMixZ req.method=POST req.path=/_matrix/client/r0/register session_id="" username=bob
2021-08-24T17:40:09.2737063Z time="2021-08-24T17:39:26.181175495Z" level=info msg=PerformDeviceCreation func="PerformDeviceCreation\n\t" file=" [api.go:115]" device_id="<nil>" display_name="<nil>" localpart=bob req.id=VLo845EiMixZ req.method=POST req.path=/_matrix/client/r0/register
2021-08-24T17:40:09.2739128Z time="2021-08-24T17:39:26.187016666Z" level=info msg="Sending device list update message to []" func="onDeviceKeyMessage\n\t" file=" [keychange.go:145]"
2021-08-24T17:40:09.2740955Z time="2021-08-24T17:39:26.189896451Z" level=info msg="Produced to key change topic 'DendriteOutputKeyChangeEvent'" func="ProduceKeyChanges\n\t" file=" [keychange.go:73]" num_key_changes=1 user_id="@bob:hs1"
2021-08-24T17:40:09.2743440Z time="2021-08-24T17:39:26.190181450Z" level=trace msg="Responding (126 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=VLo845EiMixZ req.method=POST req.path=/_matrix/client/r0/register
2021-08-24T17:40:09.2745479Z time="2021-08-24T17:39:26.191575743Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=hNjpWcpST55b req.method=POST req.path=/_matrix/client/r0/register
2021-08-24T17:40:09.2747565Z time="2021-08-24T17:39:26.192033341Z" level=info msg="Processing registration request" func="Register\n\t" file=" [register.go:523]" auth.type=m.login.dummy req.id=hNjpWcpST55b req.method=POST req.path=/_matrix/client/r0/register session_id="" username=eve
2021-08-24T17:40:09.2749945Z time="2021-08-24T17:39:26.198132310Z" level=info msg=PerformDeviceCreation func="PerformDeviceCreation\n\t" file=" [api.go:115]" device_id="<nil>" display_name="<nil>" localpart=eve req.id=hNjpWcpST55b req.method=POST req.path=/_matrix/client/r0/register
2021-08-24T17:40:09.2752276Z time="2021-08-24T17:39:26.204476878Z" level=info msg="Sending device list update message to []" func="onDeviceKeyMessage\n\t" file=" [keychange.go:145]"
2021-08-24T17:40:09.2754289Z time="2021-08-24T17:39:26.208163659Z" level=info msg="Produced to key change topic 'DendriteOutputKeyChangeEvent'" func="ProduceKeyChanges\n\t" file=" [keychange.go:73]" num_key_changes=1 user_id="@eve:hs1"
2021-08-24T17:40:09.2757044Z time="2021-08-24T17:39:26.208466858Z" level=trace msg="Responding (126 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=hNjpWcpST55b req.method=POST req.path=/_matrix/client/r0/register
2021-08-24T17:40:09.2758852Z time="2021-08-24T17:39:26.210013750Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=3N9T6fvrpc9K req.method=POST req.path=/_matrix/client/r0/createRoom
2021-08-24T17:40:09.2761183Z time="2021-08-24T17:39:26.210999045Z" level=info msg="Creating new room" func="createRoom\n\t" file=" [createroom.go:201]" req.id=3N9T6fvrpc9K req.method=POST req.path=/_matrix/client/r0/createRoom roomID="!hPHHSpjk5TfalAKr:hs1" roomVersion=6 userID="@alice:hs1" user_id="@alice:hs1"
2021-08-24T17:40:09.2765399Z time="2021-08-24T17:39:26.216370718Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$y4h-jKf7dBkg_vSpExjhRazqNSlP-uc1YqweGh-1748" room="!hPHHSpjk5TfalAKr:hs1" sender="@alice:hs1" type=m.room.create
2021-08-24T17:40:09.2768958Z time="2021-08-24T17:39:26.227114364Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=1 event_id="$y4h-jKf7dBkg_vSpExjhRazqNSlP-uc1YqweGh-1748" event_type=m.room.create removes_state=0 room_id="!hPHHSpjk5TfalAKr:hs1" send_as_server="" sender="@alice:hs1" state_key="" type=new_room_event
2021-08-24T17:40:09.2772151Z time="2021-08-24T17:39:26.237676810Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$y4h-jKf7dBkg_vSpExjhRazqNSlP-uc1YqweGh-1748"
2021-08-24T17:40:09.2775171Z time="2021-08-24T17:39:26.247979658Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$6txq01kUa1VWnKHT15dIiH0JIxlS_ulf4BrfG3IAAck" room="!hPHHSpjk5TfalAKr:hs1" sender="@alice:hs1" type=m.room.member
2021-08-24T17:40:09.2778386Z time="2021-08-24T17:39:26.273930028Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=2 content_value=join event_id="$6txq01kUa1VWnKHT15dIiH0JIxlS_ulf4BrfG3IAAck" event_type=m.room.member removes_state=0 room_id="!hPHHSpjk5TfalAKr:hs1" send_as_server="" sender="@alice:hs1" state_key="@alice:hs1" type=new_room_event
2021-08-24T17:40:09.2781723Z time="2021-08-24T17:39:26.290281545Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$y4h-jKf7dBkg_vSpExjhRazqNSlP-uc1YqweGh-1748"
2021-08-24T17:40:09.2784147Z time="2021-08-24T17:39:26.291136241Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$6txq01kUa1VWnKHT15dIiH0JIxlS_ulf4BrfG3IAAck"
2021-08-24T17:40:09.2786983Z time="2021-08-24T17:39:26.296192515Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$PsNsNHtaaKm94THFijKoA48959VFR4GCFeG1kqifRv4" room="!hPHHSpjk5TfalAKr:hs1" sender="@alice:hs1" type=m.room.power_levels
2021-08-24T17:40:09.2790528Z time="2021-08-24T17:39:26.310132845Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=3 event_id="$PsNsNHtaaKm94THFijKoA48959VFR4GCFeG1kqifRv4" event_type=m.room.power_levels removes_state=0 room_id="!hPHHSpjk5TfalAKr:hs1" send_as_server="" sender="@alice:hs1" state_key="" type=new_room_event
2021-08-24T17:40:09.2793741Z time="2021-08-24T17:39:26.324645072Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$y4h-jKf7dBkg_vSpExjhRazqNSlP-uc1YqweGh-1748"
2021-08-24T17:40:09.2796080Z time="2021-08-24T17:39:26.325254569Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$6txq01kUa1VWnKHT15dIiH0JIxlS_ulf4BrfG3IAAck"
2021-08-24T17:40:09.2798539Z time="2021-08-24T17:39:26.325851666Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$PsNsNHtaaKm94THFijKoA48959VFR4GCFeG1kqifRv4"
2021-08-24T17:40:09.2801673Z time="2021-08-24T17:39:26.334449122Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$2_dt4YHa6lJ1sExicCuwf2SScZUovzzlBwKJt3_UZm0" room="!hPHHSpjk5TfalAKr:hs1" sender="@alice:hs1" type=m.room.join_rules
2021-08-24T17:40:09.2805337Z time="2021-08-24T17:39:26.350999239Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=4 content_value=invite event_id="$2_dt4YHa6lJ1sExicCuwf2SScZUovzzlBwKJt3_UZm0" event_type=m.room.join_rules removes_state=0 room_id="!hPHHSpjk5TfalAKr:hs1" send_as_server="" sender="@alice:hs1" state_key="" type=new_room_event
2021-08-24T17:40:09.2808379Z time="2021-08-24T17:39:26.365361667Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$y4h-jKf7dBkg_vSpExjhRazqNSlP-uc1YqweGh-1748"
2021-08-24T17:40:09.2810790Z time="2021-08-24T17:39:26.365942864Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$6txq01kUa1VWnKHT15dIiH0JIxlS_ulf4BrfG3IAAck"
2021-08-24T17:40:09.2813498Z time="2021-08-24T17:39:26.366620760Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$PsNsNHtaaKm94THFijKoA48959VFR4GCFeG1kqifRv4"
2021-08-24T17:40:09.2816269Z time="2021-08-24T17:39:26.367224557Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$2_dt4YHa6lJ1sExicCuwf2SScZUovzzlBwKJt3_UZm0"
2021-08-24T17:40:09.2818876Z time="2021-08-24T17:39:26.378482300Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$eljejY9WSf5PewFWxtNj4_jdHtaMUrkIkjO2AdBmhAo" room="!hPHHSpjk5TfalAKr:hs1" sender="@alice:hs1" type=m.room.history_visibility
2021-08-24T17:40:09.2822416Z time="2021-08-24T17:39:26.392661429Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=5 content_value=shared event_id="$eljejY9WSf5PewFWxtNj4_jdHtaMUrkIkjO2AdBmhAo" event_type=m.room.history_visibility removes_state=0 room_id="!hPHHSpjk5TfalAKr:hs1" send_as_server="" sender="@alice:hs1" state_key="" type=new_room_event
2021-08-24T17:40:09.2825468Z time="2021-08-24T17:39:26.405548064Z" level=trace msg="Responding (35 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=3N9T6fvrpc9K req.method=POST req.path=/_matrix/client/r0/createRoom
2021-08-24T17:40:09.2827279Z time="2021-08-24T17:39:26.406457059Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=mWFbN7nn6aTS req.method=POST req.path=/_matrix/client/r0/createRoom
2021-08-24T17:40:09.2829433Z time="2021-08-24T17:39:26.406591359Z" level=info msg="Creating new room" func="createRoom\n\t" file=" [createroom.go:201]" req.id=mWFbN7nn6aTS req.method=POST req.path=/_matrix/client/r0/createRoom roomID="!34PPQGpLUub2aLe2:hs1" roomVersion=6 userID="@bob:hs1" user_id="@bob:hs1"
2021-08-24T17:40:09.2832367Z time="2021-08-24T17:39:26.409750243Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$Me4UEzL6t3mJB-eA9b9F2ldUypE1S7TBAovJy8vw9Mo" room="!34PPQGpLUub2aLe2:hs1" sender="@bob:hs1" type=m.room.create
2021-08-24T17:40:09.2835940Z time="2021-08-24T17:39:26.420501388Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=1 event_id="$Me4UEzL6t3mJB-eA9b9F2ldUypE1S7TBAovJy8vw9Mo" event_type=m.room.create removes_state=0 room_id="!34PPQGpLUub2aLe2:hs1" send_as_server="" sender="@bob:hs1" state_key="" type=new_room_event
2021-08-24T17:40:09.2839239Z time="2021-08-24T17:39:26.430246039Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$Me4UEzL6t3mJB-eA9b9F2ldUypE1S7TBAovJy8vw9Mo"
2021-08-24T17:40:09.2842047Z time="2021-08-24T17:39:26.433831521Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$RB0SR9JopT3T3x7m3dPtMDP4meWVmNxed86pvJHWTZc" room="!34PPQGpLUub2aLe2:hs1" sender="@bob:hs1" type=m.room.member
2021-08-24T17:40:09.2845950Z time="2021-08-24T17:39:26.452351328Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=2 content_value=join event_id="$RB0SR9JopT3T3x7m3dPtMDP4meWVmNxed86pvJHWTZc" event_type=m.room.member removes_state=0 room_id="!34PPQGpLUub2aLe2:hs1" send_as_server="" sender="@bob:hs1" state_key="@bob:hs1" type=new_room_event
2021-08-24T17:40:09.2849236Z time="2021-08-24T17:39:26.460317188Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$Me4UEzL6t3mJB-eA9b9F2ldUypE1S7TBAovJy8vw9Mo"
2021-08-24T17:40:09.2851844Z time="2021-08-24T17:39:26.460941285Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$RB0SR9JopT3T3x7m3dPtMDP4meWVmNxed86pvJHWTZc"
2021-08-24T17:40:09.2854523Z time="2021-08-24T17:39:26.470070038Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$-GWF4m3ZYpnw8U2d_WU27E4D6ZxZ0wE2D2ukZIliJQg" room="!34PPQGpLUub2aLe2:hs1" sender="@bob:hs1" type=m.room.power_levels
2021-08-24T17:40:09.2857589Z time="2021-08-24T17:39:26.483668670Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=3 event_id="$-GWF4m3ZYpnw8U2d_WU27E4D6ZxZ0wE2D2ukZIliJQg" event_type=m.room.power_levels removes_state=0 room_id="!34PPQGpLUub2aLe2:hs1" send_as_server="" sender="@bob:hs1" state_key="" type=new_room_event
2021-08-24T17:40:09.2860573Z time="2021-08-24T17:39:26.500658384Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$Me4UEzL6t3mJB-eA9b9F2ldUypE1S7TBAovJy8vw9Mo"
2021-08-24T17:40:09.2864475Z time="2021-08-24T17:39:26.501169482Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$RB0SR9JopT3T3x7m3dPtMDP4meWVmNxed86pvJHWTZc"
2021-08-24T17:40:09.2867330Z time="2021-08-24T17:39:26.502140077Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$-GWF4m3ZYpnw8U2d_WU27E4D6ZxZ0wE2D2ukZIliJQg"
2021-08-24T17:40:09.2869676Z time="2021-08-24T17:39:26.507218051Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$3xvBhfz2iLBN-t1CXd3pwlRW8-DI_rlBjZXLoVxadRI" room="!34PPQGpLUub2aLe2:hs1" sender="@bob:hs1" type=m.room.join_rules
2021-08-24T17:40:09.2873001Z time="2021-08-24T17:39:26.519280790Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=4 content_value=invite event_id="$3xvBhfz2iLBN-t1CXd3pwlRW8-DI_rlBjZXLoVxadRI" event_type=m.room.join_rules removes_state=0 room_id="!34PPQGpLUub2aLe2:hs1" send_as_server="" sender="@bob:hs1" state_key="" type=new_room_event
2021-08-24T17:40:09.2876248Z time="2021-08-24T17:39:26.532608123Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$Me4UEzL6t3mJB-eA9b9F2ldUypE1S7TBAovJy8vw9Mo"
2021-08-24T17:40:09.2878904Z time="2021-08-24T17:39:26.533494619Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$RB0SR9JopT3T3x7m3dPtMDP4meWVmNxed86pvJHWTZc"
2021-08-24T17:40:09.2881516Z time="2021-08-24T17:39:26.534112515Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$-GWF4m3ZYpnw8U2d_WU27E4D6ZxZ0wE2D2ukZIliJQg"
2021-08-24T17:40:09.2883806Z time="2021-08-24T17:39:26.534814812Z" level=info msg="Already processed event; ignoring" func="processRoomEvent\n\t" file=" [input_events.go:94]" context=missing event_id="$3xvBhfz2iLBN-t1CXd3pwlRW8-DI_rlBjZXLoVxadRI"
2021-08-24T17:40:09.2886626Z time="2021-08-24T17:39:26.539071390Z" level=debug msg="Stored outlier" func="processRoomEvent\n\t" file=" [input_events.go:160]" event_id="$iYa4AjOH6TTmy0z5rTJqHkzr1xww91TOKaSACxxSZEo" room="!34PPQGpLUub2aLe2:hs1" sender="@bob:hs1" type=m.room.history_visibility
2021-08-24T17:40:09.2890165Z time="2021-08-24T17:39:26.550710332Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=5 content_value=shared event_id="$iYa4AjOH6TTmy0z5rTJqHkzr1xww91TOKaSACxxSZEo" event_type=m.room.history_visibility removes_state=0 room_id="!34PPQGpLUub2aLe2:hs1" send_as_server="" sender="@bob:hs1" state_key="" type=new_room_event
2021-08-24T17:40:09.2893676Z time="2021-08-24T17:39:26.562265174Z" level=info msg="processing invite event" func="PerformInvite\n\t" file=" [perform_invite.go:63]" event_id="$_EOMeFCKkzexxP5jHnxp1NggaWHSLzuvh6lIBs93vNo" room_id="!34PPQGpLUub2aLe2:hs1" room_info_exists=true room_version=6 target_user_id="@alice:hs1"
2021-08-24T17:40:09.2896204Z time="2021-08-24T17:39:26.583882964Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" room_id="!34PPQGpLUub2aLe2:hs1" type=new_invite_event
2021-08-24T17:40:09.2899353Z time="2021-08-24T17:39:26.584093663Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=1 content_value=invite event_id="$_EOMeFCKkzexxP5jHnxp1NggaWHSLzuvh6lIBs93vNo" event_type=m.room.member removes_state=0 room_id="!34PPQGpLUub2aLe2:hs1" send_as_server=hs1 sender="@bob:hs1" state_key="@alice:hs1" type=new_room_event
2021-08-24T17:40:09.2902101Z time="2021-08-24T17:39:26.586075853Z" level=debug msg="roomserver output log: ignoring unknown output type" func="onMessage\n\t" file=" [roomserver.go:126]" type=new_invite_event
2021-08-24T17:40:09.2903945Z time="2021-08-24T17:39:26.592304822Z" level=trace msg="Responding (35 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=mWFbN7nn6aTS req.method=POST req.path=/_matrix/client/r0/createRoom
2021-08-24T17:40:09.2905882Z time="2021-08-24T17:39:26.593546816Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=GS4cUa5dIcR0 req.method=GET req.path=/_matrix/client/r0/sync
2021-08-24T17:40:09.2908035Z time="2021-08-24T17:39:26.593728315Z" level=debug msg="Responding to sync immediately" func="OnIncomingSyncRequest\n\t" file=" [requestpool.go:186]" device_id=ofyo-HnV limit=20 req.id=GS4cUa5dIcR0 req.method=GET req.path=/_matrix/client/r0/sync since=s0_0_0_0_0_0 timeout=1s user_id="@alice:hs1"
2021-08-24T17:40:09.2910030Z time="2021-08-24T17:39:26.604239762Z" level=trace msg="Responding (2374 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=GS4cUa5dIcR0 req.method=GET req.path=/_matrix/client/r0/sync
2021-08-24T17:40:09.2912029Z time="2021-08-24T17:39:26.605098557Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=DTO1B4hGED35 req.method=POST req.path="/_matrix/client/r0/join/!34PPQGpLUub2aLe2:hs1"
2021-08-24T17:40:09.2914398Z time="2021-08-24T17:39:26.634761508Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" room_id="!34PPQGpLUub2aLe2:hs1" type=retire_invite_event
2021-08-24T17:40:09.2917514Z time="2021-08-24T17:39:26.634877907Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=1 content_value=join event_id="$9k6LBK87PCj6avCWYk0EUKn0Exu8p0hgZIyV8FLSWaQ" event_type=m.room.member removes_state=1 room_id="!34PPQGpLUub2aLe2:hs1" send_as_server=hs1 sender="@alice:hs1" state_key="@alice:hs1" type=new_room_event
2021-08-24T17:40:09.2920357Z time="2021-08-24T17:39:26.636866097Z" level=debug msg="roomserver output log: ignoring unknown output type" func="onMessage\n\t" file=" [roomserver.go:126]" type=retire_invite_event
2021-08-24T17:40:09.2922143Z time="2021-08-24T17:39:26.644290160Z" level=trace msg="Responding (35 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=DTO1B4hGED35 req.method=POST req.path="/_matrix/client/r0/join/!34PPQGpLUub2aLe2:hs1"
2021-08-24T17:40:09.2924230Z time="2021-08-24T17:39:26.672889416Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=KZBfNlw3tkcu req.method=PUT req.path="/_matrix/client/r0/rooms/!34PPQGpLUub2aLe2:hs1/state/m.room.member/@alice:hs1"
2021-08-24T17:40:09.2927399Z time="2021-08-24T17:39:26.695669601Z" level=info msg="Producing to topic 'DendriteOutputRoomEvent'" func="WriteOutputEvents\n\t" file=" [input.go:130]" adds_state=1 content_value=join event_id="$LEFK_zVlFTy086OgOIAKI60U3qICuyNqEn9Ir-RohWQ" event_type=m.room.member removes_state=1 room_id="!34PPQGpLUub2aLe2:hs1" send_as_server=hs1 sender="@alice:hs1" state_key="@alice:hs1" type=new_room_event
2021-08-24T17:40:09.2930955Z time="2021-08-24T17:39:26.700070179Z" level=info msg="Sent event to roomserver" func="SendEvent\n\t" file=" [sendevent.go:134]" event_id="$LEFK_zVlFTy086OgOIAKI60U3qICuyNqEn9Ir-RohWQ" req.id=KZBfNlw3tkcu req.method=PUT req.path="/_matrix/client/r0/rooms/!34PPQGpLUub2aLe2:hs1/state/m.room.member/@alice:hs1" room_id="!34PPQGpLUub2aLe2:hs1" room_version=6 user_id="@alice:hs1"
2021-08-24T17:40:09.2934182Z time="2021-08-24T17:39:26.700197278Z" level=trace msg="Responding (59 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=KZBfNlw3tkcu req.method=PUT req.path="/_matrix/client/r0/rooms/!34PPQGpLUub2aLe2:hs1/state/m.room.member/@alice:hs1"
2021-08-24T17:40:09.2936400Z time="2021-08-24T17:39:26.701597871Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=9QVsrRdtNlus req.method=POST req.path=/_matrix/client/r0/user_directory/search
2021-08-24T17:40:09.2938420Z time="2021-08-24T17:39:26.703720260Z" level=trace msg="Responding (63 bytes)" func="respond\n\t" file=" [json.go:173]" code=500 req.id=9QVsrRdtNlus req.method=POST req.path=/_matrix/client/r0/user_directory/search
2021-08-24T17:40:09.2939940Z 2021/08/24 17:39:26 ============== 013673f35bbc9ea8fb2dd61dfc3fc903e36857b69b623d7a66e8f206ca02eecb : END LOGS ==============
Which sounds like two dendrite bugs/unimplemented bits to me:
  1. I think this search should return exactly Alice. Assuming my test setup is correct, She's the only one in a public room, and Eve's not in any rooms. (spec)
  2. If a search yields no users, return 200 with an empty results list rather than 500 internal sadness

It's not required that you can search for people by per-room names (and
per-room names are kind of an accident anyway right now)
Copy link
Member

@richvdh richvdh left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm from the PoV of the tests. I'd have to defer to @kegsay on whether excluding SA1019 is the right way to go.

tests/csapi/user_directory_display_names_test.go Outdated Show resolved Hide resolved
tests/csapi/user_directory_display_names_test.go Outdated Show resolved Hide resolved
Copy link
Member

@richvdh richvdh left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm!

internal/instruction/runner.go Show resolved Hide resolved
@richvdh
Copy link
Member

richvdh commented Sep 6, 2021

CI seems to be failing for both Synapse and Dendrite for an unrelated test. Any idea what's going on there? (Old branch? or have you accidentally broken something?)

@DMRobertson
Copy link
Contributor Author

CI seems to be failing for both Synapse and Dendrite for an unrelated test. Any idea what's going on there? (Old branch? or have you accidentally broken something?)

In both runs I see two failures, both in the newly written tests: TestRoomSpecificUsernameHandling and TestRoomSpecificUsernameHandlingOverFederation. Which ones are you seeing fail, and where?

@richvdh
Copy link
Member

richvdh commented Sep 6, 2021

In both runs I see two failures, both in the newly written tests: TestRoomSpecificUsernameHandling and TestRoomSpecificUsernameHandlingOverFederation. Which ones are you seeing fail, and where?

oh, sorry. The output is confusing. I saw this at the end of the report:

=== RUN   TestKeysQueryWithDeviceIDAsObjectFails
    user_query_keys_test.go:18: Deploy times: 7.538142ms blueprints, 2.037674431s containers
    client.go:407: POST hs1/_matrix/client/r0/keys/query => 400 Bad Request (3.897721ms)
--- PASS: TestKeysQueryWithDeviceIDAsObjectFails (2.29s)
FAIL
FAIL	github.com/matrix-org/complement/tests/csapi	59.689s
FAIL

But that doesn't mean what I thought it means.

internal/client/client.go Outdated Show resolved Hide resolved
Copy link
Member

@kegsay kegsay left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks great overall, thank you!

@kegsay
Copy link
Member

kegsay commented Sep 6, 2021

Tests are failing however:

=== RUN   TestRoomSpecificUsernameHandlingOverFederation
    user_directory_federated_display_names_test.go:22: Deploy times: 7.681441ms blueprints, 3.556640339s containers
    client.go:407: POST hs1/_matrix/client/r0/register => 200 OK (40.50622ms)
    client.go:407: PUT hs2/profile/@charlie:hs2/displayname => 404 Not Found (2.345413ms)
    user_directory_federated_display_names_test.go:33: CSAPI.MustDoFunc response return non-2xx code: 404 Not Found - body: 
        <html>
          <head><title>404 - No Such Resource</title></head>
          <body>
            <h1>No Such Resource</h1>
            <p>No such child resource.</p>
          </body>
        </html>

@DMRobertson
Copy link
Contributor Author

DMRobertson commented Sep 6, 2021

Running this against my changes in matrix-org/synapse#10695 yields

dmr on titan in complement on  dmr/per-room-nick-leakage via 🐹 v1.16.6 via 🐍 v3.9.6 (env) took 24s 
2021-09-06 18:10:20 ✗ 1 ERROR  $ COMPLEMENT_BASE_IMAGE=complement-synapse go test ./... -run TestRoomSpecificUsername | grep FAIL
318:--- FAIL: TestRoomSpecificUsernameHandlingOverFederation (19.90s)
332:    --- FAIL: TestRoomSpecificUsernameHandlingOverFederation/Eve_can_find_Charlie_by_profile_display_name (0.03s)
335:    --- FAIL: TestRoomSpecificUsernameHandlingOverFederation/Eve_can_find_Charlie_by_mxid (0.00s)
336:        user_directory_federated_display_names_test.go:112: MatchResponse all checks failed:
340:    --- FAIL: TestRoomSpecificUsernameHandlingOverFederation/Eve_cannot_find_Charlie_by_room-specific_name_that_Eve_is_not_privy_to (0.00s)
343:    --- FAIL: TestRoomSpecificUsernameHandlingOverFederation/Bob_can_find_Charlie_by_profile_display_name (0.00s)
346:    --- FAIL: TestRoomSpecificUsernameHandlingOverFederation/Bob_can_find_Charlie_by_mxid (0.00s)
347:        user_directory_federated_display_names_test.go:155: MatchResponse all checks failed:
350:FAIL
351:FAIL	github.com/matrix-org/complement/tests	21.022s
353:FAIL

Edit: and this is good, because it's only the federated tests failing; the other ones pass.

@DMRobertson
Copy link
Contributor Author

oh, sorry. The output is confusing. I saw this at the end of the report:
[...]
But that doesn't mean what I thought it means.

We could maybe try not passing -v to go test?

-v
Verbose output: log all tests as they are run. Also print all
text from Log and Logf calls even if the test succeeds.

@DMRobertson DMRobertson requested a review from kegsay September 6, 2021 17:25
I think "alice" rather than "@alice:example.com" is nicer to display in
the UI until we've confirmed their public profile.
@kegsay
Copy link
Member

kegsay commented Sep 7, 2021

Please add these tests to dendrite's blacklist, then fix the synapse issue then I'm happy to merge this.

@DMRobertson
Copy link
Contributor Author

Thanks @kegsay, will do. Working on this in synapse now.

@DMRobertson
Copy link
Contributor Author

Please add these tests to dendrite's blacklist, then fix the synapse issue then I'm happy to merge this.

The issue is fixed for Synapse for local users now. The other tests over federation (tests/user_directory_federated_display_names_test.go) aren't, and it's going to take more thought to address those. I propose commiting that file as is, but adding it to both Synapse and Dendrite's blacklist.

How does that sound to everyone?

@kegsay
Copy link
Member

kegsay commented Oct 21, 2021

I don't like the idea of merging tests which fail on all HS implementations. I don't like it because:

  • the risk of test bitrot where these tests can break and we have nothing exercising the test.
  • it's unclear that said tests are expected to fail everywhere. Could be helped with t.Skipf.
  • it needlessly adds code to this repository.

Remove the failing tests and add them when the underlying issues are resolved.

@kegsay
Copy link
Member

kegsay commented Nov 10, 2021

@DMRobertson what's the status of this PR? Can we merge the bits that work and back out the things which don't?

@DMRobertson
Copy link
Contributor Author

Remove the failing tests and add them when the underlying issues are resolved.

Ahh sorry, I missed this.

@DMRobertson what's the status of this PR? Can we merge the bits that work and back out the things which don't?

The tests in /csapi should all pass against Synapse now. I'll get that done now.

@DMRobertson
Copy link
Contributor Author

The failed dendrite tests don't look related to this one:

$ grep < /tmp/log -- "--- FAIL"
1090:2021-11-10T12:00:54.6836096Z --- FAIL: TestRestrictedRoomsLocalJoin (5.72s)
1226:2021-11-10T12:00:54.7314982Z --- FAIL: TestRestrictedRoomsRemoteJoin (2.53s)
1390:2021-11-10T12:00:54.7828077Z --- FAIL: TestRestrictedRoomsRemoteJoinLocalUser (2.80s)
1555:2021-11-10T12:00:54.8332109Z --- FAIL: TestRestrictedRoomsRemoteJoinFailOver (14.60s)

AFAICS these are failing on master too.

@DMRobertson DMRobertson requested a review from kegsay November 10, 2021 13:54
@DMRobertson DMRobertson changed the title Add test case reproducing matrix-org/synapse#5677 Add test case reproducing matrix-org/synapse#5677 for local users Nov 10, 2021
@kegsay
Copy link
Member

kegsay commented Nov 15, 2021

Yep that's fine, @neilalexander is working on that now.

@kegsay
Copy link
Member

kegsay commented Nov 15, 2021

Happy for me to merge this @DMRobertson ?

@DMRobertson
Copy link
Contributor Author

Happy for me to merge this @DMRobertson ?

@kegsay Let's do it.

@DMRobertson DMRobertson merged commit 83b4571 into master Nov 15, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants