regression: Policy server signatures are applied too aggressively #1815

New issue

Closed

opened 2026-05-26 09:11:15 +00:00 by nex · 1 comment

nex commented

2026-05-26 09:11:15 +00:00

Owner

As of #1487, policy server checks are applied too aggressively. In #offtopic, my server has resolved the current policy server state event to the one pointing at asgard.chat, not correctly continuwuity.org. ellis.link is getting signatures from continuwuity.org, but my server doesn't care, since as far as it is concerned, .org isn't the policy server. It is then asking asgard.chat for a signature on the fly, which is correct behaviour, and doesn't get one back as the room is not protected by that server anymore. However, the unexpected behaviour is that this then fails a signature check, which is weird, because there isn't a signature to check? This then results in the event being soft-failed and/or not upgraded from an outlier to timeline event.

2026-05-26T09:01:45.176921Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}: conduwuit_api::server::send: Processing transaction pdus=1 edus=0
2026-05-26T09:01:45.181945Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}: conduwuit_service::rooms::event_handler::handle_outlier_pdu: Fetching 2 missing auth events for outlier event $OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34
2026-05-26T09:01:45.182026Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}: conduwuit_service::rooms::event_handler::handle_outlier_pdu: Checking based on auth events
2026-05-26T09:01:45.182864Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}: conduwuit_service::rooms::event_handler::handle_incoming_pdu: Handling previous events events=["$3w28C6ZNJ9S206zmkOIC78RUhqNKLuj8hMPcLD0Ji6k", "$eRz86zXxS9sGorB-x_aTXz3crfka9yrdQ8mmZunrXy4", "$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q", "$I6HOAFM1WWkZ85lMuqrEo7UYh7uESHPRTSlusAfOCmE", "$9uscgr0ri5qdcd8fuwxS2KFWmV3Rw_03vET8i0ZZeMg"]
2026-05-26T09:01:45.184115Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Upgrading PDU from outlier to timeline event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q
2026-05-26T09:01:45.184135Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Resolving state at event event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q
2026-05-26T09:01:45.515072Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Performing auth check to upgrade event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q
2026-05-26T09:01:45.515110Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Running initial auth check event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q
2026-05-26T09:01:45.516786Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Gathering auth events event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q
2026-05-26T09:01:45.516823Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::state: Auth types for event auth_types=[("m.room.power_levels", ""), ("m.room.member", "@jade:ellis.link")]
2026-05-26T09:01:45.517004Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::state: Auth events to fetch sauthevents={17994135: ("m.room.member", "@jade:ellis.link"), 17: ("m.room.power_levels", "")}
2026-05-26T09:01:45.517070Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::state: Auth events found in state state_keys=[("m.room.power_levels", ""), ("m.room.member", "@jade:ellis.link")] event_ids=[195625637, 219223386]
2026-05-26T09:01:45.517318Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Running auth check with claimed state auth event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q
2026-05-26T09:01:45.517382Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Performing soft-fail check event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q
2026-05-26T09:01:45.540422Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Checking policy server for event event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q
2026-05-26T09:01:45.541818Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}: conduwuit_service::rooms::event_handler::policy_server: No (valid) policy server signature present on event
2026-05-26T09:01:45.541837Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}: conduwuit_service::rooms::event_handler::policy_server: Event is incoming but does not have a valid policy server signature; asking policy server to sign it now via=asgard.chat
2026-05-26T09:01:45.541935Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}: conduwuit_service::rooms::event_handler::policy_server: Asking policy server to sign event ps.via=asgard.chat
2026-05-26T09:01:45.541956Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}: conduwuit_service::rooms::event_handler::policy_server: Requesting policy server signature
2026-05-26T09:01:45.542727Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}:request:fed{dest="asgard.chat"}: conduwuit_service::federation::execute: Sending request method=POST url=https://matrix.asgard.chat/_matrix/policy/v1/sign
2026-05-26T09:01:45.669977Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}:request:fed{dest="asgard.chat"}: conduwuit_service::federation::execute: Got 404 for POST https://matrix.asgard.chat/_matrix/policy/v1/sign
2026-05-26T09:01:45.670022Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}: conduwuit_service::rooms::event_handler::policy_server: Error from policy server: Answer from asgard.chat: [404 / M_NOT_FOUND] Policy server error: room is not protected
2026-05-26T09:01:45.670030Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}: conduwuit_service::rooms::event_handler::policy_server: Policy server is not actually a policy server or is not protecting this room: Answer from asgard.chat: [404 / M_NOT_FOUND] Policy server error: room is not protected via=asgard.chat event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk
2026-05-26T09:01:45.670055Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}: conduwuit_service::rooms::event_handler::policy_server: No (valid) policy server signature present on event
2026-05-26T09:01:45.670106Z  WARN process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}: conduwuit_service::rooms::event_handler::handle_incoming_pdu: Prev $u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q failed: Unknown: Policy server signature was made with a different key to the one advertised

