PANIC at dmu.c:1135:dmu_write()

[adamdmoss]

System information

Type	Version/Name
Kernel Version	5.15.0-57-lowlatency #63-Ubuntu SMP PREEMPT
Architecture	x86_64
OpenZFS Version	git master @ d27c7ba

Describe the problem you're observing

Got a panic (failed assertion) during day-to-day use. Hadn't seen it before. Hasn't come back since.

Describe how to reproduce the problem

No clear repro.

Include any warning/errors/backtraces from the system logs

[43737.253268] zio pool=backups-on-6tbusb vdev=/dev/sdc1 error=5 type=1 offset=2598766071808 size=36864 
flags=1575040
[43737.254146] VERIFY0(0 == dmu_buf_hold_array(os, object, offset, size, FALSE, FTAG, &numbufs, &dbp)) failed (0 == 5)
[43737.254151] PANIC at dmu.c:1135:dmu_write()
[43737.254153] Showing stack for process 4098
[43737.254155] CPU: 5 PID: 4098 Comm: txg_sync Tainted: P           OE     5.15.0-57-lowlatency #63-Ubuntu
[43737.254158] Hardware name: Gigabyte Technology Co., Ltd. Z68MA-D2H-B3/Z68MA-D2H-B3, BIOS F10 02/23/2012
[43737.254160] Call Trace:
[43737.254163]  <TASK>
[43737.254167]  show_stack+0x52/0x5c
[43737.254174]  dump_stack_lvl+0x4a/0x63
[43737.254182]  dump_stack+0x10/0x16
[43737.254186]  spl_dumpstack+0x29/0x2f [spl]
[43737.254201]  spl_panic+0xd1/0xe9 [spl]
[43737.254212]  ? spl_kmem_free+0x2e/0x40 [spl]
[43737.254221]  ? dmu_buf_hold_array_by_dnode+0x398/0x5f0 [zfs]
[43737.254407]  ? dnode_rele_and_unlock+0x68/0x100 [zfs]
[43737.254540]  dmu_write.part.0+0x12a/0x140 [zfs]
[43737.254667]  dmu_write+0x18/0x20 [zfs]
[43737.254791]  spa_history_write+0x191/0x1d0 [zfs]
[43737.254926]  spa_history_log_sync+0x18d/0x7d0 [zfs]
[43737.255054]  log_internal+0xff/0x130 [zfs]
[43737.255180]  spa_history_log_internal_ds+0xc3/0x100 [zfs]
[43737.255312]  ? dbuf_rele_and_unlock+0x1ba/0x5e0 [zfs]
[43737.255431]  ? dmu_buf_rele+0x3d/0x50 [zfs]
[43737.255541]  ? zap_update+0x166/0x270 [zfs]
[43737.255663]  ? dnode_rele+0x3d/0x50 [zfs]
[43737.255790]  ? dsl_dir_snap_cmtime_update+0xb1/0x160 [zfs]
[43737.255896]  dsl_dataset_snapshot_sync_impl+0x859/0xb90 [zfs]
[43737.256011]  ? dsl_dir_rele+0x30/0x40 [zfs]
[43737.256142]  dsl_dataset_snapshot_sync+0x11d/0x1d0 [zfs]
[43737.256271]  ? spl_kmem_cache_free+0x11a/0x200 [spl]
[43737.256284]  ? kmem_cache_free+0x263/0x2b0
[43737.256290]  ? metaslab_class_get_dspace+0x16/0x30 [zfs]
[43737.256423]  ? spa_get_slop_space+0x61/0xf0 [zfs]
[43737.256556]  ? dsl_pool_adjustedsize+0x42/0x90 [zfs]
[43737.256687]  dsl_sync_task_sync+0xb7/0x110 [zfs]
[43737.256820]  dsl_pool_sync+0x3d5/0x4f0 [zfs]
[43737.256949]  spa_sync+0x554/0xff0 [zfs]
[43737.257084]  ? spa_txg_history_init_io+0x10a/0x120 [zfs]
[43737.257218]  txg_sync_thread+0x218/0x3a0 [zfs]
[43737.257353]  ? txg_register_callbacks+0xb0/0xb0 [zfs]
[43737.257482]  thread_generic_wrapper+0x61/0x80 [spl]
[43737.257497]  ? spl_taskq_fini+0x80/0x80 [spl]
[43737.257506]  kthread+0x138/0x160
[43737.257511]  ? set_kthread_struct+0x50/0x50
[43737.257515]  ret_from_fork+0x1f/0x30
[43737.257521]  </TASK>

[adamdmoss]

Unless it's a coincidence / red herring:

[43737.253268] zio pool=backups-on-6tbusb vdev=/dev/sdc1 error=5 type=1 offset=2598766071808 size=36864 flags=1575040
[43737.254146] VERIFY0(0 == dmu_buf_hold_array(os, object, offset, size, FALSE, FTAG, &numbufs, &dbp)) failed (0 == 5)

... an error=5 (actual hw error?) is seen at the zio level and this gets passed as-is all the way up to the caller of dmu_buf_hold_array()...? If that handwaving guess is accurate then I'm hoping something more elegant can be done than PANICing the kernel - guess it's far too late to let the userspace probably-async writer know though. :)

[adamdmoss]

The only thing I can see which is close to having touched this path recently is #14243 and even that shouldn't have really affected the write case so I think that's just coincidence.

[adamdmoss]

Guess I'd appreciate @amotin at least having a glance though - thanks!

[stale]

This issue has been automatically marked as "stale" because it has not had any activity for a while. It will be closed in 90 days if no further activity occurs. Thank you for your contributions.

[amotin]

From one side it is obviously wrong that dmu_write() is unable to return errors, but asserts them instead. It should be fixed, but may need refactoring to a number of code paths to handle those errors.

From the other side, dmu_tx_hold_write(), that should be called by anybody doing writes, should check that all required data are readable before assigning transaction, so the error should not happen at that point. But I suppose spa_history_write() is called in sync context does not call it, since it is called in sync context, being passed already assigned TXG, so it bypasses this safety measure.