PANIC at metaslab.c:5341:metaslab_free_concrete()

[lukashass]

I am unable to import a pool of 2 mirrored disks because of the following kernel panic:

VERIFY3(0 == P2PHASE(asize, 1ULL << vd->vdev_ashift)) failed (0 == 1024)
PANIC at metaslab.c:5341:metaslab_free_concrete()

Pool setup:

   pool: data
     id: 9243778338286895504
  state: ONLINE
status: The pool was last accessed by another system.
 action: The pool can be imported using its name or numeric identifier and
	the '-f' flag.
   see: https://openzfs.github.io/openzfs-docs/msg/ZFS-8000-EY
 config:

	data        ONLINE
	  mirror-0  ONLINE
	    sdb     ONLINE
	    sda     ONLINE

I'm using 2.1.22 so the line in question should be: https://github.com/openzfs/zfs/blob/zfs-2.1.12/module/zfs/metaslab.c#L5341

The disks themselves seem fine (short SMART test completed without errors), though the situation might be caused by some recent power outages.

I'm wondering what asize and ashift actually are and of course how to fix this issue and successfully import the pool.

dmesg trace:

Call Trace:
[ 1440.263680] Call Trace:
[ 1440.263683]  <TASK>
[ 1440.263688]  dump_stack_lvl+0x48/0x70
[ 1440.263702]  dump_stack+0x10/0x20
[ 1440.263708]  spl_dumpstack+0x29/0x40 [spl]
[ 1440.263731]  spl_panic+0xfc/0x120 [spl]
[ 1440.263759]  metaslab_free_concrete+0x287/0x290 [zfs]
[ 1440.264044]  ? dmu_buf_will_dirty_impl+0x142/0x190 [zfs]
[ 1440.264257]  metaslab_free_impl+0xc1/0x110 [zfs]
[ 1440.264455]  metaslab_free_dva+0x61/0x90 [zfs]
[ 1440.264650]  metaslab_free+0x117/0x1d0 [zfs]
[ 1440.264845]  zio_free_sync+0xfb/0x120 [zfs]
[ 1440.265064]  dsl_scan_free_block_cb+0x6e/0x1f0 [zfs]
[ 1440.265268]  bpobj_dsl_scan_free_block_cb+0x11/0x20 [zfs]
[ 1440.265456]  bpobj_iterate_blkptrs+0x13c/0x3e0 [zfs]
[ 1440.265620]  ? __pfx_bpobj_dsl_scan_free_block_cb+0x10/0x10 [zfs]
[ 1440.265808]  bpobj_iterate_impl+0x261/0x4e0 [zfs]
[ 1440.265973]  ? __pfx_bpobj_dsl_scan_free_block_cb+0x10/0x10 [zfs]
[ 1440.266160]  bpobj_iterate+0x17/0x30 [zfs]
[ 1440.266323]  dsl_scan_sync+0x59c/0x1480 [zfs]
[ 1440.266575]  spa_sync+0x5ce/0x1010 [zfs]
[ 1440.266860]  ? spa_txg_history_init_io+0x120/0x130 [zfs]
[ 1440.267150]  txg_sync_thread+0x21a/0x3e0 [zfs]
[ 1440.267434]  ? __pfx_txg_sync_thread+0x10/0x10 [zfs]
[ 1440.267706]  ? __pfx_thread_generic_wrapper+0x10/0x10 [spl]
[ 1440.267732]  thread_generic_wrapper+0x5f/0x70 [spl]
[ 1440.267754]  kthread+0xe9/0x110
[ 1440.267761]  ? __pfx_kthread+0x10/0x10
[ 1440.267768]  ret_from_fork+0x2c/0x50
[ 1440.267776]  </TASK>
[ 1572.072551] INFO: task zpool:69013 blocked for more than 120 seconds.
[ 1572.072568]       Tainted: P           OE      6.2.6-76060206-generic #202303130630~1689015125~22.04~ab2190e
[ 1572.072573] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1572.072576] task:zpool           state:D stack:0     pid:69013 ppid:69012  flags:0x00004002
[ 1572.072586] Call Trace:
[ 1572.072591]  <TASK>
[ 1572.072599]  __schedule+0x2aa/0x610
[ 1572.072614]  schedule+0x63/0x110
[ 1572.072619]  io_schedule+0x46/0x80
[ 1572.072628]  cv_wait_common+0xac/0x140 [spl]
[ 1572.072652]  ? __pfx_autoremove_wake_function+0x10/0x10
[ 1572.072663]  __cv_wait_io+0x18/0x30 [spl]
[ 1572.072688]  txg_wait_synced_impl+0xe1/0x130 [zfs]
[ 1572.072993]  txg_wait_synced+0x10/0x60 [zfs]
[ 1572.073271]  spa_config_update+0x17e/0x1a0 [zfs]
[ 1572.073560]  spa_import+0x5bd/0x6b0 [zfs]
[ 1572.073839]  zfs_ioc_pool_import+0x163/0x180 [zfs]
[ 1572.074130]  zfsdev_ioctl_common+0x8fd/0xa50 [zfs]
[ 1572.074405]  ? __kmalloc_large_node+0xbb/0x160
[ 1572.074413]  ? check_heap_object+0x5d/0x1b0
[ 1572.074421]  ? __check_object_size.part.0+0x72/0x150
[ 1572.074428]  zfsdev_ioctl+0x57/0xf0 [zfs]
[ 1572.074695]  __x64_sys_ioctl+0xa0/0xe0
[ 1572.074702]  do_syscall_64+0x5b/0x90
[ 1572.074707]  ? exc_page_fault+0x91/0x1b0
[ 1572.074714]  entry_SYSCALL_64_after_hwframe+0x72/0xdc
[ 1572.074721] RIP: 0033:0x7f46c091aaff
[ 1572.074733] RSP: 002b:00007ffc11a56510 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1572.074738] RAX: ffffffffffffffda RBX: 000055c7111a8c60 RCX: 00007f46c091aaff
[ 1572.074741] RDX: 00007ffc11a56ee0 RSI: 0000000000005a02 RDI: 0000000000000003
[ 1572.074744] RBP: 00007ffc11a5a4d0 R08: 0000000000000000 R09: 000055c7111b25b0
[ 1572.074747] R10: 0000000000000079 R11: 0000000000000246 R12: 000055c711183630
[ 1572.074749] R13: 00007ffc11a56ee0 R14: 000055c7111a5d60 R15: 0000000000000000
[ 1572.074755]  </TASK>
[ 1572.074765] INFO: task txg_sync:72595 blocked for more than 120 seconds.
[ 1572.074770]       Tainted: P           OE      6.2.6-76060206-generic #202303130630~1689015125~22.04~ab2190e
[ 1572.074773] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1572.074776] task:txg_sync        state:D stack:0     pid:72595 ppid:2      flags:0x00004000
[ 1572.074782] Call Trace:
[ 1572.074783]  <TASK>
[ 1572.074786]  __schedule+0x2aa/0x610
[ 1572.074794]  schedule+0x63/0x110
[ 1572.074799]  spl_panic+0x112/0x120 [spl]
[ 1572.074830]  metaslab_free_concrete+0x287/0x290 [zfs]
[ 1572.075109]  ? dmu_buf_will_dirty_impl+0x142/0x190 [zfs]
[ 1572.075336]  metaslab_free_impl+0xc1/0x110 [zfs]
[ 1572.075599]  metaslab_free_dva+0x61/0x90 [zfs]
[ 1572.075859]  metaslab_free+0x117/0x1d0 [zfs]
[ 1572.076120]  zio_free_sync+0xfb/0x120 [zfs]
[ 1572.076430]  dsl_scan_free_block_cb+0x6e/0x1f0 [zfs]
[ 1572.076700]  bpobj_dsl_scan_free_block_cb+0x11/0x20 [zfs]
[ 1572.076953]  bpobj_iterate_blkptrs+0x13c/0x3e0 [zfs]
[ 1572.077173]  ? __pfx_bpobj_dsl_scan_free_block_cb+0x10/0x10 [zfs]
[ 1572.077423]  bpobj_iterate_impl+0x261/0x4e0 [zfs]
[ 1572.077641]  ? __pfx_bpobj_dsl_scan_free_block_cb+0x10/0x10 [zfs]
[ 1572.077891]  bpobj_iterate+0x17/0x30 [zfs]
[ 1572.078109]  dsl_scan_sync+0x59c/0x1480 [zfs]
[ 1572.078363]  spa_sync+0x5ce/0x1010 [zfs]
[ 1572.078647]  ? spa_txg_history_init_io+0x120/0x130 [zfs]
[ 1572.078938]  txg_sync_thread+0x21a/0x3e0 [zfs]
[ 1572.079221]  ? __pfx_txg_sync_thread+0x10/0x10 [zfs]
[ 1572.079493]  ? __pfx_thread_generic_wrapper+0x10/0x10 [spl]
[ 1572.079519]  thread_generic_wrapper+0x5f/0x70 [spl]
[ 1572.079541]  kthread+0xe9/0x110
[ 1572.079548]  ? __pfx_kthread+0x10/0x10
[ 1572.079554]  ret_from_fork+0x2c/0x50
[ 1572.079563]  </TASK>

[rincebrain]

My immediate guess, quickly and blindly, would be that you took disks out of or put disks into enclosures that lie about the disk's physical size, leading to it screaming. I could be wrong, because this seems like it should be the on-disk representation, not the disk's reported one, but that'd be my quick guess other than "some metadata got very unhappy."

That assertion, if I understand it right, is intended to be a safeguard against trying to free something that's not an allocation size the vdev should have allowed - that is, if your vdev (and disks) were configured with ashift 12 (4096B sector size), and you tried only freeing 512B, that would be very incorrect, because you shouldn't have been able to make that allocation in the first place.

Which is why I'm guessing you changed how the disks were connected, to/from something that lies about their minimum allocation size.

[lukashass]

I did in fact change the disks connection. I moved them from SATA into USB3 enclosures.

This was only after the exact same error occurred while connected via SATA, though. My thinking was to try and import the disks with another Kernel, but apparently that didn't help.

I presume the solution to "some metadata got very unhappy" would be to destroy the pool and recreate it from a backup? 🙈

[rincebrain]

That would work, but I'm really curious what happened here, as I can't find any historical examples of someone tripping this assert, at all.

[lukashass]

Do you have any hint on what I could check to get further insights?

[rincebrain]

I'm genuinely unsure how you can get more information out of how this could happen at this point, let me think about it.

The obvious answer would be to see what the allocation is that it's upset about, and the pool layout and history, and try to guess from there.

[ItsANoBrainer]

I am also getting this exact same message. My Proxmox machine was having hardware issues that caused irregular system crashes. Eventually my machine would fail to finish booting and I got this message.

New to this ecosystem, I did a backup of my boot drive and reinstalled Proxmox. After attempting to import the pool, I got the same message again.

Is there any advice to troubleshoot this further or get everything working again? I appreciate it.

   pool: Local-Proxmox
     id: 4720398549667281341
  state: ONLINE
status: The pool was last accessed by another system.
 action: The pool can be imported using its name or numeric identifier and
        the '-f' flag.
   see: https://openzfs.github.io/openzfs-docs/msg/ZFS-8000-EY
 config:

        Local-Proxmox                    ONLINE
          mirror-0                       ONLINE
            ata-SATA_SSD_23020210240582  ONLINE
            ata-SATA_SSD_23020210240566  ONLINE