Unhandled error: Failed to backfill ... AttributeError redacts

[jo-so]

Description

I've got this error in my synapse logs:

synapse.handlers.federation: [GET-46198] Failed to backfill from … because FirstError[#0, [Failure instance: Traceback: <class 'AttributeError'>: redacts
/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:491:throwExceptionIntoGenerator
--- <exception caught here> ---
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:157: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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:316: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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:198:f
/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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:493:_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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py:408:runInteraction
/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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py:457:runWithConnection
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/threadpool.py:250:inContext
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/threadpool.py:266:<lambda>
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/context.py:122:callWithContext
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/context.py:85:callWithContext
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/compat.py:464:reraise
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py:453:inner_func
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py:329:_new_transaction
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/util/logutils.py:88:wrapped
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:902:_persist_events_txn
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:1334:_update_metadata_tables_txn
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/events/__init__.py:89:getter
]]
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/handlers/federation.py", line 933, in try_backfill
    extremities=extremities,
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'AttributeError'>: redacts
/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:491:throwExceptionIntoGenerator
--- <exception caught here> ---
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:157: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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:316: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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:198:f
/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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:493:_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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py:408:runInteraction
/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:491:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py:457:runWithConnection
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/threadpool.py:250:inContext
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/threadpool.py:266:<lambda>
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/context.py:122:callWithContext
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/context.py:85:callWithContext
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/compat.py:464:reraise
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py:453:inner_func
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py:329:_new_transaction
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/util/logutils.py:88:wrapped
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:902:_persist_events_txn
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/events.py:1334:_update_metadata_tables_txn
/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/events/__init__.py:89:getter
]]

Version information

• Version: 0.99.2+stretch1
• Install method: Debian package from matrix.org
• Platform: Debian stable

[richvdh]

is this still a problem? A lot of the redaction code has been rewritten so I think it might have been fixed

[jo-so]

I don't know. I see so much errors and warnings from Synapse that I can't tell when this error came up the last time.

[richvdh]

let us know if you see it again.

[csett86]

To me it seems that unfortunately this is again occurring with synapse 1.4.1, see eg:

2019-10-28 14:09:26,373 - synapse.handlers.federation - 989 - ERROR - GET-6999 - Failed to backfill from matrix.org because FirstError[#0, [Failure instance: Traceback: <class 'AttributeError'>: redacts
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1475:gotResult
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- ---
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:181:handle_queue_loop
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:353:persisting_queue
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:223:f
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:539:_persist_events
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/_base.py:506:runInteraction
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/_base.py:554:runWithConnection
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/threadpool.py:250:inContext
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/threadpool.py:266:
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/context.py:122:callWithContext
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/context.py:85:callWithContext
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/compat.py:464:reraise
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/_base.py:551:inner_func
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/_base.py:423:_new_transaction
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/logging/utils.py:79:wrapped
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:1014:_persist_events_txn
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:1456:_update_metadata_tables_txn
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/events/init.py:127:getter
]]
Traceback (most recent call last):
File "/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/handlers/federation.py", line 964, in try_backfill
dom, room_id, limit=100, extremities=extremities
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'AttributeError'>: redacts
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1475:gotResult
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- ---
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:181:handle_queue_loop
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:353:persisting_queue
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:223:f
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:539:_persist_events
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/_base.py:506:runInteraction
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/_base.py:554:runWithConnection
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/threadpool.py:250:inContext
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/threadpool.py:266:
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/context.py:122:callWithContext
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/context.py:85:callWithContext
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/python/compat.py:464:reraise
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/_base.py:551:inner_func
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/_base.py:423:_new_transaction
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/logging/utils.py:79:wrapped
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:1014:_persist_events_txn
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/storage/events.py:1456:_update_metadata_tables_txn
/home/pacs/lki01/users/synod/synapse/env37/lib/python3.7/site-packages/synapse/events/init.py:127:getter
]]

[richvdh]

So this happens when we have a redaction event without a redacts property, which can happen when a redaction is redacted. #6145 was a partial fix to this, but there are clearly other instances.

[richvdh]

think this was probably fixed by #6771