Deadlock at the end of the backfill (not 100% reproducible).

[nalepae]

Sometimes, at the end of the backfill process, we get:

[2026-07-30 19:50:17.37] DEBUG backfill: Imported batch batchId=13828288:13828320 batchesRemaining=10 begin=13828288 blobPid= blockPid=16Uiu2HAmJYCRKjdfVqYNqUEPqjmX1HNKGsJ4VdNRPeJC9XjPYrN7 busyPid=16Uiu2HAmJYCRKjdfVqYNqUEPqjmX1HNKGsJ4VdNRPeJC9XjPYrN7 colPid= end=13828320 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:15.807447205 +0000 UTC m=+32635.201330993 seq=2 state=importable
[2026-07-30 19:50:17.85] DEBUG backfill: Imported batch batchId=13828256:13828288 batchesRemaining=9 begin=13828256 blobPid= blockPid=16Uiu2HAmL7DsdduKsUNdSCxh9NrP2vssrmYrkDSapg5JkmqgJF5A busyPid=16Uiu2HAmL7DsdduKsUNdSCxh9NrP2vssrmYrkDSapg5JkmqgJF5A colPid= end=13828288 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:16.722343682 +0000 UTC m=+32636.116227470 seq=2 state=importable
[2026-07-30 19:50:18.15] DEBUG backfill: Imported batch batchId=13828224:13828256 batchesRemaining=8 begin=13828224 blobPid= blockPid=16Uiu2HAkxtZ7BRTzCqvYMDNsaJzGLm4JNUGvvtBVteK8zAri7LNm busyPid=16Uiu2HAkxtZ7BRTzCqvYMDNsaJzGLm4JNUGvvtBVteK8zAri7LNm colPid= end=13828256 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:17.376384833 +0000 UTC m=+32636.770268621 seq=2 state=importable
[2026-07-30 19:50:19.19] DEBUG backfill: Imported batch batchId=13828192:13828224 batchesRemaining=7 begin=13828192 blobPid= blockPid=16Uiu2HAmUxASPUjQBwEjfqjeDkjdRWguHamHQSZ2EiJrDfepSpba busyPid=16Uiu2HAmUxASPUjQBwEjfqjeDkjdRWguHamHQSZ2EiJrDfepSpba colPid= end=13828224 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:17.854756233 +0000 UTC m=+32637.248640021 seq=2 state=importable
[2026-07-30 19:50:19.32] DEBUG backfill: Imported batch batchId=13828160:13828192 batchesRemaining=6 begin=13828160 blobPid= blockPid=16Uiu2HAm9gK8x5hF37TvKRUMnK1rv5U1XUd1zFwVfFjFaxMKWvDZ busyPid=16Uiu2HAm9gK8x5hF37TvKRUMnK1rv5U1XUd1zFwVfFjFaxMKWvDZ colPid= end=13828192 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:18.153061934 +0000 UTC m=+32637.546945722 seq=2 state=importable
[2026-07-30 19:50:19.92] DEBUG backfill: Imported batch batchId=13828128:13828160 batchesRemaining=5 begin=13828128 blobPid= blockPid=16Uiu2HAkxtZ7BRTzCqvYMDNsaJzGLm4JNUGvvtBVteK8zAri7LNm busyPid=16Uiu2HAkxtZ7BRTzCqvYMDNsaJzGLm4JNUGvvtBVteK8zAri7LNm colPid= end=13828160 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:19.190329447 +0000 UTC m=+32638.584213235 seq=2 state=importable
[2026-07-30 19:50:20.62] DEBUG backfill: Imported batch batchId=13828096:13828128 batchesRemaining=4 begin=13828096 blobPid= blockPid=16Uiu2HAmJYCRKjdfVqYNqUEPqjmX1HNKGsJ4VdNRPeJC9XjPYrN7 busyPid=16Uiu2HAmJYCRKjdfVqYNqUEPqjmX1HNKGsJ4VdNRPeJC9XjPYrN7 colPid= end=13828128 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:19.325958443 +0000 UTC m=+32638.719842191 seq=2 state=importable
[2026-07-30 19:50:20.94] DEBUG backfill: Imported batch batchId=13828064:13828096 batchesRemaining=3 begin=13828064 blobPid= blockPid=16Uiu2HAmEEFin6991smQ4vXGkrHRpB5yXZu2b7GD8jF95nY7RdB8 busyPid=16Uiu2HAmEEFin6991smQ4vXGkrHRpB5yXZu2b7GD8jF95nY7RdB8 colPid= end=13828096 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:19.926218225 +0000 UTC m=+32639.320102013 seq=2 state=importable
[2026-07-30 19:50:21.76] DEBUG backfill: Imported batch batchId=13828032:13828064 batchesRemaining=2 begin=13828032 blobPid= blockPid=16Uiu2HAm9gK8x5hF37TvKRUMnK1rv5U1XUd1zFwVfFjFaxMKWvDZ busyPid=16Uiu2HAm9gK8x5hF37TvKRUMnK1rv5U1XUd1zFwVfFjFaxMKWvDZ colPid= end=13828064 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:20.620430126 +0000 UTC m=+32640.014313914 seq=2 state=importable
[2026-07-30 19:50:22.40] DEBUG backfill: Waiting for descendent batch to complete
[2026-07-30 19:50:22.61] DEBUG backfill: Imported batch batchId=13828000:13828032 batchesRemaining=1 begin=13828000 blobPid= blockPid=16Uiu2HAmMCcBUnUpBaazfD2pYabyPsAh9GYVHyb4exzvPz1MCzQe busyPid=16Uiu2HAmMCcBUnUpBaazfD2pYabyPsAh9GYVHyb4exzvPz1MCzQe colPid= end=13828032 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:20.943216978 +0000 UTC m=+32640.337100766 seq=2 state=importable
[2026-07-30 19:50:22.69] DEBUG backfill: Batch outside retention window batchId=13827981:13827981 begin=13827981 blockPid= busyPid= end=13827981 retentionStartSlot=13827981 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=0001-01-01 00:00:00 +0000 UTC seq=0 state=end_sequence
[2026-07-30 19:50:22.69] DEBUG backfill: Imported batch batchId=13827981:13828000 batchesRemaining=0 begin=13827981 blobPid= blockPid=16Uiu2HAmEEFin6991smQ4vXGkrHRpB5yXZu2b7GD8jF95nY7RdB8 busyPid=16Uiu2HAmEEFin6991smQ4vXGkrHRpB5yXZu2b7GD8jF95nY7RdB8 colPid= end=13828000 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-30 19:50:21.766186127 +0000 UTC m=+32641.160069915 seq=2 state=importable

