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 #12606

Closed
haslersn opened this issue May 2, 2022 · 1 comment
Closed

Error attempting to resolve state at missing prev_events #12606

haslersn opened this issue May 2, 2022 · 1 comment

Comments

@haslersn
Copy link
Contributor

haslersn commented May 2, 2022

I observed the following error log on synapse 1.57.1 (official Docker image). Not sure how to reproduce it and what to do with it. I'm not aware of any user-facing effect due to that error (server continues to serve normally), but I think having Python backtraces in the log is not something normal. Also not sure if this is a duplicate of #10764.

2022-05-02 14:05:48,962 - synapse.federation.sender.per_destination_queue - 357 - WARNING - federation_transaction_transmission_loop-1959749 - TX [bknow.net] Received 403 response to transaction: 403: Forbidden
2022-05-02 14:05:48,978 - synapse.handlers.federation_event - 829 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU - Error attempting to resolve state at missing prev_events
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 794, in _resolve_state_at_missing_prevs
    remote_state = await self._get_state_after_missing_prev_event(
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 954, in _get_state_after_missing_prev_event
    raise Exception("Unable to get missing prev_event %s" % (event_id,))
Exception: Unable to get missing prev_event $fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ
2022-05-02 14:05:48,980 - synapse.handlers.federation_event - 720 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU - Pulled event $w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU failed history check.
2022-05-02 14:05:48,991 - synapse.logging.context - 81 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU-$fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ-$_PjcCnX0SH_-WC3NjRRmJMGR6uQqpfzANNQIzuGIlMo - Re-starting finished log context _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU-$fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ-$_PjcCnX0SH_-WC3NjRRmJMGR6uQqpfzANNQIzuGIlMo
2022-05-02 14:05:48,992 - synapse.logging.context - 81 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU-$fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ-$_PjcCnX0SH_-WC3NjRRmJMGR6uQqpfzANNQIzuGIlMo - Re-starting finished log context _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU-$fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ-$_PjcCnX0SH_-WC3NjRRmJMGR6uQqpfzANNQIzuGIlMo
2022-05-02 14:05:48,993 - synapse.logging.context - 81 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU-$fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ-$_PjcCnX0SH_-WC3NjRRmJMGR6uQqpfzANNQIzuGIlMo - Re-starting finished log context _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU-$fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ-$_PjcCnX0SH_-WC3NjRRmJMGR6uQqpfzANNQIzuGIlMo
2022-05-02 14:05:48,994 - synapse.logging.context - 81 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU-$fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ-$_PjcCnX0SH_-WC3NjRRmJMGR6uQqpfzANNQIzuGIlMo - Re-starting finished log context _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$w2ov5NMNbF2LGjAgLnZgB041f0Bs2stS9xSEF7r1PSU-$fzUcwU5EkYMglMBJAqe6kUWKinmwH-GQDtBfrlGQrpQ-$_PjcCnX0SH_-WC3NjRRmJMGR6uQqpfzANNQIzuGIlMo
2022-05-02 14:05:49,026 - synapse.handlers.federation_event - 829 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$5NQ1VsKif5EiR8Btl5vXcbOjIBwVne6Et5hjgCVLJZg - Error attempting to resolve state at missing prev_events
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: DestinationRetryTimings(failure_ts=1651500342591, retry_last_ts=1651500342591, retry_interval=600000)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: DestinationRetryTimings(failure_ts=1651500342591, retry_last_ts=1651500342591, retry_interval=600000)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 794, in _resolve_state_at_missing_prevs
    remote_state = await self._get_state_after_missing_prev_event(
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 860, in _get_state_after_missing_prev_event
    ) = await self._federation_client.get_room_state_ids(
  File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_client.py", line 409, in get_room_state_ids
    result = await self.transport_layer.get_room_state_ids(
  File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/client.py", line 83, in get_room_state_ids
    return await self.client.get_json(
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 1043, in get_json
    response = await self._send_request_with_optional_trailing_slash(
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 382, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 471, in _send_request
    limiter = await synapse.util.retryutils.get_retry_limiter(
  File "/usr/local/lib/python3.9/site-packages/synapse/util/retryutils.py", line 102, in get_retry_limiter
    raise NotRetryingDestination(
synapse.util.retryutils.NotRetryingDestination: Not retrying server sspaeth.de.
2022-05-02 14:05:49,029 - synapse.handlers.federation_event - 720 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$5NQ1VsKif5EiR8Btl5vXcbOjIBwVne6Et5hjgCVLJZg - Pulled event $5NQ1VsKif5EiR8Btl5vXcbOjIBwVne6Et5hjgCVLJZg failed history check.
2022-05-02 14:05:49,050 - synapse.handlers.federation_event - 829 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$D0kgXu5hKRjDKQsGFOJ0vOJs_3lbTZguQlLlFd-33_I - Error attempting to resolve state at missing prev_events
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: []

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 794, in _resolve_state_at_missing_prevs
    remote_state = await self._get_state_after_missing_prev_event(
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 860, in _get_state_after_missing_prev_event
    ) = await self._federation_client.get_room_state_ids(
  File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_client.py", line 409, in get_room_state_ids
    result = await self.transport_layer.get_room_state_ids(
  File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/client.py", line 83, in get_room_state_ids
    return await self.client.get_json(
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 1043, in get_json
    response = await self._send_request_with_optional_trailing_slash(
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 382, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 471, in _send_request
    limiter = await synapse.util.retryutils.get_retry_limiter(
  File "/usr/local/lib/python3.9/site-packages/synapse/util/retryutils.py", line 102, in get_retry_limiter
    raise NotRetryingDestination(
synapse.util.retryutils.NotRetryingDestination: Not retrying server sspaeth.de.
2022-05-02 14:05:49,051 - synapse.handlers.federation_event - 720 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$D0kgXu5hKRjDKQsGFOJ0vOJs_3lbTZguQlLlFd-33_I - Pulled event $D0kgXu5hKRjDKQsGFOJ0vOJs_3lbTZguQlLlFd-33_I failed history check.
2022-05-02 14:05:49,066 - synapse.handlers.federation_event - 829 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$-uSRKmeKZOiDwBe7awwobdTJ2IrkbVqVJuPuvD7AXQE - Error attempting to resolve state at missing prev_events
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: []

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 794, in _resolve_state_at_missing_prevs
    remote_state = await self._get_state_after_missing_prev_event(
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 860, in _get_state_after_missing_prev_event
    ) = await self._federation_client.get_room_state_ids(
  File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_client.py", line 409, in get_room_state_ids
    result = await self.transport_layer.get_room_state_ids(
  File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/client.py", line 83, in get_room_state_ids
    return await self.client.get_json(
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 1043, in get_json
    response = await self._send_request_with_optional_trailing_slash(
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 382, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 471, in _send_request
    limiter = await synapse.util.retryutils.get_retry_limiter(
  File "/usr/local/lib/python3.9/site-packages/synapse/util/retryutils.py", line 102, in get_retry_limiter
    raise NotRetryingDestination(
synapse.util.retryutils.NotRetryingDestination: Not retrying server sspaeth.de.
2022-05-02 14:05:49,067 - synapse.handlers.federation_event - 720 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$-uSRKmeKZOiDwBe7awwobdTJ2IrkbVqVJuPuvD7AXQE - Pulled event $-uSRKmeKZOiDwBe7awwobdTJ2IrkbVqVJuPuvD7AXQE failed history check.
2022-05-02 14:05:49,082 - synapse.handlers.federation_event - 829 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$7s5FwGnr0O7SW-k4ps4728YhN-f5xu4T265DgtvE2LI - Error attempting to resolve state at missing prev_events
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: []

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 794, in _resolve_state_at_missing_prevs
    remote_state = await self._get_state_after_missing_prev_event(
  File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 860, in _get_state_after_missing_prev_event
    ) = await self._federation_client.get_room_state_ids(
  File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_client.py", line 409, in get_room_state_ids
    result = await self.transport_layer.get_room_state_ids(
  File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/client.py", line 83, in get_room_state_ids
    return await self.client.get_json(
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 1043, in get_json
    response = await self._send_request_with_optional_trailing_slash(
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 382, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 471, in _send_request
    limiter = await synapse.util.retryutils.get_retry_limiter(
  File "/usr/local/lib/python3.9/site-packages/synapse/util/retryutils.py", line 102, in get_retry_limiter
    raise NotRetryingDestination(
synapse.util.retryutils.NotRetryingDestination: Not retrying server sspaeth.de.
2022-05-02 14:05:49,083 - synapse.handlers.federation_event - 720 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw-$7s5FwGnr0O7SW-k4ps4728YhN-f5xu4T265DgtvE2LI - Pulled event $7s5FwGnr0O7SW-k4ps4728YhN-f5xu4T265DgtvE2LI failed history check.
2022-05-02 14:05:49,090 - synapse.handlers.federation_event - 260 - WARNING - _process_incoming_pdus_in_room_inner-12221-$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw - Rejecting: failed to fetch 4 prev events: ['$D0kgXu5hKRjDKQsGFOJ0vOJs_3lbTZguQlLlFd-33_I', '$-uSRKmeKZOiDwBe7awwobdTJ2IrkbVqVJuPuvD7AXQE', '$5NQ1VsKif5EiR8Btl5vXcbOjIBwVne6Et5hjgCVLJZg', '$7s5FwGnr0O7SW-k4ps4728YhN-f5xu4T265DgtvE2LI']
2022-05-02 14:05:49,091 - synapse.federation.federation_server - 1105 - WARNING - _process_incoming_pdus_in_room_inner-12221 - Error handling PDU $228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.
2022-05-02 14:05:49,169 - synapse.handlers.federation_event - 618 - WARNING - _process_incoming_pdus_in_room_inner-12221-$MLPmuuZCH7LxDx_z2RFiwa2W7R-TE9BkkJBa1r4cELQ - Failed to get prev_events: Not retrying server sspaeth.de.
2022-05-02 14:05:49,188 - synapse.handlers.federation_event - 260 - WARNING - _process_incoming_pdus_in_room_inner-12221-$MLPmuuZCH7LxDx_z2RFiwa2W7R-TE9BkkJBa1r4cELQ - Rejecting: failed to fetch 1 prev events: ['$228IlevA3TA6AN6sYQYCBSLap3w-myJXiYFwMQ7Mxnw']
2022-05-02 14:05:49,189 - synapse.federation.federation_server - 1105 - WARNING - _process_incoming_pdus_in_room_inner-12221 - Error handling PDU $MLPmuuZCH7LxDx_z2RFiwa2W7R-TE9BkkJBa1r4cELQ: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.
@H-Shay
Copy link
Contributor

H-Shay commented May 2, 2022

I think actually this is a duplicate of #12539, closing in favor of that one.

@H-Shay H-Shay closed this as completed May 2, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@H-Shay @haslersn