potential problem area: handle_policy_server_error returns a fail-open Ok(()), indicating that the request was "allowed" by the policy server:

 		| StatusCode::NOT_FOUND => {
 			debug_info!(
 				via = %via,
 				event_id = %pdu.event_id(),
 				%room_id,
 				"Policy server is not actually a policy server or is not protecting this room: {}",
 				error.message()
 			);
 			Ok(())

However, policy_server_allows_event expects an error to be returned if there was no signature. This would cause the event to be soft-failed as it was "rejected" as "spam", however when it does not receive an error, it assumes the event was signed, and always calls verify_policy_signature with the expected policy server data (which we have established isn't correct in this scenario):

 	self.fetch_policy_server_signature(pdu, pdu_json, &ps.via, outgoing, room_id, ps_key, 0)
 		.await?;
 	// Verify that the policy server signature was made with the same public key as
 	// is in the state event, not just that it was signed.
 	if verify_policy_signature(&ps.via, ps_key, pdu_json, &room_version_rules.redaction) {
 		Ok(())
 	} else {
 		Err(Error::Request(
 			ErrorKind::Unknown,
 			"Policy server signature was made with a different key to the one advertised".into(),
 			StatusCode::BAD_GATEWAY,
 		))
 	}

As of #1487, policy server checks are applied too aggressively. In #offtopic, my server has resolved the current policy server state event to the one pointing at `asgard.chat`, not correctly `continuwuity.org`. ellis.link is getting signatures from continuwuity.org, but my server doesn't care, since as far as it is concerned, .org isn't the policy server. It is then asking asgard.chat for a signature on the fly, which is correct behaviour, and doesn't get one back as the room is not protected by that server anymore. However, the unexpected behaviour is that this then fails a *signature check*, which is weird, because there isn't a signature to check? This then results in the event being soft-failed and/or not upgraded from an outlier to timeline event. ``` 2026-05-26T09:01:45.176921Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}: conduwuit_api::server::send: Processing transaction pdus=1 edus=0 2026-05-26T09:01:45.181945Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}: conduwuit_service::rooms::event_handler::handle_outlier_pdu: Fetching 2 missing auth events for outlier event $OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34 2026-05-26T09:01:45.182026Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}: conduwuit_service::rooms::event_handler::handle_outlier_pdu: Checking based on auth events 2026-05-26T09:01:45.182864Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}: conduwuit_service::rooms::event_handler::handle_incoming_pdu: Handling previous events events=["$3w28C6ZNJ9S206zmkOIC78RUhqNKLuj8hMPcLD0Ji6k", "$eRz86zXxS9sGorB-x_aTXz3crfka9yrdQ8mmZunrXy4", "$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q", "$I6HOAFM1WWkZ85lMuqrEo7UYh7uESHPRTSlusAfOCmE", "$9uscgr0ri5qdcd8fuwxS2KFWmV3Rw_03vET8i0ZZeMg"] 2026-05-26T09:01:45.184115Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Upgrading PDU from outlier to timeline event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q 2026-05-26T09:01:45.184135Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Resolving state at event event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q 2026-05-26T09:01:45.515072Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Performing auth check to upgrade event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q 2026-05-26T09:01:45.515110Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Running initial auth check event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q 2026-05-26T09:01:45.516786Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Gathering auth events event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q 2026-05-26T09:01:45.516823Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::state: Auth types for event auth_types=[("m.room.power_levels", ""), ("m.room.member", "@jade:ellis.link")] 2026-05-26T09:01:45.517004Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::state: Auth events to fetch sauthevents={17994135: ("m.room.member", "@jade:ellis.link"), 17: ("m.room.power_levels", "")} 2026-05-26T09:01:45.517070Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::state: Auth events found in state state_keys=[("m.room.power_levels", ""), ("m.room.member", "@jade:ellis.link")] event_ids=[195625637, 219223386] 2026-05-26T09:01:45.517318Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Running auth check with claimed state auth event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q 2026-05-26T09:01:45.517382Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Performing soft-fail check event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q 2026-05-26T09:01:45.540422Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}: conduwuit_service::rooms::event_handler::upgrade_outlier_pdu: Checking policy server for event event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q 2026-05-26T09:01:45.541818Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}: conduwuit_service::rooms::event_handler::policy_server: No (valid) policy server signature present on event 2026-05-26T09:01:45.541837Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}: conduwuit_service::rooms::event_handler::policy_server: Event is incoming but does not have a valid policy server signature; asking policy server to sign it now via=asgard.chat 2026-05-26T09:01:45.541935Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}: conduwuit_service::rooms::event_handler::policy_server: Asking policy server to sign event ps.via=asgard.chat 2026-05-26T09:01:45.541956Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}: conduwuit_service::rooms::event_handler::policy_server: Requesting policy server signature 2026-05-26T09:01:45.542727Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}:request:fed{dest="asgard.chat"}: conduwuit_service::federation::execute: Sending request method=POST url=https://matrix.asgard.chat/_matrix/policy/v1/sign 2026-05-26T09:01:45.669977Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}:request:fed{dest="asgard.chat"}: conduwuit_service::federation::execute: Got 404 for POST https://matrix.asgard.chat/_matrix/policy/v1/sign 2026-05-26T09:01:45.670022Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}: conduwuit_service::rooms::event_handler::policy_server: Error from policy server: Answer from asgard.chat: [404 / M_NOT_FOUND] Policy server error: room is not protected 2026-05-26T09:01:45.670030Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}:fetch_policy_server_signature{event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q via=asgard.chat}: conduwuit_service::rooms::event_handler::policy_server: Policy server is not actually a policy server or is not protecting this room: Answer from asgard.chat: [404 / M_NOT_FOUND] Policy server error: room is not protected via=asgard.chat event_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk 2026-05-26T09:01:45.670055Z DEBUG process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}:prev{prev_id=$u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q}:policy_server_allows_event{room_id="!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk" incoming=true}: conduwuit_service::rooms::event_handler::policy_server: No (valid) policy server signature present on event 2026-05-26T09:01:45.670106Z WARN process_inbound_transaction{id="q4GV23zJpNoS6i8i6I5HgPWgP-Ro6kiIEXKpZWkFoDE" origin="ellis.link"}:pdu{room_id=!c10y-fNiMx5ijtgGFibzPUfNs9hpQvnJYPTV-fD2KPk event_id=$OmA9hkUECYORczpvkqbZgyhBaJuQgFI34N6U89ERZ34}: conduwuit_service::rooms::event_handler::handle_incoming_pdu: Prev $u8LyF1CFTVGyYyc81o_xA-fI4CWwzoF7A87eZnrCU2Q failed: Unknown: Policy server signature was made with a different key to the one advertised ``` --- potential problem area: `handle_policy_server_error` returns a fail-open `Ok(())`, indicating that the request was "allowed" by the policy server: https://forgejo.ellis.link/continuwuation/continuwuity/src/commit/5f9594363dce1df851773e8bca9753d656c2abd2/src/service/rooms/event_handler/policy_server.rs#L267-L275 However, `policy_server_allows_event` expects an error to be returned if there was no signature. This would cause the event to be soft-failed as it was "rejected" as "spam", however when it does not receive an error, it assumes the event was signed, and always calls `verify_policy_signature` with the *expected* policy server data (which we have established isn't correct in this scenario): https://forgejo.ellis.link/continuwuation/continuwuity/src/commit/5f9594363dce1df851773e8bca9753d656c2abd2/src/service/rooms/event_handler/policy_server.rs#L207-L220

nex added the

labels

2026-05-26 09:11:15 +00:00

nex self-assigned this

2026-05-26 09:11:15 +00:00

nex commented

2026-05-26 09:27:27 +00:00

Author

Owner

to further note: policy_server_allows_event probably shouldn't return that differing-key error when checking incoming events, it should return forbidden instead, so that the event gets soft failed instead of left as an outlier, per server-server § 27.2 Validating Policy Server signatures. The "key differs" M_UNKNOWN is meant to prevent us creating events that fail that check, not persisting incoming ones.

to further note: `policy_server_allows_event` probably shouldn't return that differing-key error when checking incoming events, it should return forbidden instead, so that the event gets soft failed instead of left as an outlier, per [server-server § 27.2 Validating Policy Server signatures](https://spec.matrix.org/v1.18/server-server-api/#validating-policy-server-signatures:~:text=if%20the%20Policy%20Server%20rotates%20its%20key%20without%20the%20room%20also%20updating%20the%20state%20event%2C%20events%20will%20be%20flagged%20as%20not%20recommended%20for%20inclusion.%20This%20is%20expected%20behaviour.). The "key differs" M_UNKNOWN is meant to prevent us *creating* events that fail that check, not persisting incoming ones.

nex referenced this issue from a pull request that will close it,

2026-05-26 15:17:29 +00:00

fix: Don't be so aggressive when validating policy server signatures #1816

nex closed this issue

2026-05-26 18:01:09 +00:00