[No more backfill log]

• We never see the Backfill is complete log
• The backfill process never really ends even if, technically, all the blocks to backfill are backfilled (batchesRemaining=0)
• The DB pruning process, which wait for the backfill to end, never starts.

Restarting the node is a workaround.

A correct backfill termination should look like:

[2026-07-31 09:55:20.27] DEBUG backfill: Validation failed batchId=13832206:13832224 begin=13832206 blockPid=16Uiu2HAmBnZmaGre71139RXA2zUkJ4C36PZcfcKhPp5UGgfbLhg9 busyPid=16Uiu2HAmBnZmaGre71139RXA2zUkJ4C36PZcfcKhPp5UGgfbLhg9 end=13832224 error=no blocks to verify in batch retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-31 09:55:20.262870769 +0000 UTC m=+46364.245270372 seq=1 state=sequenced
[2026-07-31 09:55:20.27] DEBUG backfill: Sleeping for retry backoff delay batchId=13832206:13832224 begin=13832206 blockPid= busyPid=16Uiu2HAmQs5CGRvPCN9TvxXit7aWg6Lv37c2DBf7okLfj9u1s7HH end=13832224 retries=1 retryAfter=2026-07-31 09:55:21.274184318 +0000 UTC m=+46365.256583961 scheduled=2026-07-31 09:55:20.27607181 +0000 UTC m=+46364.258471413 seq=3 state=sequenced untilRetry=997.999428ms
[2026-07-31 09:55:21.54] DEBUG backfill: Waiting for descendent batch to complete
[2026-07-31 09:55:22.35] DEBUG backfill: Imported batch batchId=13832224:13832256 batchesRemaining=1 begin=13832224 blobPid= blockPid=16Uiu2HAkvkioAXvB4xDeDWugpvfXe7vrjYKvEiNxPhSF4HkuCtHp busyPid=16Uiu2HAkvkioAXvB4xDeDWugpvfXe7vrjYKvEiNxPhSF4HkuCtHp colPid= end=13832256 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=2026-07-31 09:55:20.262869849 +0000 UTC m=+46364.245269492 seq=2 state=importable
[2026-07-31 09:55:22.44] DEBUG backfill: Batch outside retention window batchId=13832206:13832206 begin=13832206 blockPid= busyPid= end=13832206 retentionStartSlot=13832206 retries=0 retryAfter=0001-01-01 00:00:00 +0000 UTC scheduled=0001-01-01 00:00:00 +0000 UTC seq=0 state=end_sequence
[2026-07-31 09:55:22.44] DEBUG backfill: Imported batch batchId=13832206:13832224 batchesRemaining=0 begin=13832206 blobPid= blockPid=16Uiu2HAmQs5CGRvPCN9TvxXit7aWg6Lv37c2DBf7okLfj9u1s7HH busyPid=16Uiu2HAmQs5CGRvPCN9TvxXit7aWg6Lv37c2DBf7okLfj9u1s7HH colPid= end=13832224 retries=1 retryAfter=2026-07-31 09:55:21.274184318 +0000 UTC m=+46365.256583961 scheduled=2026-07-31 09:55:20.27607181 +0000 UTC m=+46364.258471413 seq=4 state=importable
[2026-07-31 09:55:22.44]  INFO backfill: Backfill is complete backfillSlot=13832206
[2026-07-31 09:55:22.44]  INFO backfill: Marked as complete
[2026-07-31 09:55:22.44]  INFO backfill: Service is shutting down
[2026-07-31 09:55:22.44]  INFO backfill: Worker exiting after context canceled backfillWorker=1
[2026-07-31 09:55:22.44]  INFO backfill: Worker exiting after context canceled backfillWorker=0
[2026-07-31 09:55:22.44]  INFO backfill: p2pBatchWorkerPool context canceled, shutting down error=context canceled