[LU-3584] Failure on racer test_1: unable to handle kernel NULL pointer dereference at 0000000000000018

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.5.0
• Fix Version/s: Lustre 2.5.0
• Type: Bug
• Priority: Critical
• Reporter: Maloo
• Assignee: Nathaniel Clark
• Resolution: Fixed
• Labels: zfs

Environment

server and client: lustre-master build #1560 zfs

• Severity: 3

Description

This issue was created by maloo for sarah <[e-mail]>

This issue relates to the following test suite run: http://maloo.whamcloud.com/test_sets/73626350-ed40-11e2-99b4-52540035b04c.

The sub-test test_1 failed with the following error:

test failed to respond and timed out

MDS console shows:

07:36:06:Lustre: DEBUG MARKER: == racer test 1: racer on clients: client-22-ib,client-23-ib.lab.whamcloud.com DURATION=900 == 07:36:05 (1373812565)
07:36:06:Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400):0:mdt
07:36:07:BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
07:36:07:IP: [<ffffffffa04cdea6>] dmu_tx_hold_spill+0x26/0xa0 [zfs]
07:36:08:PGD 0 
07:36:08:Oops: 0000 [#1] SMP 
07:36:08:last sysfs file: /sys/devices/system/cpu/possible
07:36:08:CPU 1 
07:36:08:Modules linked in: osp(U) lod(U) mdt(U) mdd(U) lfsck(U) mgs(U) mgc(U) osd_zfs(U) lquota(U) lustre(U) lov(U) osc(U) mdc(U) fid(U) fld(U) ko2iblnd(U) ptlrpc(U) obdclass(U) lnet(U) lvfs(U) libcfs(U) jbd2 sha512_generic sha256_generic crc32c_intel zfs(P)(U) zcommon(P)(U) znvpair(P)(U) zavl(P)(U) zunicode(P)(U) spl(U) zlib_deflate nfs fscache nfsd lockd nfs_acl auth_rpcgss exportfs autofs4 sunrpc cpufreq_ondemand acpi_cpufreq freq_table mperf ib_ipoib rdma_ucm ib_ucm ib_uverbs ib_umad rdma_cm ib_cm iw_cm ib_addr ipv6 mlx4_ib ib_sa ib_mad ib_core mlx4_en mlx4_core igb ptp pps_core microcode serio_raw sg i2c_i801 i2c_core iTCO_wdt iTCO_vendor_support ioatdma dca i7core_edac edac_core shpchp ext3 jbd mbcache sd_mod crc_t10dif ahci dm_mirror dm_region_hash dm_log dm_mod [last unloaded: libcfs]
07:36:08:
07:36:08:Pid: 22820, comm: mdt00_008 Tainted: P           ---------------    2.6.32-358.11.1.el6_lustre.x86_64 #1 Supermicro X8DTT/X8DTT
07:36:08:RIP: 0010:[<ffffffffa04cdea6>]  [<ffffffffa04cdea6>] dmu_tx_hold_spill+0x26/0xa0 [zfs]
07:36:08:RSP: 0018:ffff880317e45a50  EFLAGS: 00010286
07:36:08:RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001
07:36:08:RDX: 0000000000000000 RSI: ffffffffa0558d10 RDI: ffff880321f3aa98
07:36:08:RBP: ffff880317e45a60 R08: ffff880317e45820 R09: 0000000000000000
07:36:08:R10: 000000000000000d R11: 0000000000000000 R12: ffff880323e091c0
07:36:08:R13: ffff880315822220 R14: 0000000000000000 R15: 0000000000000121
07:36:08:FS:  0000000000000000(0000) GS:ffff880032e20000(0000) knlGS:0000000000000000
07:36:08:CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
07:36:08:CR2: 0000000000000018 CR3: 0000000001a85000 CR4: 00000000000007e0
07:36:08:DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
07:36:08:DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
07:36:08:Process mdt00_008 (pid: 22820, threadinfo ffff880317e44000, task ffff88031396c040)
07:36:08:Stack:
07:36:08: ffff880317b186c0 ffff880323e091c0 ffff880317e45aa0 ffffffffa04ced2b
07:36:08:<d> 0000000000000001 ffff880318719b48 ffff880318733c00 ffff880322411c00
07:36:08:<d> ffff88031772e880 0000000000000000 ffff880317e45b10 ffffffffa161cd2d
07:36:08:Call Trace:
07:36:08: [<ffffffffa04ced2b>] dmu_tx_hold_sa+0x17b/0x190 [zfs]
07:36:08: [<ffffffffa161cd2d>] osd_declare_attr_set+0x22d/0x4a0 [osd_zfs]
07:36:08: [<ffffffffa04ce99d>] ? dmu_tx_hold_zap+0x8d/0x200 [zfs]
07:36:08: [<ffffffffa161cfd3>] osd_declare_object_ref_add+0x13/0x20 [osd_zfs]
07:36:08: [<ffffffffa17b3d5b>] lod_declare_ref_add+0x3b/0xd0 [lod]
07:36:08: [<ffffffffa16a4e6e>] mdd_link+0x1ee/0xaa0 [mdd]
07:36:08: [<ffffffffa0a94464>] ? lustre_msg_get_flags+0x34/0xb0 [ptlrpc]
07:36:08: [<ffffffffa16fd419>] mdt_reint_link+0x639/0x9e0 [mdt]
07:36:08: [<ffffffffa0a931ee>] ? lustre_pack_reply_flags+0xae/0x1f0 [ptlrpc]
07:36:08: [<ffffffffa16fb5b1>] mdt_reint_rec+0x41/0xe0 [mdt]
07:36:08: [<ffffffffa16e0c53>] mdt_reint_internal+0x4c3/0x780 [mdt]
07:36:08: [<ffffffffa16e0f54>] mdt_reint+0x44/0xe0 [mdt]
07:36:08: [<ffffffffa16e5b77>] mdt_handle_common+0x647/0x16d0 [mdt]
07:36:08: [<ffffffffa171edc5>] mds_regular_handle+0x15/0x20 [mdt]
07:36:08: [<ffffffffa0aa33a8>] ptlrpc_server_handle_request+0x398/0xc60 [ptlrpc]
07:36:08: [<ffffffffa05ba54e>] ? cfs_timer_arm+0xe/0x10 [libcfs]
07:36:08: [<ffffffffa05cba9f>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
07:36:08: [<ffffffffa0a9a7b9>] ? ptlrpc_wait_event+0xa9/0x290 [ptlrpc]
07:36:08: [<ffffffff81055ab3>] ? __wake_up+0x53/0x70
07:36:08: [<ffffffffa0aa472d>] ptlrpc_main+0xabd/0x1700 [ptlrpc]
07:36:08: [<ffffffffa0aa3c70>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
07:36:08: [<ffffffff81096936>] kthread+0x96/0xa0
07:36:08: [<ffffffff8100c0ca>] child_rip+0xa/0x20
07:36:09: [<ffffffff810968a0>] ? kthread+0x0/0xa0
07:36:09: [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
07:36:09:Code: 00 00 00 00 00 55 48 89 e5 41 54 53 0f 1f 44 00 00 45 31 c9 45 31 c0 b9 06 00 00 00 48 89 f2 48 8b 77 20 e8 7d fe ff ff 48 89 c3 <48> 8b 40 18 48 85 c0 74 14 4c 8b 60 58 41 f6 44 24 07 04 75 15 
07:36:09:RIP  [<ffffffffa04cdea6>] dmu_tx_hold_spill+0x26/0xa0 [zfs]
07:36:09: RSP <ffff880317e45a50>
07:36:09:CR2: 0000000000000018
07:36:09:Initializing cgroup subsys cpuset

Issue Links

• is blocking: LU-3678 Update zfs build version to 0.6.2

Comments

[Jodi Levi (Inactive)]

Nathaniel,
Could you comment on this one?
Thank you!

[Nathaniel Clark]

The OOPS appears to be a bug upstream in ZFS, I'll push a patch up, but the osd-zfs code could also do better job error checking, I'll build a patch for that. Beyond fixing the oops, there may be another bug, but I'm not sure where to look till the oops is fixed.

[Nathaniel Clark]

Lustre error handling:
http://review.whamcloud.com/7090

Fix upstream:
https://github.com/zfsonlinux/zfs/pull/1606

[Nathaniel Clark]

Updated upstream patch:
https://github.com/zfsonlinux/zfs/pull/1610

[Brian Behlendorf]

While it's true the NULL dereference was caused by ZFS I believe the root cause resides in the Lustre ZFS OSD code. In this instance the only legitimate way for dmu_tx_hold_object_impl() to return a NULL value is if the OSD passed it an object which was either invalid or not currently allocated. Lustre is calling the API improperly. I'd prefer to avoid papering over this ZFS code and fix Lustre not to pass down an invalid SA handle.

[Nathaniel Clark]

I believe, the root cause of this issue involves mdd_link() calling osd_declare_object_ref_add() (from mdd_declare_link()) which calls osd_declare_attr_set() without calling osd_declare_object_create() before hand.

In ldiskfs, osd_declare_object_ref_add just increments a counter, but in zfs, it calls down into zfs via osd_declare_attr_set.

I'm not sure yet, if the issue is the failure to call declare_object_create or if object_ref_add/del shouldn't call osd_declare_attr_set.

[Peter Jones]

Landed for 2.5.0