[LU-7866] BUG: unable to handle kernel NULL pointer dereference at (null)

• Type: Bug
• Resolution: Unresolved
• Priority: Blocker
• Affects Version/s: Lustre 2.8.0
• Labels: patch soak
• Environment: lola; build: https://build.hpdd.intel.com/job/lustre-b2_8/12/
• Severity: 3
• Assignee: Hongchao Zhang
• Reporter: Frank Heckes (Inactive)

Description

Error occurred during soak testing of build '20160309' (b2_8 RC5) (see: https://wiki.hpdd.intel.com/display/Releases/Soak+Testing+on+Lola#SoakTestingonLola-20160309 also). DNE is enabled. MDTs had been formatted using ldiskfs, OSTs using zfs. MDS nodes are configured in active - active HA failover configuration. (For teset set-up configuration see https://wiki.hpdd.intel.com/display/Releases/Soak+Testing+on+Lola#SoakTestingonLola-Configuration)

Sequence of events:

• mds_restart : 2016-03-11 03:41:05,597 - 2016-03-11 03:54:49,109 lola-8
• 2016-03-11 03:56 Lustre client lola-32 crashed with the following error:

  <1>BUG: unable to handle kernel NULL pointer dereference at (null)
  <1>IP: [<ffffffffa0a0241f>] ll_open_cleanup+0xaf/0x600 [lustre]
  <4>PGD 38a867067 PUD 775372067 PMD 0
  <4>Oops: 0000 [#1] SMP
  <4>last sysfs file: /sys/devices/pci0000:00/0000:00:02.0/0000:06:00.0/infiniband_mad/umad0/port
  <4>CPU 1
  <4>Modules linked in: osc(U) mgc(U) lustre(U) lov(U) mdc(U) fid(U) lmv(U) fld(U) ko2iblnd(U) ptlrpc(U) obdclass(U) lnet(U) sha512_generic crc32c_intel libcfs(U) nfsi]
  <4>
  <4>Pid: 201682, comm: simul Not tainted 2.6.32-504.30.3.el6.x86_64 #1 Intel Corporation S2600GZ/S2600GZ
  <4>RIP: 0010:[<ffffffffa0a0241f>]  [<ffffffffa0a0241f>] ll_open_cleanup+0xaf/0x600 [lustre]
  <4>RSP: 0018:ffff8801d3f298e8  EFLAGS: 00010286
  <4>RAX: 0000000000000000 RBX: ffff8807f7271a00 RCX: ffff88102dd13ca0
  <4>RDX: 0000000000000002 RSI: 0000000000000000 RDI: ffff88102f395000
  <4>RBP: ffff8801d3f29928 R08: ffff88034f47e9c0 R09: 0000000000000000
  <4>R10: 0000000000000010 R11: 0000000000000000 R12: 0000000000000000
  <4>R13: ffff88082dd02c00 R14: ffff88081a5fc800 R15: ffff8801d3f29988
  <4>FS:  00007f72f89d3700(0000) GS:ffff880045e20000(0000) knlGS:0000000000000000
  <4>CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
  <4>CR2: 0000000000000000 CR3: 00000003b89f2000 CR4: 00000000001407e0
  <4>DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
  <4>DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
  <4>Process simul (pid: 201682, threadinfo ffff8801d3f28000, task ffff8804c6d73520)
  <4>Stack:
  <4> ffff8801d3f298f8 0000000000000000 ffff8801d3f29928 0000000000000001
  <4><d> ffff88082dd02c00 ffff88081a5fc800 ffff8809648898c0 ffff8801d3f29988
  <4><d> ffff8801d3f299f8 ffffffffa0a09c4a fffffffffffffffb 00ff880a531788c0
  <4>Call Trace:
  <4> [<ffffffffa0a09c4a>] ll_prep_inode+0x20a/0xc40 [lustre]
  <4> [<ffffffffa07804b2>] ? __req_capsule_get+0x162/0x6e0 [ptlrpc]
  <4> [<ffffffffa0a214f0>] ? ll_md_blocking_ast+0x0/0x7d0 [lustre]
  <4> [<ffffffffa0a21fe1>] ll_lookup_it_finish+0x321/0x12e0 [lustre]
  <4> [<ffffffffa0723dd0>] ? ldlm_lock_decref_internal+0x2e0/0xa80 [ptlrpc]
  <4> [<ffffffffa0569925>] ? class_handle2object+0x95/0x190 [obdclass]
  <4> [<ffffffff81174ab3>] ? kmem_cache_alloc_trace+0x1b3/0x1c0
  <4> [<ffffffffa0a1e439>] ? ll_i2suppgid+0x19/0x30 [lustre]
  <4> [<ffffffffa0a1e47e>] ? ll_i2gids+0x2e/0xd0 [lustre]
  <4> [<ffffffffa0a214f0>] ? ll_md_blocking_ast+0x0/0x7d0 [lustre]
  <4> [<ffffffffa0a23226>] ll_lookup_it+0x286/0xda0 [lustre]
  <4> [<ffffffffa0a23dc9>] ll_lookup_nd+0x89/0x4f0 [lustre]
  <4> [<ffffffff8119e055>] do_lookup+0x1a5/0x230
  <4> [<ffffffff8119ece4>] __link_path_walk+0x7a4/0x1000
  <4> [<ffffffff8119f7fa>] path_walk+0x6a/0xe0
  <4> [<ffffffff8119fa0b>] filename_lookup+0x6b/0xc0
  <4> [<ffffffff8122daa6>] ? security_file_alloc+0x16/0x20
  <4> [<ffffffff811a0ee4>] do_filp_open+0x104/0xd20
  <4> [<ffffffff81063c63>] ? perf_event_task_sched_out+0x33/0x70
  <4> [<ffffffff8129943a>] ? strncpy_from_user+0x4a/0x90
  <4> [<ffffffff811ae392>] ? alloc_fd+0x92/0x160
  <4> [<ffffffff8118b157>] do_sys_open+0x67/0x130
  <4> [<ffffffff8118b260>] sys_open+0x20/0x30
  <4> [<ffffffff8100b0d2>] system_call_fastpath+0x16/0x1b
  <4>Code: ba 38 01 00 00 31 f6 e8 30 62 b6 ff f6 05 fd 6b a9 ff 10 74 0d 80 3d f0 6b a9 ff 00 0f 88 ba 01 00 00 48 85 db 0f 84 16 02 00 00 <49> 8b 04 24 48 89 03 49
  <1>RIP  [<ffffffffa0a0241f>] ll_open_cleanup+0xaf/0x600 [lustre]
  <4> RSP <ffff8801d3f298e8>
  <4>CR2: 0000000000000000
  

Attached client (lola-32) message, console and vmcore-dmesg.txt file.

Comments

[Hongchao Zhang]

the issue should be caused by the race between the replay and the normal process of the open request.

Thread 1:
send the LDLM_ENQUEUE request to MDT1 to open the directory, and send requests to other MDTs to get the attributes
after get the reply from the MDT1, but it was stuck by one of the requests to other MDTs.

Thread 2:
closing the file, and the "rq_replay" of the open request is cleared in "mdc_close".

Then, the MDT1 got failover and the recovery is initiated, then the LDLM_ENQUEUE request in Thread 1 is replayed but failed
with -ENOTCONN during replaying the request to MDT1 and its "rq_repmsg" will contain only the "PTLRPC_BODY" field.
then the issue is triggered in "ll_open_cleanup".

[Frank Heckes (Inactive)]

Odd, I decompressed the Lustre client 'normal' kernel and the debuginfo kernel, both returned the
following messages (besides different names):

[root@lola-16 crash_lustre]# crash /scratch/crashdumps/lu-7866/lola-32/127.0.0.1-2016-03-11-03\:55\:54/vmcore /tmp/vmlinux-2.6.32-504.30.3.el6.x86_64

crash 6.1.0-6.el6_6
Copyright (C) 2002-2012  Red Hat, Inc.
Copyright (C) 2004, 2005, 2006, 2010  IBM Corporation
Copyright (C) 1999-2006  Hewlett-Packard Co
Copyright (C) 2005, 2006, 2011, 2012  Fujitsu Limited
Copyright (C) 2006, 2007  VA Linux Systems Japan K.K.
Copyright (C) 2005, 2011  NEC Corporation
Copyright (C) 1999, 2002, 2007  Silicon Graphics, Inc.
Copyright (C) 1999, 2000, 2001, 2002  Mission Critical Linux, Inc.
This program is free software, covered by the GNU General Public License,
and you are welcome to change it and/or distribute copies of it under
certain conditions.  Enter "help copying" to see the conditions.
This program has absolutely no warranty.  Enter "help warranty" for details.
 
crash: /tmp/vmlinux-2.6.32-504.30.3.el6.x86_64: no .gnu_debuglink section

crash: /tmp/vmlinux-2.6.32-504.30.3.el6.x86_64: no debugging data available

Path to Oleg's lustre.so is configured via ~/.crashrc. Any ideas?

[Frank Heckes (Inactive)]

Yes, to extract the debug log from the crash file. For log information on MDS side (MDT000

{0,1}

I'm going to check, too and will attach the files here.

[Hongchao Zhang]

the issue can be reproduced if the request is replayed but failed between ll_prep_inod and ll_open_cleanup.
I have managed to simulate this case in my local VMs and it occurred, but I'm not sure whether it is the same case with this one

[Hongchao Zhang]

Hi Frank,
Could you please extract the debug logs from the crash dump? and I can't connect to the Lola.
and is the logs at MDT0000 & MDT0001 available? it could help to trace the problem.
Thanks!!

[Hongchao Zhang]

status update:
1, the request is just change between ll_prep_inode and ll_open_cleanup, for the MDT_BODY is also retrieved in ll_prep_inode
2, in ll_prep_inode, ll_iget failed with -EIO, then the related FID could be a directory, and the GET_ATTR request to other MDTs failed

It's not clear where the request is modified, and it could be changed by the replay, but there is no "P" flags in the request,
and I also try to reproduce the problem by replaying the request before ll_open_cleanup use it, but failed to reproduce.

[Hongchao Zhang]

the related request has been actually failed with -ENOTCONN(-107), then there is not reply fields (Reply's bufcount is 1, only contains
PTLRPC_BODY) in the request, still looking why the failed request can go to the "ll_prep_inode/ll_open_cleanup".

[Frank Heckes (Inactive)]

My apologies there's a typo in the description field above (I corrected it). The build under test was b2_8 rc5 and had been downloaded from Jenkens job lustre-2_8 . The debuginfo RPMs can be found at lhn.lola.hpdd.intel.com:/scratch/rpms/20160309/notinstalled/server/x86_64.

[Oleg Drokin]

Frank - are these builds using the RC5 RPM or do you self-build them from tip of whatever branch? Because it says "build '20160302'", but if you self build it does not help us and you need to put debuginfo vmlinux and debuginfo modules alongside the crashdumps

[Peter Jones]

Hongchao

Can you please look into this? Oleg has suggested that you should

1) add error handling
2. figure out why the request reply does not have what we think it should have inside

Thanks

Peter

[Oleg Drokin]

The actual problem here is two lines above the crash:

<3>LustreError: 201682:0:(layout.c:2025:__req_capsule_get()) @@@ Wrong buffer for field `mdt_body' (2 of 1) in format `LDLM_INTENT_OPEN': 0 vs. 216 (server)
<3>  req@ffff880e244a90c0 x1528368254991312/t489629526959(489629526959) o101->soaked-MDT0001-mdc-ffff88082dd02c00@192.168.1.108@o2ib10:12/10 lens 840/192 e 1 to 0 dl 1457697328 ref 2 fl Complete:R/4/0 rc -107/-107

This then causes the crash because:

void ll_open_cleanup(struct super_block *sb, struct ptlrpc_request *open_req)
{
        struct mdt_body                 *body;
        struct md_op_data               *op_data;
        struct ptlrpc_request           *close_req = NULL;
        struct obd_export               *exp       = ll_s2sbi(sb)->ll_md_exp;
        ENTRY;

        body = req_capsule_server_get(&open_req->rq_pill, &RMF_MDT_BODY);  <=== Returns NULL due to message above
        OBD_ALLOC_PTR(op_data);
        if (op_data == NULL) {
                CWARN("%s: cannot allocate op_data to release open handle for "
                      DFID"\n",
                      ll_get_fsname(sb, NULL, 0), PFID(&body->mbo_fid1));

                RETURN_EXIT;
        }

        op_data->op_fid1 = body->mbo_fid1;       <==== Whoops!