Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

BUG via zil_replay_log_record & zfs_replay_remove #527

Closed
rlaager opened this issue Jan 11, 2012 · 5 comments
Closed

BUG via zil_replay_log_record & zfs_replay_remove #527

rlaager opened this issue Jan 11, 2012 · 5 comments
Milestone

Comments

@rlaager
Copy link
Member

rlaager commented Jan 11, 2012

[ 152.451302] BUG: unable to handle kernel NULL pointer dereference at (null)
[ 152.451308] IP: [] mutex_lock+0x20/0x50
[ 152.451344] PGD 3d427067 PUD 3d426067 PMD 0
[ 152.451348] Oops: 0002 [#1] SMP
[ 152.451354] CPU 0
[ 152.451355] Modules linked in: parport_pc ppdev dm_crypt lp parport rfcomm bnep bluetooth zfs(P) zcommon(P) znvpair(P) zavl(P) zunicode(P) spl snd_intel8x0 snd_ac97_codec ac97_bus snd_pcm snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq psmouse virtio_balloon serio_raw snd_timer snd_seq_device snd soundcore snd_page_alloc i2c_piix4 binfmt_misc squashfs overlayfs nls_utf8 isofs dm_raid45 xor dm_mirror dm_region_hash dm_log btrfs zlib_deflate libcrc32c virtio_blk 8139too sym53c8xx 8139cp scsi_transport_spi virtio_pci virtio_ring virtio floppy
[ 152.451382]
[ 152.451388] Pid: 6971, comm: mount.zfs Tainted: P 3.0.0-12-generic #20-Ubuntu Bochs Bochs
[ 152.451391] RIP: 0010:[] [] mutex_lock+0x20/0x50
[ 152.451395] RSP: 0018:ffff88003f709838 EFLAGS: 00010246
[ 152.451397] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000010
[ 152.451398] RDX: ffff88003f709fd8 RSI: 0000000000000000 RDI: 0000000000000000
[ 152.451400] RBP: ffff88003f709848 R08: 0000000000000000 R09: e018000000000000
[ 152.451402] R10: ffff88003f709860 R11: 000000000000000c R12: ffff88003d803b50
[ 152.451403] R13: ffff88003d04e000 R14: ffff88003d803b50 R15: ffff88003d803760
[ 152.451407] FS: 00007fe7e1676b80(0000) GS:ffff88007f000000(0000) knlGS:0000000000000000
[ 152.451409] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 152.451410] CR2: 0000000000000000 CR3: 000000003d417000 CR4: 00000000000006f0
[ 152.451416] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 152.451421] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 152.451423] Process mount.zfs (pid: 6971, threadinfo ffff88003f708000, task ffff88003d87c560)
[ 152.451425] Stack:
[ 152.451426] 0000000000000000 ffff88003d803b50 ffff88003f709898 ffffffffa0323d81
This is with 0.6.0.34-0ubuntu1~oneiric1 from the PPA:

[ 152.451429] ffff88003fab4190 ffff88003f7098b0 0000000000000000 ffffffff00000010
[ 152.451432] ffffc900020a9a60 ffff88003d8038f8 ffff88003d04e000 ffff88003d803b50
[ 152.451434] Call Trace:
[ 152.451569] [] sa_lookup+0x31/0x60 [zfs]
[ 152.451604] [] zfs_inode_update+0x40/0x180 [zfs]
[ 152.451625] [] zfs_rmdir+0x51e/0x760 [zfs]
[ 152.451646] [] zfs_replay_remove+0xc9/0xd0 [zfs]
[ 152.451665] [] zil_replay_log_record+0xf3/0x1f0 [zfs]
[ 152.451685] [] zil_parse+0x416/0x850 [zfs]
[ 152.451706] [] ? perf_event_task_sched_out+0x2e/0xa0
[ 152.451726] [] ? zil_aitx_compare+0x20/0x20 [zfs]
[ 152.451746] [] ? zil_replay_error.isra.5+0xc0/0xc0 [zfs]
[ 152.451766] [] zil_replay+0xb1/0x100 [zfs]
[ 152.451787] [] zfs_sb_setup+0x130/0x140 [zfs]
[ 152.451806] [] zfs_domount+0x233/0x280 [zfs]
[ 152.451821] [] ? sget+0x1b4/0x230
[ 152.451823] [] ? unlock_super+0x30/0x30
[ 152.451936] [] ? zpl_mount+0x30/0x30 [zfs]
[ 152.451956] [] zpl_fill_super+0xe/0x20 [zfs]
[ 152.451958] [] mount_nodev+0x5d/0xc0
[ 152.451977] [] zpl_mount+0x25/0x30 [zfs]
[ 152.451979] [] mount_fs+0x43/0x1b0
[ 152.451993] [] vfs_kern_mount+0x6a/0xc0
[ 152.451996] [] do_kern_mount+0x54/0x110
[ 152.451999] [] do_mount+0x1a4/0x260
[ 152.452001] [] sys_mount+0x90/0xe0
[ 152.452016] [] system_call_fastpath+0x16/0x1b
[ 152.452017] Code: 66 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 48 83 ec 10 48 89 5d f0 4c 89 65 f8 66 66 66 66 90 48 89 fb e8 83 f5 ff ff 48 89 df <3e> ff 0f 79 05 e8 16 03 00 00 65 48 8b 04 25 80 cd 00 00 4c 8b
[ 152.452038] RIP [] mutex_lock+0x20/0x50
[ 152.452041] RSP
[ 152.452042] CR2: 0000000000000000
[ 152.452074] ---[ end trace 4f6c2b5ca5cbb66c ]---

