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

Forward extremity event missing from database, leading to No state group for unknown or outlier event #12507

Closed

Description

@esackbauer

Description

After upgrading to Synapse v1.57.0, one direct room is not working anymore. Cannot post new messages from any client or member.
Cannot roll back history more than the screen, then its stuck.
Cannot leave room "Internal Server Error 500"

Steps to reproduce

Tried rebooting the server, even tried to remove the room with Synapse-Admin - still get an error, room cannot be deleted.

Version information

  • Homeserver:

If not matrix.org:
matrix.flyar.net

  • Version:
    {"server_version":"1.57.0","python_version":"3.9.2"}

  • Install method:

Debian repo

  • Platform:

Debian 11.3 VM x64

This is how the logfile looks like:

2022-04-20 10:03:34,130 - synapse.http.server - 100 - ERROR - GET-0- Failed handle request via 'RoomMessageListRestServlet': <XForwardedForRequest at 0x7f28d07d3730 method>
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: [{'event_id': '$1650209062194EQOlf:matrix.flyar.net', 'state_group': 1277497}]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/state.py", line 331, in _get_state_group_for_events
    raise RuntimeError("No state group for unknown or outlier event %s" % e)
RuntimeError: No state group for unknown or outlier event $1638282339138PTbRx:matrix.flyar.net
2022-04-20 10:03:34,508 - synapse.http.server - 100 - ERROR - GET-1- Failed handle request via 'RoomMessageListRestServlet': <XForwardedForRequest at 0x7f28d07e3be0 method>
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: [{'event_id': '$1650209062194EQOlf:matrix.flyar.net', 'state_group': 1277497}]

The part after "During handling" is repeated. It seems one event is blocking everything? How can I get rid of this?

Activity

  1. changed the title [-]Direct room broken - [/-] [+]Direct room broken - Failed handle request via 'RoomMessageListRestServlet'[/+] on Apr 20, 2022
  2. DMRobertson commented on Apr 20, 2022

    @DMRobertson
    Contributor

    Error message is from #12191. @richvdh, one for you?

  3. changed the title [-]Direct room broken - Failed handle request via 'RoomMessageListRestServlet'[/-] [+]Direct room broken - `No state group for unknown or outlier event`[/+] on Apr 20, 2022
  4. richvdh commented on Apr 20, 2022

    @richvdh
    Member

    Possibly, but there's not really enough info in those logs to help. @esackbauer: is that the complete log? there is nothing logged at INFO?

  5. added
    X-Needs-InfoThis issue is blocked awaiting information from the reporter
    on Apr 20, 2022
  6. esackbauer commented on Apr 20, 2022

    @esackbauer
    Author

    [edited by @richvdh to fix formatting]

    There is actually nothing more. the room which is not working is !DJCGiBKsgowqkkhkfS:matrix.flyar.net

    2022-04-20 14:14:25,352 - synapse.access.http.8008 - 427 - INFO - GET-777- 10.0.0.254 - 8008 - {@xxxxxxx:matrix.flyar.net} Processed request: 7.106sec/0.001sec (0.002sec, 0.000sec) (0.001sec/0.003sec/2) 427B 200 "GET /_matrix/client/r0/sync?filter=16&timeout=30000&since=s1777543_19487621_0_763076_55581_74_3576_68313_1 HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36" [0 dbevts]
    2022-04-20 14:14:25,353 - synapse.access.http.8008 - 427 - INFO - PUT-782- 10.0.0.254 - 8008 - {derechosdigitales.org} Processed request: 0.028sec/0.000sec (0.004sec, 0.000sec) (0.002sec/0.018sec/8) 11B 200 "PUT /_matrix/federation/v1/send/1649264576283 HTTP/1.0" "Synapse/1.54.0" [0 dbevts]
    2022-04-20 14:14:25,857 - synapse.http.server - 100 - ERROR - GET-786- Failed handle request via 'RoomMessageListRestServlet': <XForwardedForRequest at 0x7f5ca035c880 method='GET' uri='/_matrix/client/r0/rooms/!DJCGiBKsgowqkkhkfS:matrix.flyar.net/messages?limit=20&dir=b&from=t26905-1777420_19484474_34_762945_55494_74_3575_68099_1&filter=%7B%22lazy_load_members%22%3Atrue%7D' clientproto='HTTP/1.0' site='8008'>
    Traceback (most recent call last):
      File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
        result = current_context.run(gen.send, result)
    StopIteration: [{'event_id': '$1650209062194EQOlf:matrix.flyar.net', 'state_group': 1277497}]
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last):
      File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
        result = current_context.run(gen.send, result)
      File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/state.py", line 331, in _get_state_group_for_events
        raise RuntimeError("No state group for unknown or outlier event %s" % e)
    RuntimeError: No state group for unknown or outlier event $1638282339138PTbRx:matrix.flyar.net
    2022-04-20 14:14:25,857 - synapse.access.http.8008 - 427 - INFO - GET-786- 10.0.0.254 - 8008 - {@xxxxxxx:matrix.flyar.net} Processed request: 0.003sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.001sec/1) 55B 500 "GET /_matrix/client/r0/rooms/!DJCGiBKsgowqkkhkfS:matrix.flyar.net/messages?limit=20&dir=b&from=t26905-1777420_19484474_34_762945_55494_74_3575_68099_1&filter=%7B%22lazy_load_members%22%3Atrue%7D HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36" [0 dbevts]
    2022-04-20 14:14:28,904 - synapse.federation.transport.server.federation - 102 - INFO - PUT-787- Received txn 1648140153658 from theyosh.nl. (PDUs: 0, EDUs: 1)
    2022-04-20 14:14:28,924 - synapse.access.http.8008 - 427 - INFO - GET-784- 10.0.0.254 - 8008 - {@xxxxxxx:matrix.flyar.net} Processed request: 3.538sec/0.001sec (0.001sec, 0.000sec) (0.001sec/0.003sec/2) 386B 200 "GET /_matrix/client/r0/sync?filter=16&timeout=30000&since=s1777543_19487622_0_763076_55581_74_3576_68313_1 HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36" [0 dbevts]
    2022-04-20 14:14:28,927 - synapse.access.http.8008 - 427 - INFO - PUT-787- 10.0.0.254 - 8008 - {theyosh.nl} Processed request: 0.023sec/0.000sec (0.001sec, 0.002sec) (0.002sec/0.016sec/6) 11B 200 "PUT /_matrix/federation/v1/send/1648140153658 HTTP/1.0" "Synapse/1.49.2" [0 dbevts]
    2022-04-20 14:14:29,072 - synapse.metrics._gc - 120 - INFO - sentinel- Collecting gc 1
    2022-04-20 14:14:29,747 - synapse.federation.transport.server.federation - 102 - INFO - PUT-790- Received txn 1647625979627 from jaccu.se. (PDUs: 0, EDUs: 1)
    2022-04-20 14:14:29,753 - synapse.access.http.8008 - 427 - INFO - PUT-790- 10.0.0.254 - 8008 - {jaccu.se} Processed request: 0.010sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.005sec/3) 11B 200 "PUT /_matrix/federation/v1/send/1647625979627 HTTP/1.0" "Synapse/1.54.0" [0 dbevts]
    2022-04-20 14:14:29,856 - synapse.http.server - 100 - ERROR - GET-791- Failed handle request via 'RoomMessageListRestServlet': <XForwardedForRequest at 0x7f5ca025ff40 method='GET' uri='/_matrix/client/r0/rooms/!DJCGiBKsgowqkkhkfS:matrix.flyar.net/messages?limit=20&dir=b&from=t26905-1777420_19484474_34_762945_55494_74_3575_68099_1&filter=%7B%22lazy_load_members%22%3Atrue%7D' clientproto='HTTP/1.0' site='8008'>
    Traceback (most recent call last):
      File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
        result = current_context.run(gen.send, result)
    StopIteration: [{'event_id': '$1650209062194EQOlf:matrix.flyar.net', 'state_group': 1277497}]
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last):
      File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
        result = current_context.run(gen.send, result)
      File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/state.py", line 331, in _get_state_group_for_events
        raise RuntimeError("No state group for unknown or outlier event %s" % e)
    RuntimeError: No state group for unknown or outlier event $1638282339138PTbRx:matrix.flyar.net
    2022-04-20 14:14:29,857 - synapse.access.http.8008 - 427 - INFO - GET-791- 10.0.0.254 - 8008 - {@xxxxxxx:matrix.flyar.net} Processed request: 0.003sec/0.000sec (0.002sec, 0.000sec) (0.000sec/0.001sec/1) 55B 500 "GET /_matrix/client/r0/rooms/!DJCGiBKsgowqkkhkfS:matrix.flyar.net/messages?limit=20&dir=b&from=t26905-1777420_19484474_34_762945_55494_74_3575_68099_1&filter=%7B%22lazy_load_members%22%3Atrue%7D HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36" [0 dbevts]
    2022-04-20 14:14:30,002 - synapse.federation.transport.server.federation - 102 - INFO - PUT-792- Received txn 1648259608250 from chat.tux.land. (PDUs: 0, EDUs: 1)
    2022-04-20 14:14:30,009 - synapse.access.http.8008 - 427 - INFO - PUT-792- 10.0.0.254 - 8008 - {chat.tux.land} Processed request: 0.014sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.007sec/3) 11B 200 "PUT /_matrix/federation/v1/send/1648259608250 HTTP/1.0" "Synapse/1.55.0" [0 dbevts]
    
  7. richvdh commented on Apr 20, 2022

    @richvdh
    Member

    [please wrap your logs in triple-backticks (```) for legibility]

    well, that's frustrating. Could you maybe enable DEBUG logging (change the level to DEBUG in your log config file)?

  8. esackbauer commented on Apr 20, 2022

    @esackbauer
    Author

    Ok, sorry. The debug output is rather large, I did a clean start of synapse and logged everything after I tried to post something in that room.

    Because its so large, I attached the homeserver.log

  9. richvdh commented on Apr 20, 2022

    @richvdh
    Member

    Right, well, that sheds a bit of light on the situation, but not much.

    I'd like to ask you to run some queries on your database - could you DM me at @richvdh:sw1v.org ?

  10. esackbauer commented on Apr 20, 2022

    @esackbauer
    Author
  11. richvdh commented on Apr 20, 2022

    @richvdh
  12. esackbauer commented on Apr 20, 2022

    @esackbauer
    Author
  13. richvdh commented on Apr 20, 2022

    @richvdh
    Member

    It seems that a particular event ($1638282339138PTbRx:matrix.flyar.net) is marked as a forward extremity, but that event is not present in the database.

    Attempts to delete the room are failing, because the delete operation tries to generate leave events for each of the members of the room - which requires the forward extremities to exist.

    The event id suggests that the event was created in November 2021, so this problem has probably been waiting undetected since then, and it only became a real problem when Synapse 1.57 added the extra validation.

    I'm at a bit of a loss to explain how this could have happened. There's essentially no way for an entry to be added to event_forward_extremites without there also being an entry in events. It could have been related to #11521, but since this room isn't federated, I don't think it can be.

  14. changed the title [-]Direct room broken - `No state group for unknown or outlier event`[/-] [+]Forward extremity event missing from database, leading to `No state group for unknown or outlier event`[/+] on Apr 20, 2022
  15. removed
    X-Needs-InfoThis issue is blocked awaiting information from the reporter
    on Apr 20, 2022
  16. 16 remaining items

  17. travisghansen commented on Apr 25, 2022

    @travisghansen
    • Is this affecting a federated room (ie, are there now, or have there ever been, any users on other servers in this room)?

    My install is fully isolated currently.

    • do you have retention enabled on your server?

    I've never enabled that, so I'm guessing the default is no. Glad to now know it exists however! That's partly why I wasn't federating anything as I knew the data would grow massively on public rooms etc :)

    No.

    • Have you done any database maintenance operations which could somehow have introduced this (eg: backup/restore; port from sqlite)?

    No.

  18. added
    T-DefectBugs, crashes, hangs, security vulnerabilities, or other reported issues.
    on Apr 25, 2022
  19. richvdh commented on Apr 26, 2022

    @richvdh
    Member

    @MparkG: as the earlier comments make very clear: "If it doesn't [return any rows] you likely have a different problem and should open a separate issue".

  20. richvdh commented on Apr 26, 2022

    @richvdh
    Member

    @travisghansen thanks for the answers, though honestly they don't help me get any closer to understanding what can have caused this.

    Be wary of retention: it's not a well-used feature and the reason I asked about it is that it is likely to cause corruption bugs like this.

  21. mweinelt commented on May 31, 2022

    @mweinelt
    Contributor

    We're seeing exceptions like these as well and those rooms can't be written to. This is a room on the hackint IRC bridge, so lots of federated users, no usage of delete room or purge history API endpoints and we are using rust-synapse-compress-state regularly.

    We're on Synapse 1.58.01.59.1 right now.

    Feel free to contact me at @hexa:lossy.network and we can debug this together.

    Traceback
     synapse.http.server: [PUT-672070] Failed handle request via 'RoomSendEventRestServlet': <XForwardedForRequest at 0x7fb87ab32a30 method='PUT' uri='/_matrix/client/r0/rooms/!lxUgQdCOpWnOrYNVxb%3Ahax404.de/send/m.room.message/1653997592776__inc2?user_id=%40hexa-%3Ahackint.org' clientproto='HTTP/1.1' site='8008'>
     Traceback (most recent call last):
       File "/nix/store/ks8r355nmkcx9q23s4m3nm1y767rfrln-python3.9-Twisted-22.4.0/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
         result = current_context.run(gen.send, result)
     StopIteration: [{'event_id': '$Ps2Ot0YLz20kbjS8lRFmK_Yo4t2fXPAvq3IU0CQTMoU', 'state_group': 820535}]
     
     During handling of the above exception, another exception occurred:
     
     Traceback (most recent call last):
       File "/nix/store/ks8r355nmkcx9q23s4m3nm1y767rfrln-python3.9-Twisted-22.4.0/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
         result = current_context.run(gen.send, result)
       File "/nix/store/lan1pgij0701dzi9nsvvy6nn62qk93b5-matrix-synapse-1.58.0/lib/python3.9/site-packages/synapse/storage/databases/main/state.py", line 332, in _get_state_group_for_events
         raise RuntimeError("No state group for unknown or outlier event %s" % e)
     RuntimeError: No state group for unknown or outlier event $FXKIdG6LkVKVsOEROx4IBer-eqPsQ-HCWdWpRuqyRFk
    Retention

    We are indeed using a pretty aggressive retention rule, since we only want to relay the bridged content, but not store it persistenly.

    retention:
      allowed_lifetime_max: 1m
      allowed_lifetime_min: 1m
      default_policy:
        max_lifetime: 1m
        min_lifetime: 1m
      enabled: true
      purge_jobs:
      - interval: 30m
    Query result

    select * from event_forward_extremities efe left join events e using (event_id) where e.event_id is null;
    (7 rows)

    Not the event id mentioned in the traceback above, but I guess that's still worth debugging/fixing.

    No corruption log lines

    We don't see any corruption log events from #12620

    Removed events according to #12507 (comment)
    matrix-synapse=# SELECT count(event_id) FROM event_forward_extremities;
    count 
    -------
    2660
    (1 row)
    matrix-synapse=# BEGIN;
    BEGIN
    matrix-synapse=# DELETE FROM event_forward_extremities WHERE event_id IN (select event_id from event_forward_extremities efe left join events e using (event_id) where e.event_id is null);
    DELETE 7
    matrix-synapse=# SELECT count(event_id) FROM event_forward_extremities;
    count 
    -------
    2655
    (1 row)
    
    matrix-synapse=# END;
    COMMIT

    2660 - 7 = 2655 … okay. 🤔

  22. richvdh commented on Aug 8, 2022

    @richvdh
    Member

    @mweinelt: it is unsurprising to me that you would see these symptoms when retention is enabled, particularly with such aggressive numbers (see #13476). This issue is specific to people who do not have retention enabled, meaning there is no explanation for the missing event_forward_extremities.

  23. added
    S-MajorMajor functionality / product severely impaired, no satisfactory workaround.
    A-DatabaseDB stuff like queries, migrations, new/remove columns, indexes, unexpected entries in the db
    O-UncommonMost users are unlikely to come across this or unexpected workflow
    A-CorruptionThings that have led to unexpected state in Synapse or the database
    on Dec 8, 2022
  24. 14mRh4X0r commented on Jan 24, 2023

    @14mRh4X0r
    Contributor

    I noticed it recently when restarting a bot.

    • Is this affecting a federated room (ie, are there now, or have there ever been, any users on other servers in this room)?

    Yes. The event is my own homeserver's though.

    • do you have retention enabled on your server?

    No.

    Yes, only purge history; it has happened that Synapse was terminated during mass purging, it may have been while purging this room.

    • Have you done any database maintenance operations which could somehow have introduced this (eg: backup/restore; port from sqlite)?

    No.

  25. squahtx commented on Jan 25, 2023

    @squahtx
    Contributor

    @14mRh4X0r Could you post the logs for your issue?

  26. 14mRh4X0r commented on Jan 25, 2023

    @14mRh4X0r
    Contributor

    Sure (Synapse 1.66.0 from Debian backports):

    2023-01-24 00:03:03,106 - synapse.http.server - 185 - ERROR - PUT-725315- Failed handle request via 'RoomSendEventRestServlet': <XForwardedForRequest at 0x7fa6af4ff9a0 method='PUT' uri='/_matrix/client/r0/rooms/%21zCLWAbYiBPnmFazMZQ:t2l.io/send/m.room.message/go1674514983085965456?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'>
    Traceback (most recent call last):
      File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
        result = g.send(result)
    StopIteration: []
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last):
      File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python3/dist-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python3/dist-packages/synapse/rest/client/room.py", line 343, in on_POST
        ) = await self.event_creation_handler.create_and_send_nonmember_event(
      File "/usr/lib/python3/dist-packages/synapse/handlers/message.py", line 996, in create_and_send_nonmember_event
        ev = await self.handle_new_client_event(
      File "/usr/lib/python3/dist-packages/synapse/util/metrics.py", line 113, in measured_func
        r = await func(self, *args, **kwargs)
      File "/usr/lib/python3/dist-packages/synapse/handlers/message.py", line 1330, in handle_new_client_event
        result, _ = await make_deferred_yieldable(
      File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
        result = g.send(result)
      File "/usr/lib/python3/dist-packages/synapse/storage/databases/main/state.py", line 371, in _get_state_group_for_events
        raise RuntimeError("No state group for unknown or outlier event %s" % e)
    RuntimeError: No state group for unknown or outlier event $167038633525fvhTN:canarymod.net
    2023-01-24 00:03:03,107 - synapse.access.http.8008 - 450 - INFO - PUT-725315- 2001:67c:2564:331:215:5dff:fea8:9aee - 8008 - {@monitor-bot:canarymod.net} Processed request: 0.020sec/0.000sec (0.003sec, 0.001sec) (0.001sec/0.003sec/4) 55B 500 "PUT /_matrix/client/r0/rooms/%21zCLWAbYiBPnmFazMZQ:t2l.io/send/m.room.message/go1674514983085965456?access_token=<redacted> HTTP/1.0" "Go-http-client/2.0" [0 dbevts]
    
  27. richvdh commented on Jan 30, 2023

    @richvdh
    Member

    I'm going to assume @14mRh4X0r's issue is caused by their use of the history purge function and is hence a duplicate of #13476.

    As far as I can tell from the history in this issue, everybody who has seen this (apart from @travisghansen) has, at some point in the past, used one of the history deletion functions. @travisghansen's symptoms remain unexplained, but in the absence of further reports, it's unlikely to be worth further investigation.

    Accordingly, I'm closing this as a duplicate of #13476.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    A-CorruptionThings that have led to unexpected state in Synapse or the databaseA-DatabaseDB stuff like queries, migrations, new/remove columns, indexes, unexpected entries in the dbO-UncommonMost users are unlikely to come across this or unexpected workflowS-MajorMajor functionality / product severely impaired, no satisfactory workaround.T-DefectBugs, crashes, hangs, security vulnerabilities, or other reported issues.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions