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

Error attempting to resolve state at missing prev_events: 403: Forbidden #15204

Open
Cyberes opened this issue Mar 4, 2023 · 4 comments
Open

Error attempting to resolve state at missing prev_events: 403: Forbidden #15204

Cyberes opened this issue Mar 4, 2023 · 4 comments
Labels
A-Admin-API A-Federated-Join joins over federation generally suck A-Moderation Tools for moderating HSes: event redaction, media removal, purge admin API, reports from users, ... O-Occasional Affects or can be seen by some users regularly or most users rarely S-Minor Blocks non-critical functionality, workarounds exist. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.
Milestone
Remaining faster ...

Comments

@Cyberes
Copy link
Contributor

Cyberes commented Mar 4, 2023 •
edited
Loading

Description

I use a script to test federation between matrix.org and my homeserver. It uses two bots. The test goes like this:

Bot 1 is on my HS. Bot 2 is on matrix.org.

  1. Bot 1 creates a room
  2. Bot 1 invites bot 2
  3. Bot 2 joins the room.
  4. Bot 1 sends a message to the room
  5. Using data from both bots the time it took to receive the message is calculated
  6. Both bots leave the room and forget it

This process is then repeated for bot 2.

I logged into the bots today to grab new access tokens and saw that there were a bunch of rooms that they had not left so I manually removed them. I was able to leave all the rooms of the matrix.org bot but was not able to do so for the bot on my HS. I tried nuking the rooms using /_synapse/admin/v2/rooms/ ( with force + purge) but that gave me this error:

2023-03-03 16:56:33,209 - synapse.storage.util.partial_state_events_tracker - 82 - INFO - shutdown_and_purge_room-0 - Awaiting un-partial-stating of events ['$goL0dWWdYWwvAeMR2yIepZPXCxlF9eGkF2Lx6P04UXk']
Stack (most recent call last):
  File "/usr/lib/python3.10/runpy.py", line 196, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/lib/python3.10/runpy.py", line 86, in _run_code
    exec(code, run_globals)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/app/homeserver.py", line 389, in <module>
    main()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/app/homeserver.py", line 385, in main
    run(hs)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/app/homeserver.py", line 364, in run
    _base.start_reactor(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/app/_base.py", line 191, in start_reactor
    run()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/app/_base.py", line 173, in run
    run_command()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/app/_base.py", line 148, in <lambda>
    run_command: Callable[[], None] = lambda: reactor.run(),
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/base.py", line 1318, in run
    self.mainLoop()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/base.py", line 1328, in mainLoop
    reactorBaseSelf.runUntilCurrent()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/base.py", line 967, in runUntilCurrent
    f(*a, **kw)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 696, in callback
    self._startRunCallbacks(result)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 798, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 892, in _runCallbacks
    current.result = callback(  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 1792, in gotResult
    _inlineCallbacks(r, gen, status, context)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 1782, in _inlineCallbacks
    status.deferred.callback(callbackValue)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 696, in callback
    self._startRunCallbacks(result)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 798, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 892, in _runCallbacks
    current.result = callback(  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 696, in callback
    self._startRunCallbacks(result)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 798, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 892, in _runCallbacks
    current.result = callback(  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 1792, in gotResult
    _inlineCallbacks(r, gen, status, context)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 1782, in _inlineCallbacks
    status.deferred.callback(callbackValue)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 696, in callback
    self._startRunCallbacks(result)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 798, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 892, in _runCallbacks
    current.result = callback(  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 1371, in _cbDeferred
    self.callback(cast(_DeferredListResultListT, self.resultList))
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 696, in callback
    self._startRunCallbacks(result)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 798, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 892, in _runCallbacks
    current.result = callback(  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 696, in callback
    self._startRunCallbacks(result)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 798, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 892, in _runCallbacks
    current.result = callback(  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 1792, in gotResult
    _inlineCallbacks(r, gen, status, context)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/twisted/internet/defer.py", line 1697, in _inlineCallbacks
    result = context.run(gen.send, result)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/metrics/background_process_metrics.py", line 242, in run
    return await func(*args, **kwargs)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/handlers/pagination.py", line 659, in _shutdown_and_purge_room
    ].shutdown_room = await self._room_shutdown_handler.shutdown_room(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/handlers/room.py", line 1869, in shutdown_room
    _, stream_id = await self.room_member_handler.update_membership(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/handlers/room_member.py", line 597, in update_membership
    result = await self.update_membership_locked(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/handlers/room_member.py", line 826, in update_membership_locked
    state_before_join = await self.state_handler.compute_state_after_events(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/state/__init__.py", line 219, in compute_state_after_events
    ret = await self.resolve_state_groups_for_events(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/util/metrics.py", line 113, in measured_func
    r = await func(self, *args, **kwargs)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/state/__init__.py", line 520, in resolve_state_groups_for_events
    state_groups = await self._state_storage_controller.get_state_group_for_events(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/logging/opentracing.py", line 901, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/logging/opentracing.py", line 901, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/storage/controllers/state.py", line 374, in get_state_group_for_events
    await self._partial_state_events_tracker.await_full_state(event_ids)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/logging/opentracing.py", line 901, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/storage/util/partial_state_events_tracker.py", line 82, in await_full_state
    logger.info(

I restarted the server and checked the logs and saw that it was failing to re-sync the broken rooms with errors such as:

2023-03-03 18:05:22,514 - synapse.handlers.federation_event - 1073 - WARNING - sync_partial_state_room-9-$utvlr8R3FKFrtoRlZxyTAtAT6ybEQGW0o6kar9N_aNY - Error attempting to resolve state at missing prev_events: 403: Forbidden
2023-03-03 18:05:22,515 - synapse.handlers.federation - 1924 - ERROR - sync_partial_state_room-9 - Failed to get state for !HsKRUpcYhnAgwvbSgH:matrix.org at <FrozenEventV3 event_id=$utvlr8R3FKFrtoRlZxyTAtAT6ybEQGW0o6kar9N_aNY, type=m.room.member, state_key=@evulid-cc-federation-tester-on-evulid-cc:evulid.cc, outlier=False> from matrix.org because ERROR 403: We can't get valid state history., giving up!
2023-03-03 18:05:22,515 - synapse.metrics.background_process_metrics - 244 - ERROR - sync_partial_state_room-4 - Background process 'sync_partial_state_room' threw an exception
Traceback (most recent call last):
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/handlers/federation_event.py", line 1056, in _compute_event_context_with_maybe_missing_prevs
    await self._get_state_ids_after_missing_prev_event(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/logging/opentracing.py", line 901, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/logging/opentracing.py", line 901, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/handlers/federation_event.py", line 1119, in _get_state_ids_after_missing_prev_event
    ) = await self._federation_client.get_room_state_ids(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/logging/opentracing.py", line 901, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/logging/opentracing.py", line 901, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/federation/federation_client.py", line 505, in get_room_state_ids
    result = await self.transport_layer.get_room_state_ids(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/federation/transport/client.py", line 78, in get_room_state_ids
    return await self.client.get_json(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/http/matrixfederationclient.py", line 1077, in get_json
    response = await self._send_request_with_optional_trailing_slash(
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/http/matrixfederationclient.py", line 406, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/opt/matrix-synapse/lib/python3.10/site-packages/synapse/http/matrixfederationclient.py", line 668, in _send_request
    raise exc
synapse.api.errors.HttpResponseException: 403: Forbidden

Doing /_synapse/admin/v1/purge_history/ on the room yields this:

{"status":"failed","error":"update or delete on table \"events\" violates foreign key constraint \"partial_state_events_event_id_fkey\" on table \"partial_state_events\"\nDETAIL:  Key (event_id)=($U259e4xDM9mlnGzxtK3kGpToqUX8QypNQQ5Tj8lcIwI) is still referenced from table \"partial_state_events\".\n"}

I've thought about nuking everything (#14300 (comment)) but thought I'd file a bug report first.

Steps to reproduce

???

Homeserver

evulid.cc + matrix.org

Synapse Version

1.77.0

Installation Method

pip (from PyPI)

Database

PostgreSQL, no

Workers

Multiple workers

Platform

Ubuntu 22.04 LXC

Configuration

Shorter msg retention

Relevant log output

See above.

Anything else that would be useful to know?

No response
@Cyberes
Copy link
Contributor Author

Cyberes commented Mar 4, 2023

I just updated to v1.78, restarted Synapse and all the workers, and now all the broken rooms are gone from my bot's account.

image

So issue solved, I guess?

@Cyberes Cyberes closed this as completed Mar 4, 2023
@Cyberes Cyberes reopened this Mar 4, 2023
@Cyberes
Copy link
Contributor Author

Cyberes commented Mar 4, 2023

Re-opened. I would appreciate it if a dev reviewed this to make sure it isn't a deeper issue with Synapse.

@DMRobertson
Copy link
Contributor

Looks like there are two problems:

  • purging a room tries to leave the room, so that other servers don't send you traffic for that room. It looks like this can block on full state.
  • purge history looks to be broken for partial state rooms.

@DMRobertson DMRobertson added A-Admin-API A-Moderation Tools for moderating HSes: event redaction, media removal, purge admin API, reports from users, ... A-Federated-Join joins over federation generally suck S-Minor Blocks non-critical functionality, workarounds exist. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. O-Occasional Affects or can be seen by some users regularly or most users rarely labels Mar 8, 2023
@Cyberes
Copy link
Contributor Author

Cyberes commented Mar 9, 2023 •
edited
Loading

Cool. I checked the bots again today and there were a bunch of rooms left over again. I didn't have any issues this time removing them manually. I also added a function to my script to leave every room (instead of just the ones created for that test) and log any errors from leaving/forgetting rooms. I'll update you if I get any logs.

@matrixbot matrixbot mentioned this issue Dec 21, 2023
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Admin-API A-Federated-Join joins over federation generally suck A-Moderation Tools for moderating HSes: event redaction, media removal, purge admin API, reports from users, ... O-Occasional Affects or can be seen by some users regularly or most users rarely S-Minor Blocks non-critical functionality, workarounds exist. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.
Projects
None yet
Milestone
Remaining faster remote join work
Development

No branches or pull requests
2 participants
@DMRobertson @Cyberes