@behlendorf
Copy link
Contributor

Thanks for posting this, clearly we've got a bug in the rmdir case of zil_replay(). For now you could avoid the issue by briefly setting 'zil_replay_disable=1'. You'll discard the zil an lose the last few changes before your pool crashed but you should be able to mount the fs.

@maxximino
Copy link
Contributor

I'm also getting this problem.
Running on 3.1.10 with ff998d8 .

Never met it with 3.1.6 with behlendorf@a576bc0.

Running a debug version hits 2 assertions:
[ 121.786429] SPLError: 3172:0:(spl-err.c:67:vcmn_err()) WARNING: ZFS replay transaction error 5, dataset mypool/rootfs, seq 0x210, txtype 9
[ 121.786430]
[ 121.786625] SPLError: 3172:0:(zil.c:361:zil_parse()) ASSERTION(!claimed || !(zh->zh_flags & ZIL_CLAIM_LR_SEQ_VALID) || (max_blk_seq == claim_blk_seq && max_lr_seq == claim_lr_seq)) failed
[ 121.786799] SPLError: 3172:0:(zil.c:361:zil_parse()) SPL PANIC
[ 121.786878] SPL: Showing stack for process 3172
[ 121.786956] Pid: 3172, comm: mount.zfs Tainted: P 3.1.10 #1
[ 121.786957] Call Trace:
[ 121.786967] [] spl_debug_dumpstack+0x27/0x50 [spl]
[ 121.786971] [] spl_debug_bug+0x7c/0xe0 [spl]
[ 121.787006] [] zil_parse+0x7c7/0x7d0 [zfs]
[ 121.787025] [] ? zil_aitx_compare+0x20/0x20 [zfs]
[ 121.787044] [] ? zil_replay_error.clone.3+0xa0/0xa0 [zfs]
[ 121.787065] [] zil_replay+0xbb/0x160 [zfs]
[ 121.787084] [] zfs_sb_setup+0x138/0x150 [zfs]
[ 121.787104] [] zfs_domount+0x20e/0x240 [zfs]
[ 121.787123] [] ? zpl_mount+0x30/0x30 [zfs]
[ 121.787143] [] zpl_fill_super+0x13/0x80 [zfs]
[ 121.787161] [] ? zpl_mount+0x30/0x30 [zfs]
[ 121.787165] [] mount_nodev+0x58/0xb0
[ 121.787167] [] ? alloc_pages_current+0xa1/0x100
[ 121.787186] [] zpl_mount+0x25/0x30 [zfs]
[ 121.787188] [] mount_fs+0x47/0x1c0
[ 121.787190] [] vfs_kern_mount+0x55/0xb0
[ 121.787192] [] do_kern_mount+0x54/0x100
[ 121.787194] [] do_mount+0x502/0x7e0
[ 121.787196] [] ? __get_free_pages+0xe/0x40
[ 121.787198] [] sys_mount+0x90/0xe0
[ 121.787200] [] system_call_fastpath+0x16/0x1b
[ 121.787237] SPL: Dumping log to /tmp/spl-log.1327185971.3172
[ 126.700154] SPLError: 3149:0:(zil.c:1551:zil_sync()) ASSERTION(zh->zh_replay_seq < *replayed_seq) failed
[ 126.700274] SPLError: 3149:0:(zil.c:1551:zil_sync()) SPL PANIC
[ 126.700352] SPL: Showing stack for process 3149
[ 126.700429] Pid: 3149, comm: txg_sync Tainted: P 3.1.10 #1
[ 126.700507] Call Trace:
[ 126.700591] [] spl_debug_dumpstack+0x27/0x50 [spl]
[ 126.700672] [] spl_debug_bug+0x7c/0xe0 [spl]
[ 126.700776] [] zil_sync+0x443/0x450 [zfs]
[ 126.700874] [] ? zio_taskq_dispatch+0xc3/0x1b0 [zfs]
[ 126.700973] [] ? refcount_add+0x16/0x20 [zfs]
[ 126.701069] [] ? zio_nowait+0x1d2/0x380 [zfs]
[ 126.701162] [] dmu_objset_sync+0x254/0x5a0 [zfs]
[ 126.701255] [] ? findfunc+0x20/0x20 [zfs]
[ 126.701347] [] ? copies_changed_cb+0xe0/0xe0 [zfs]
[ 126.701427] [] ? mutex_lock+0x1e/0x50
[ 126.701521] [] dsl_dataset_sync+0x80/0x170 [zfs]
[ 126.701615] [] dsl_pool_sync+0x125/0x7d0 [zfs]
[ 126.701714] [] spa_sync+0x3ba/0xbe0 [zfs]
[ 126.701796] [] ? __wake_up_common+0x59/0x90
[ 126.701891] [] txg_sync_thread+0x2b8/0x4e0 [zfs]
[ 126.701971] [] ? sched_clock_cpu+0xa8/0x120
[ 126.702066] [] ? txg_do_callbacks+0x100/0x100 [zfs]
[ 126.702148] [] ? __thread_create+0x360/0x360 [spl]
[ 126.702230] [] thread_generic_wrapper+0x81/0xe0 [spl]
[ 126.702311] [] ? __thread_create+0x360/0x360 [spl]
[ 126.702393] [] ? __thread_create+0x360/0x360 [spl]
[ 126.702472] [] kthread+0x96/0xa0
[ 126.702550] [] kernel_thread_helper+0x4/0x10
[ 126.702628] [] ? kthread_worker_fn+0x190/0x190
[ 126.702706] [] ? gs_change+0xb/0xb
[ 126.702817] SPL: Dumping log to /tmp/spl-log.1327185976.3149

I have the /tmp/spl-log* files, if needed.

@nielsdec
Copy link

I also found a case of the transaction error in my log:

PLError: 8221:0:(spl-err.c:67:vcmn_err()) WARNING: ZFS replay transaction error 5, dataset data/misc, seq 0x1c, txtype 9

No oops, and the system had been idle before a clean reboot.
ubuntu 11.10, 0.6.0.54
A chmod done before the reboot was probably reverted to the old rights (not 100% sure).

I set the pool to readonly, and rebooted with 0.6.0.50 to make a backup of the pool, which worked fine. (No errors after the reboot). After that I set the pool back to read/write and booted back to 0.6.0.54, but the error didn't appear anymore. I'm using the following custom settings:

options zfs zfs_arc_max=0x200000000
options zfs zfs_arc_meta_limit=0x180000000
options zfs zfs_txg_synctime_ms=5000
options zfs zfs_txg_timeout=30
options zfs l2arc_write_max=0x10000000
options zfs l2arc_write_boost=0x10000000
options zfs l2arc_headroom=6
options zfs l2arc_feed_min_ms=50
options zfs l2arc_noprefetch=0
options zfs l2arc_norw=0

I'm not sure if my issue is related is the same as this one, the transaction error message is very similar, but the rest of the symptoms are not. A scrub is running now, no errors so far.

The version running before the reboot was 0.6.0.51, which was likely the version that caused the corrupted zil entry.
Does a readonly import clear the zil as well? That would explain why the issue didn't show up afterwards for me.

@behlendorf
Copy link
Contributor

While I'm not 100% sure of the root cause for this issue my best guess is that it was caused by a small regression which was accidentally introduced by commit 2c6d0b1. The patch was designed to minimize the odds of hitting a particular deadlock but accidentally introduces a case where a zio might not be properly reinitialized. This could lead to something like this.

This flaw exists for the Ubuntu 0.6.0.53 - 0.6.0-54 releases and was fixed in 0.6.0.55 and stable ppas. It has also been fixed in the master branch but was present in -rc7 release tag, so expect an -rc8 release fairly quickly. If you've seen this issue I'd suggest updating to one of these fixed versions.

If you encounter this issue you can most likely resolve it be disabling zil replay zil_replay_disable=1 during import and then scrubbing your pool. Alternately, if you import you pool read-only zil replay will not occur and you'll be able to access your data. By disabling zil replay you may loose the last few seconds of updates to your pool.

@behlendorf
Copy link
Contributor

I'm sure, this issue was caused by 2c6d0b1 and subsequently fixed by 49be0cc .

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants