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

System Bug with call to arc_buf_remove_ref #4069

Closed
willthelaw opened this issue Dec 7, 2015 · 8 comments
Closed

System Bug with call to arc_buf_remove_ref #4069

willthelaw opened this issue Dec 7, 2015 · 8 comments

Comments

@willthelaw
Copy link

Hi,

We have a system running zfs on linux that has gone down twice since friday with a call to arc_buf_remove_ref. First time we were running ZoL .0.6.4.2 with CentOS5 kernel 2.6.32-504.30.3.el6.x86_64. I updated the system yesterday to ZoL 0.6.5.3, and it happened again today with this on the console:

First time:
svc: 172.26.6.67, port=47745: unknown version (-1 for prog 100003, nfsd)^M
BUG: unable to handle kernel NULL pointer dereference at (null)^M
IP: [] arc_buf_remove_ref+0x20/0x170 [zfs]^M
PGD 1aa575c067 PUD 152aabc067 PMD 0 ^M
Oops: 0000 [#1] SMP ^M
last sysfs file: /sys/devices/pci0000:40/0000:40:02.0/0000:42:00.0/host10/port-10:1/expander-10:6/port-10:6:1/expander-10:7/port-10:7:3/end_device-10:7:3/target10:0:65/10:0:65:0/state^M
CPU 15 ^M
Modules linked in: nf_conntrack_ipv4 nf_defrag_ipv4 iptable_filter ip_tables nfsd lockd nfs_acl auth_rpcgss sunrpc exportfs vfat fat usb_storage mpt3sas dell_rbu mptctl mptbase ipt_REJECT ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables dm_round_robin dm_multipath zfs(P)(U) zcommon(P)(U) znvpair(P)(U) spl(U) zlib_deflate zavl(P)(U) zunicode(P)(U) ipmi_devintf sg ses enclosure power_meter acpi_ipmi ipmi_si ipmi_msghandler mlx4_ib ib_sa ib_mad ib_core ib_addr ipv6 mlx4_en mlx4_core iTCO_wdt iTCO_vendor_support ixgbe mdio mpt2sas(U) scsi_transport_sas raid_class igb dca i2c_algo_bit i2c_core ptp pps_core dcdbas sb_edac edac_core lpc_ich mfd_core shpchp ext4 jbd2 mbcache sd_mod crc_t10dif ahci wmi megaraid_sas dm_mirror dm_region_hash dm_log dm_mod [last unloaded: nf_defrag_ipv4]^M
^M
Pid: 29523, comm: zfs Tainted: P --------------- 2.6.32-504.30.3.el6.x86_64 #1 Dell Inc. PowerEdge R720/0020HJ^M
RIP: 0010:[] [] arc_buf_remove_ref+0x20/0x170 [zfs]^M
RSP: 0018:ffff883b91169378 EFLAGS: 00010296^M
RAX: 0000000000000000 RBX: ffff883b911694f8 RCX: 0000000000000000^M
RDX: ffffffffffffffff RSI: ffff883b911694f8 RDI: 0000000000000000^M
RBP: ffff883b911693b8 R08: 0000000000000000 R09: 0000000000000034^M
R10: 0000000000000000 R11: 0000000000000080 R12: 0000000000000000^M
R13: 0000000000000000 R14: 0000008000000000 R15: 0000000002000000^M
FS: 00007fabe6377740(0000) GS:ffff8820f0ce0000(0000) knlGS:0000000000000000^M
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b^M
CR2: 0000000000000000 CR3: 000000182cc01000 CR4: 00000000000407e0^M
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000^M
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400^M
Process zfs (pid: 29523, threadinfo ffff883b91168000, task ffff8840520e9520)^M
Stack:^M
ffff883b911693d8 ffffffffa04a8ac1 0000000000000000 ffff883b911694f8^M
ffff883a775b6380 0000000000000000 0000008000000000 0000000002000000^M
ffff883b911693d8 ffffffffa03f737b ffff883b00000001 ffff882fb7fea090^M
Call Trace:^M
[] ? zio_null+0x61/0x70 [zfs]^M
[] arc_getbuf_func+0x3b/0x80 [zfs]^M
[] arc_read+0x3c1/0xa70 [zfs]^M
[] ? spl_kmem_cache_alloc+0x6b/0x8c0 [spl]^M
[] ? buf_cons+0x50/0x60 [zfs]^M
[] ? arc_getbuf_func+0x0/0x80 [zfs]^M
[] backup_cb+0x53d/0x760 [zfs]^M
[] traverse_visitbp+0x476/0x7b0 [zfs]^M
[] ? arc_read+0x3e1/0xa70 [zfs]^M
[] ? backup_cb+0x2da/0x760 [zfs]^M
[] traverse_dnode+0xbe/0xd0 [zfs]^M
[] traverse_visitbp+0x6f7/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_dnode+0x71/0xd0 [zfs]^M
[] traverse_visitbp+0x551/0x7b0 [zfs]^M
[] ? traverse_prefetch_thread+0x0/0x170 [zfs]^M
[] traverse_impl+0x184/0x400 [zfs]^M
[] ? dump_bytes_strategy+0x0/0x100 [zfs]^M
[] traverse_dataset+0x56/0x60 [zfs]^M
[] ? backup_cb+0x0/0x760 [zfs]^M
[] dmu_send_impl+0x36b/0x4f0 [zfs]^M
[] dmu_send_obj+0x157/0x210 [zfs]^M
[] zfs_ioc_send+0xa7/0x280 [zfs]^M
[] zfsdev_ioctl+0x495/0x4d0 [zfs]^M
[] vfs_ioctl+0x22/0xa0^M
[] do_vfs_ioctl+0x84/0x580^M
[] ? do_brk+0x26c/0x350^M
[] sys_ioctl+0x81/0xa0^M
[] system_call_fastpath+0x16/0x1b^M
Code: 66 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 57 41 56 41 55 41 54 53 48 83 ec 18 0f 1f 44 00 00 48 c7 c2 ff ff ff ff 49 89 fc <48> 8b 3f 4c 8b 47 10 4c 8b 4f 30 48 8d 5f 10 48 89 f8 66 0f 1f ^M
RIP [] arc_buf_remove_ref+0x20/0x170 [zfs]^M
RSP ^M
CR2: 0000000000000000^M

Second run was:
BUG: unable to handle kernel NULL pointer dereference at (null)^M
IP: [] arc_buf_remove_ref+0x20/0x170 [zfs]^M
PGD 1aa575c067 PUD 152aabc067 PMD 0 ^M
Oops: 0000 [#1] SMP ^M
last sysfs file: /sys/devices/pci0000:40/0000:40:02.0/0000:42:00.0/host10/port-10:1/expander-10:6/port-10:6:1/expander-10:7/port-10:7:3/end_device-10:7:3/target10:0:65/10:0:65:0/state^M
CPU 15 ^M
Modules linked in: nf_conntrack_ipv4 nf_defrag_ipv4 iptable_filter ip_tables nfsd lockd nfs_acl auth_rpcgss sunrpc exportfs vfat fat usb_storage mpt3sas dell_rbu mptctl mptbase ipt_REJECT ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables dm_round_robin dm_multipath zfs(P)(U) zcommon(P)(U) znvpair(P)(U) spl(U) zlib_deflate zavl(P)(U) zunicode(P)(U) ipmi_devintf sg ses enclosure power_meter acpi_ipmi ipmi_si ipmi_msghandler mlx4_ib ib_sa ib_mad ib_core ib_addr ipv6 mlx4_en mlx4_core iTCO_wdt iTCO_vendor_support ixgbe mdio mpt2sas(U) scsi_transport_sas raid_class igb dca i2c_algo_bit i2c_core ptp pps_core dcdbas sb_edac edac_core lpc_ich mfd_core shpchp ext4 jbd2 mbcache sd_mod crc_t10dif ahci wmi megaraid_sas dm_mirror dm_region_hash dm_log dm_mod [last unloaded: nf_defrag_ipv4]^M
^M
Pid: 29523, comm: zfs Tainted: P --------------- 2.6.32-504.30.3.el6.x86_64 #1 Dell Inc. PowerEdge R720/0020HJ^M
RIP: 0010:[] [] arc_buf_remove_ref+0x20/0x170 [zfs]^M
RSP: 0018:ffff883b91169378 EFLAGS: 00010296^M
RAX: 0000000000000000 RBX: ffff883b911694f8 RCX: 0000000000000000^M
RDX: ffffffffffffffff RSI: ffff883b911694f8 RDI: 0000000000000000^M
RBP: ffff883b911693b8 R08: 0000000000000000 R09: 0000000000000034^M
R10: 0000000000000000 R11: 0000000000000080 R12: 0000000000000000^M
R13: 0000000000000000 R14: 0000008000000000 R15: 0000000002000000^M
FS: 00007fabe6377740(0000) GS:ffff8820f0ce0000(0000) knlGS:0000000000000000^M
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b^M
CR2: 0000000000000000 CR3: 000000182cc01000 CR4: 00000000000407e0^M
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000^M
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400^M
Process zfs (pid: 29523, threadinfo ffff883b91168000, task ffff8840520e9520)^M
Stack:^M
ffff883b911693d8 ffffffffa04a8ac1 0000000000000000 ffff883b911694f8^M
ffff883a775b6380 0000000000000000 0000008000000000 0000000002000000^M
ffff883b911693d8 ffffffffa03f737b ffff883b00000001 ffff882fb7fea090^M
Call Trace:^M
[] ? zio_null+0x61/0x70 [zfs]^M
[] arc_getbuf_func+0x3b/0x80 [zfs]^M
[] arc_read+0x3c1/0xa70 [zfs]^M
[] ? spl_kmem_cache_alloc+0x6b/0x8c0 [spl]^M
[] ? buf_cons+0x50/0x60 [zfs]^M
[] ? arc_getbuf_func+0x0/0x80 [zfs]^M
[] backup_cb+0x53d/0x760 [zfs]^M
[] traverse_visitbp+0x476/0x7b0 [zfs]^M
[] ? arc_read+0x3e1/0xa70 [zfs]^M
[] ? backup_cb+0x2da/0x760 [zfs]^M
[] traverse_dnode+0xbe/0xd0 [zfs]^M
[] traverse_visitbp+0x6f7/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_visitbp+0x3eb/0x7b0 [zfs]^M
[] traverse_dnode+0x71/0xd0 [zfs]^M
[] traverse_visitbp+0x551/0x7b0 [zfs]^M
[] ? traverse_prefetch_thread+0x0/0x170 [zfs]^M
[] traverse_impl+0x184/0x400 [zfs]^M
[] ? dump_bytes_strategy+0x0/0x100 [zfs]^M
[] traverse_dataset+0x56/0x60 [zfs]^M
[] ? backup_cb+0x0/0x760 [zfs]^M
[] dmu_send_impl+0x36b/0x4f0 [zfs]^M
[] dmu_send_obj+0x157/0x210 [zfs]^M
[] zfs_ioc_send+0xa7/0x280 [zfs]^M
[] zfsdev_ioctl+0x495/0x4d0 [zfs]^M
[] vfs_ioctl+0x22/0xa0^M
[] do_vfs_ioctl+0x84/0x580^M
[] ? do_brk+0x26c/0x350^M
[] sys_ioctl+0x81/0xa0^M
[] system_call_fastpath+0x16/0x1b^M
Code: 66 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 57 41 56 41 55 41 54 53 48 83 ec 18 0f 1f 44 00 00 48 c7 c2 ff ff ff ff 49 89 fc <48> 8b 3f 4c 8b 47 10 4c 8b 4f 30 48 8d 5f 10 48 89 f8 66 0f 1f ^M
RIP [] arc_buf_remove_ref+0x20/0x170 [zfs]^M

We do have crash dumps enabled and I'm happy to provide that; the machine has 256 GB of RAM and was definitely not out of RAM. Arc_max was actually set to about 90gb.

After it happened today we decided to update to the latest CentOS6 kernel, 2.6.32-573.8.1.el6.x86_64. I guess any advice about suggested kernels would be helpful two.

It's hooked up to about 240 2TB SAS disks. Any ideas would be very helpful.

Will

@willthelaw
Copy link
Author

Just noticed that it is showed the same device both times, /sys/devices/pci0000:40/0000:40:02.0/0000:42:00.0/host10/port-10:1/expander-10:6/port-10:6:1/expander-10:7/port-10:7:3/end_device-10:7:3/target10:0:65/10:0:65:0/state. It's one of the L2ARC devices, so I went and disabled it and I'm running a long smartctl test on it. Does that seem reasonable or am I nuts?

Thanks!

Will

@willthelaw
Copy link
Author

OK, so.... The jury is still out on this. However, it is EXTREMELY likely that it actually was going down due to a daily zfs send. The bad part is the machine went down on both 0.6.4.2 and 0.6.5.3. A colleague did a bunch of work looking at the kernel dumps; I'll have him post that. Any ideas in helping verify/moving forward?

Current plan is to make a cloned dataset and rsync the data over to it; we did that when dealing with the SA matter bug.

Thanks,

Will

behlendorf added a commit to behlendorf/zfs that referenced this issue Dec 9, 2015
Commit 5f6d0b6 was originally added to gracefully handle block
pointers with a damaged logical size.  However, it incorrectly
assumed that all passed arc_done_func_t could handle a NULL
arc_buf_t.

Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Issue openzfs#4069
@behlendorf
Copy link
Contributor

@willthelaw this was definitely caused by a zfs send, you can tell because zfs_ioc_send() appears in the stack. As for the crash that's apparently the result of a NULL be passed in to arc_buf_remove_ref().

I've opened pull request #4080 with a patch which should prevent the panic. However, the reason this occurred at all was because you entered some error handling code designed to handle the case where a damaged block pointer is found. So while this should prevent the panic your zfs send will likely now fail with an EIO when it encounters the damaged block.

@willthelaw
Copy link
Author

Awesome, thank you! So I did take out the disk I thought it was and it is resilvering. Should that theoretically fix it, or is the logical block pointer bad? Or can it be fixed by destroying the snapshot? We could rsync the data off and apply it to an older snapshot, too.

Thank you again. I probably won't be able to apply it until Saturday.

@behlendorf
Copy link
Contributor

@willthelaw it's somehow incorrect on disk but has a good checksum. I wouldn't expect the scrub to detect it or replacing the disk to fix it. You'd need to remove all the snapshots that version of the file appears in to get rid of it.

@willthelaw
Copy link
Author

Darn. OK - we're in Palo Alto (at stanford) so we do owe you some beer.

@willthelaw
Copy link
Author

OK, that worked - thank you again. With the data set with the issue we now get EIO.

@behlendorf
Copy link
Contributor

@willthelaw OK, then it worked as expected. The next time I'm over in Palo Alto I'll take you up on the beer.

ryao pushed a commit to ryao/zfs that referenced this issue Jan 4, 2016
Commit 5f6d0b6 was originally added to gracefully handle block
pointers with a damaged logical size.  However, it incorrectly
assumed that all passed arc_done_func_t could handle a NULL
arc_buf_t.

Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes openzfs#4069
Closes openzfs#4080
goulvenriou pushed a commit to Alyseo/zfs that referenced this issue Jan 17, 2016
Commit 5f6d0b6 was originally added to gracefully handle block
pointers with a damaged logical size.  However, it incorrectly
assumed that all passed arc_done_func_t could handle a NULL
arc_buf_t.

Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes openzfs#4069
Closes openzfs#4080
goulvenriou pushed a commit to Alyseo/zfs that referenced this issue Feb 4, 2016
Commit 5f6d0b6 was originally added to gracefully handle block
pointers with a damaged logical size.  However, it incorrectly
assumed that all passed arc_done_func_t could handle a NULL
arc_buf_t.

Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes openzfs#4069
Closes openzfs#4080
tuxoko pushed a commit to tuxoko/zfs that referenced this issue Sep 8, 2016
Commit 5f6d0b6 was originally added to gracefully handle block
pointers with a damaged logical size.  However, it incorrectly
assumed that all passed arc_done_func_t could handle a NULL
arc_buf_t.

Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes openzfs#4069
Closes openzfs#4080
nedbass pushed a commit to nedbass/zfs that referenced this issue Sep 9, 2016
Commit 5f6d0b6 was originally added to gracefully handle block
pointers with a damaged logical size.  However, it incorrectly
assumed that all passed arc_done_func_t could handle a NULL
arc_buf_t.

Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes openzfs#4069
Closes openzfs#4080
nedbass pushed a commit to nedbass/zfs that referenced this issue Sep 9, 2016
Commit 5f6d0b6 was originally added to gracefully handle block
pointers with a damaged logical size.  However, it incorrectly
assumed that all passed arc_done_func_t could handle a NULL
arc_buf_t.

Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes openzfs#4069
Closes openzfs#4080
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

2 participants