KeyError: event_id on received transaction

[turt2live]

This has happened 6 times according to sentry (t2bot.io homeserver, 1.0):

_DefGen_Return: None
  File "twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "synapse/storage/_base.py", line 545, in runWithConnection
    defer.returnValue(result)
  File "twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
_DefGen_Return: None
  File "twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "synapse/storage/_base.py", line 505, in runInteraction
    defer.returnValue(result)
  File "twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
KeyError: 'event_id'
  File "synapse/federation/transport/server.py", line 393, in on_PUT
    origin, transaction_data,
  File "twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/federation/federation_server.py", line 125, in on_incoming_transaction
    origin, transaction, request_time,
  File "twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "synapse/federation/federation_server.py", line 218, in _handle_incoming_transaction
    event = event_from_pdu_json(p, format_ver)
  File "synapse/federation/federation_base.py", line 384, in event_from_pdu_json
    pdu_json,
  File "synapse/events/__init__.py", line 243, in __init__
    self.event_id = event_dict["event_id"]

[campbellr]

Not sure if this the same issue, but i just started seeing something similar on my homeserver (which now repeatedly fails syncing on all my devices.

This is the first KeyError i see in my logs

2019-12-30 09:06:01,328 - synapse.access.http.8008 - 233 - INFO - PUT-866835- 176.126.240.158 - 8008 - Received request: PUT /_matrix/federation/v1/send/1577034077697/
2019-12-30 09:06:01,329 - synapse.federation.transport.server - 154 - INFO - PUT-866835- Request from matrix.org
2019-12-30 09:06:01,330 - synapse.federation.transport.server - 389 - INFO - PUT-866835- Received txn 1577034077697 from matrix.org. (PDUs: 1, EDUs: 0)
2019-12-30 09:06:01,335 - synapse.handlers.federation - 184 - INFO - PUT-866835-$8l7/U97QjDXLjc+Ym9qzyBaO0tFF9KeYUPgH5x/vdTA- [!BAXLHOFjvDKUeLafmO:matrix.org $8l7/U97QjDXLjc+Ym9qzyBaO0tFF9KeYUPgH5x/vdTA] handling received PDU: <FrozenEventV2 event_id='$8l7/U97QjDXLjc+Ym9qzyBaO0tFF9KeYUPgH5x/vdTA', type='m.room.member', state_key='@Rnytom:matrix.org'>
2019-12-30 09:06:01,373 - synapse.storage.persist_events - 373 - INFO - persist_events-19540- Calculating state delta for room !BAXLHOFjvDKUeLafmO:matrix.org
2019-12-30 09:06:01,375 - synapse.state - 495 - INFO - persist_events-19540- Resolving state for !BAXLHOFjvDKUeLafmO:matrix.org with 2 groups
2019-12-30 09:06:01,376 - synapse.state - 518 - INFO - persist_events-19540- Resolving conflicted state for '!BAXLHOFjvDKUeLafmO:matrix.org'
2019-12-30 09:06:01,435 - synapse.federation.federation_server - 246 - ERROR - PUT-866835-$8l7/U97QjDXLjc+Ym9qzyBaO0tFF9KeYUPgH5x/vdTA- Failed to handle PDU $8l7/U97QjDXLjc+Ym9qzyBaO0tFF9KeYUPgH5x/vdTA
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/federation/federation_server.py", line 235, in process_pdus_for_room
    await self._handle_received_pdu(origin, pdu)
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/federation/federation_server.py", line 634, in _handle_received_pdu
    await self.handler.on_receive_pdu(origin, pdu, sent_to_us_directly=True)
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'KeyError'>: '$S38_aRG4Qz8eIdrTyzJuQdH3Ieus1Y1dhczoFKnOB7M'
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:654:_runCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1475:gotResult
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- <exception caught here> ---
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/persist_events.py:147:handle_queue_loop
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/persist_events.py:257:persisting_queue
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/persist_events.py:381:_persist_events
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/persist_events.py:623:_get_new_state_after_events
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/state/__init__.py:525:resolve_state_groups
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/state/v2.py:116:resolve_events_with_store
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/state/v2.py:364:_reverse_topological_power_sort
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/state/v2.py:186:_get_power_level_for_sender
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/state/v2.py:535:_get_event
]]

[turt2live]

@campbellr you're running into the same problem described here: #6605

[campbellr]

Thanks, not sure how I missed that.

[turt2live]

After a while all the python stacktraces look the same.