Bug 1055537 - kernel BUG at fs/nfs/nfs4xdr.c:908!
Summary: kernel BUG at fs/nfs/nfs4xdr.c:908!
Keywords:
Status: CLOSED DUPLICATE of bug 1050206
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 19
Hardware: x86_64
OS: Linux
unspecified
urgent
Target Milestone: ---
Assignee: Jeff Layton
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-01-20 13:59 UTC by Rosario Esposito
Modified: 2014-06-18 07:43 UTC (History)
11 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-02-26 16:23:49 UTC
Type: Bug


Attachments (Terms of Use)
abrt bug report (44.62 KB, application/x-gzip)
2014-01-20 13:59 UTC, Rosario Esposito
no flags Details
patch -- print number of bytes requested and some info about xdr stream prior to oopsing (779 bytes, patch)
2014-01-29 23:58 UTC, Jeff Layton
no flags Details | Diff
dmesg oops with kernel 3.12.8-200.fc19.x86_64 (144.96 KB, text/plain)
2014-02-08 12:12 UTC, Rosario Esposito
no flags Details
oops with kernel 3.12.9-201.bz1055537.1.fc19.x86_64.debug (6.37 KB, text/plain)
2014-02-08 23:38 UTC, Rosario Esposito
no flags Details
second oops with kernel 3.12.9-201.bz1055537.1.fc19.x86_64.debug (6.81 KB, text/plain)
2014-02-09 10:57 UTC, Rosario Esposito
no flags Details
full /var/log messages oops with kernel 3.12.9-201.bz1055537.1.fc19.x86_64.debug (345.77 KB, text/plain)
2014-02-10 18:42 UTC, Rosario Esposito
no flags Details

Description Rosario Esposito 2014-01-20 13:59:22 UTC
Created attachment 852758 [details]
abrt bug report

Description of problem:
My Fedora 19 server is experiencing kernel panics after several hours of regular usage.
I'd like to understand if this is caused by a hardware issue or a kernel instability.
 

Version-Release number of selected component (if applicable):
Fedora 19 - kernel 3.12.7-200.fc19.x86_64

How reproducible:
Not easy to reproduce.. It happened unexpectedly: 3 times in 2 days.  
The last messages it logs before dying are:

[ 5989.835667] ------------[ cut here ]------------
[ 5989.835825] kernel BUG at fs/nfs/nfs4xdr.c:908!
[ 5989.835979] invalid opcode: 0000 [#1] SMP
...
...
(see attachment for the full dmesg log) 


Additional info:
The server has an Intel 82599ES 10gbit/s interface (eth4).
The sub-interface eth4.2 is used to mount home directories from a nexenta storage system via NFS4 on VLAN2.

Comment 1 Jeff Layton 2014-01-20 17:49:11 UTC
That's the BUG_ON in this function:


static __be32 *reserve_space(struct xdr_stream *xdr, size_t nbytes)
{
        __be32 *p = xdr_reserve_space(xdr, nbytes);
        BUG_ON(!p);
        return p;
}

...a full backtrace would be helpful though. Without knowing the call chain that caused this we probably won't make any progress on it. The stuff in the abrt report is more about a problem with a network driver. That may or may not be related (probably not though).

Comment 2 Rosario Esposito 2014-01-21 10:03:44 UTC
Unfortunately I don't have the full backtrace as Kdump was not enabled at that time. Is there any other log files I could check ?
 
By the way yesterday, after the last crash, I switched the NFS mount from version 4 to version 3 and I got no kernel panics since then.

Comment 3 Reinier Schoof 2014-01-24 13:03:32 UTC
I had a similar panic, on Debian's linux 3.12.6-2~bpo70+1, just now. We're running NFSv4 intensively. I happen to have the kdump traces:

kernel BUG at /build/linux-Ol1uYP/linux-3.12.6/fs/nfs/nfs4xdr.c:908!
Workqueue: rpciod rpc_async_schedule [sunrpc]
Call Trace:
[<ffffffffa05d18fb>] ? encode_string+0x1b/0x40 [nfsv4]
[<ffffffffa05d36f0>] ? nfs4_xdr_enc_open_confirm+0x70/0xd0 [nfsv4]
[<ffffffffa04b0429>] ? rpcauth_wrap_req+0xa9/0xe0 [sunrpc]
[<ffffffffa04a4210>] ? call_connect+0xe0/0xe0 [sunrpc]
[<ffffffffa04a4385>] ? call_transmit+0x175/0x2c0 [sunrpc]
[<ffffffffa04adf4e>] ? __rpc_execute+0x8e/0x430 [sunrpc]
[<ffffffffa04a4210>] ? call_connect+0xe0/0xe0 [sunrpc]
[<ffffffffa04ae30d>] ? rpc_async_schedule+0x1d/0x30 [sunrpc]
[<ffffffff8107a7a7>] ? process_one_work+0x157/0x450
[<ffffffff8107bc24>] ? worker_thread+0x114/0x370
[<ffffffff8107bb10>] ? manage_workers.isra.21+0x2d0/0x2d0
[<ffffffff810822d3>] ? kthread+0xb3/0xc0
[<ffffffff81082220>] ? flush_kthread_worker+0xa0/0xa0
[<ffffffff814cc40c>] ? ret_from_fork+0x7c/0xb0
[<ffffffff81082220>] ? flush_kthread_worker+0xa0/0xa0

I hope this helps finding the source of the problem, let me know if additional information regarding the crash is required.

Comment 4 Rosario Esposito 2014-01-24 14:07:17 UTC
We also were running NFSv4 intensively.
Yet no kernel panics since I've switched to NFSv3.

Comment 5 Jeff Layton 2014-01-24 14:25:48 UTC
Makes sense since the panic in NFSv4 code and NFSv3 doesn't travel that codepath.

So what happened is that we hit this case in xdr_reserve_space():

        if (unlikely(q > xdr->end || q < p))
                return NULL;

...basically, that means that we don't have enough room in the xdr buffer to encode the reply or we somehow got a negative offset.

It would be interesting to figure out what line of code this address refers to 'nfs4_xdr_enc_open_confirm+0x70'. There are some instructions here though you'll need to substitute the nfsv4.ko for cifs.ko in them:

    https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Oopses

Comment 6 Rosario Esposito 2014-01-24 17:24:09 UTC
In my case:

[root@clueet ~]# grep nfs4_xdr_enc_open_confirm /tmp/oops-2014-01-20-13\:45\:53-32607-0/dmesg
[ 5989.901230]  [<ffffffffa04f0181>] nfs4_xdr_enc_open_confirm+0x61/0xc0 [nfsv4]
[ 5993.028997]  [<ffffffffa04f0181>] nfs4_xdr_enc_open_confirm+0x61/0xc0 [nfsv4]
[ 6015.784755]  [<ffffffffa04f0181>] nfs4_xdr_enc_open_confirm+0x61/0xc0 [nfsv4]
[ 6053.074343]  [<ffffffffa04f0181>] nfs4_xdr_enc_open_confirm+0x61/0xc0 [nfsv4]
[ 6232.702430]  [<ffffffffa04f0181>] nfs4_xdr_enc_open_confirm+0x61/0xc0 [nfsv4]

# gdb /lib/modules/3.12.7-200.fc19.x86_64/kernel/fs/nfs/nfsv4.ko
GNU gdb (GDB) Fedora 7.6.1-46.fc19
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/lib/modules/3.12.7-200.fc19.x86_64/kernel/fs/nfs/nfsv4.ko...Reading symbols from /usr/lib/debug/lib/modules/3.12.7-200.fc19.x86_64/kernel/fs/nfs/nfsv4.ko.debug...done.
done.
(gdb) list *(nfs4_xdr_enc_open_confirm+0x61)
0x11181 is in nfs4_xdr_enc_open_confirm (fs/nfs/nfs4xdr.c:974).
969
970	static void encode_op_hdr(struct xdr_stream *xdr, enum nfs_opnum4 op,
971			uint32_t replen,
972			struct compound_hdr *hdr)
973	{
974		encode_uint32(xdr, op);
975		hdr->nops++;
976		hdr->replen += replen;
977	}
978
(gdb)


(the 'dmesg' file is in the previously attached abrt tarball)
I hope it helps.

Comment 7 Jeff Layton 2014-01-24 17:35:03 UTC
Sigh...so most of the functions called by nfs4_xdr_enc_open_confirm end up calling that function to put the op header into the call. So we'll need to do a bit more investigation to determine which one that is. I'll take a closer look when I get time.

Comment 8 Jeff Layton 2014-01-24 18:29:57 UTC
Looking at the disassembly from 3.12.8-300.fc20.x86_64 (I doubt anything changed in this file between the two versions).

0xffffffffa0fcd179 <nfs4_xdr_enc_open_confirm+0x59>:    mov    %rbx,%rdi
0xffffffffa0fcd17c <nfs4_xdr_enc_open_confirm+0x5c>:    callq  0xffffffffa0fcb400 <encode_putfh>
0xffffffffa0fcd181 <nfs4_xdr_enc_open_confirm+0x61>:    mov    %rbx,%rdi
0xffffffffa0fcd184 <nfs4_xdr_enc_open_confirm+0x64>:    mov    $0x14,%esi

...so the oops is likely in the call to encode_string in encode_putfh. That call is this:

        encode_string(xdr, fh->size, fh->data);

....which would seem to imply that maybe you're getting some very large filehandles? It might be interesting to instrument code just before the BUG_ON call and see if that's the problem...

Comment 9 Rosario Esposito 2014-01-24 21:32:18 UTC
I would very much need this to be fixed as I'm having a number of other issues with NFSv3 file locking. If you could make a modified version of nfsv4.ko I'd be happy to test it.

Comment 10 Jeff Layton 2014-01-29 23:58:55 UTC
Created attachment 857310 [details]
patch -- print number of bytes requested and some info about xdr stream prior to oopsing

Ok, there's a patched kernel here that might give us more info:

    https://koji.fedoraproject.org/koji/taskinfo?taskID=6468532

It just adds a printk before the BUG_ON where this is oopsing. That might give us a better idea of what's going wrong.

Comment 11 Rosario Esposito 2014-02-08 12:12:50 UTC
Created attachment 860881 [details]
dmesg oops with kernel 3.12.8-200.fc19.x86_64

Comment 12 Rosario Esposito 2014-02-08 12:15:32 UTC
Hi Jeff,
I was waiting for a new crash before booting the machine with the patched kernel.
It happened today (see attached dmesg) after ~2 weeks running without problems.
Now I booted it with kernel 3.12.9-201.bz1055537.1.fc19.x86_64.debug.
I'll let you know what happens when it crashes again.

Comment 13 Rosario Esposito 2014-02-08 23:38:28 UTC
Created attachment 860911 [details]
oops with kernel 3.12.9-201.bz1055537.1.fc19.x86_64.debug

Comment 14 Rosario Esposito 2014-02-08 23:41:10 UTC
Hi again,
I got another oops after ~12 hours.
This is the output of the printk you added:

Feb  8 21:02:02 clueet kernel: [29990.543184] reserve_space: p=0xffff8807ee0409f0 end=0xffff8807ee040b34 bytes=42236
Feb  8 21:02:02 clueet kernel: [29990.559115] ------------[ cut here ]------------
Feb  8 21:02:02 clueet kernel: [29990.574703] kernel BUG at fs/nfs/nfs4xdr.c:910!
Feb  8 21:02:02 clueet kernel: [29990.590071] invalid opcode: 0000 [#1] SMP

I hope this helps.

Comment 15 Rosario Esposito 2014-02-09 10:57:28 UTC
Created attachment 860946 [details]
second oops with kernel 3.12.9-201.bz1055537.1.fc19.x86_64.debug

Comment 16 Rosario Esposito 2014-02-09 10:59:08 UTC
Another one...

Feb  9 04:32:02 clueet kernel: [14826.807581] reserve_space: p=0xffff8810128889f0 end=0xffff881012888b34 bytes=42236
Feb  9 04:32:02 clueet kernel: [14826.822269] ------------[ cut here ]------------
Feb  9 04:32:03 clueet kernel: [14826.836676] kernel BUG at fs/nfs/nfs4xdr.c:910!
Feb  9 04:32:03 clueet kernel: [14826.850876] invalid opcode: 0000 [#1] SMP

Comment 17 Jeff Layton 2014-02-10 17:32:42 UTC
Do you have the rest of the stack trace by any chance (or a vmcore)?

0xffff881012888b34-0xffff8810128889f0 == 0x144

...which is decimal 324, but this code is trying to reserve 42k. Do you by any chance have the rest of the stack trace?

Comment 18 Jeff Layton 2014-02-10 18:18:27 UTC
Assuming that the stack trace looks similar to the one in comment #11, then it looks like you're somehow getting a 42k filehandle (which is extremely large). It should be no larger than 128 bytes:

#define NFS_MAXFHSIZE           128
struct nfs_fh {
        unsigned short          size;
        unsigned char           data[NFS_MAXFHSIZE];
};

What might be best is to collect a vmcore, as I suspect that there may be some memory corruption...

Comment 19 Rosario Esposito 2014-02-10 18:42:43 UTC
Created attachment 861519 [details]
full /var/log messages oops with kernel 3.12.9-201.bz1055537.1.fc19.x86_64.debug

Comment 20 Rosario Esposito 2014-02-10 18:48:23 UTC
I only have a full /var/log/messages, I attached it in comment #19.
I was not able to generate a vmcore.
Apparently there's a problem in doing it with Fedora 19
https://fedoraproject.org/wiki/QA:Testcase_ABRT_vmcore
I followed these instructions:
https://fedoraproject.org/wiki/How_to_use_kdump_to_debug_kernel_crashes
but my /var/crash was empty after the kernel panic.
Do you have any clue how to get a vmcore correctly ?

Concerning the memory corruption you suspect, what does that mean ? could it be a hardware issue ?

Comment 21 Jeff Layton 2014-02-10 19:15:27 UTC
By memory corruption, I mean that something likely scribbled over a region of memory. That can happen for all sorts of reasons faulty hardware is certainly one, but it can happen due to software problems too.

The problem is that they're often quite tricky to track down. Looking through the log, I see this a little later:


Feb  9 04:33:07 clueet kernel: [14828.773531] BUG: unable to handle kernel paging request at ffffffffffffff98
Feb  9 04:33:07 clueet kernel: [14828.781821] IP: [<ffffffff810a2150>] kthread_data+0x10/0x20
Feb  9 04:33:07 clueet kernel: [14828.789907] PGD 1c0f067 PUD 1c11067 PMD 0 

...which is actually the more troubling problem, since that's a real GFP and not just a spot where someone put a deliberate BUG() assertion. In fact, it looks like that's equivalent to 0 - 104, so it's possible there was an ECONNRESET error in there somewhere.

Anyway, my suspicion is that the original BUG() call in reserve_space is just a symptom of a larger problem. That problem may be what's causing kdump not to work correctly too.

What may help is to set /proc/sys/kernel/panic_on_oops to 1 (it's generally 0 in Fedora) since that'll make the box panic on the first BUG() call instead of trying to keep going.

Comment 22 Rosario Esposito 2014-02-25 13:54:37 UTC
Hi,
since my last post the system has been running with no problems, using NFSv3 mounts.
Today I rebooted it, I switched back to NFSv4 + kernel 3.12.9-201.bz1055537.1.fc19.x86_64.
I also set /proc/sys/kernel/panic_on_oops to 1.
After a few hours, I got a kernel panic and it self rebooted. This time the system generated a ~680MB vmcore which I uploaded here:
https://docs.google.com/file/d/0B4tKW-EJ-33qV0N3bS0tQkVfQU0

I was not able to capture the output of dmesg. There was just an empty vmcore-dmesg-incomplete.txt in /var/crash.

Please, can you have a look ?

Comment 23 Rosario Esposito 2014-02-25 14:05:49 UTC
[root@clueet ~]# crash /var/crash/127.0.0.1-2014.02.25-13\:38\:12/vmcore /usr/lib/debug/lib/modules/3.12.9-201.bz1055537.1.fc19.x86_64/vmlinux

crash 7.0.3-1.fc20
Copyright (C) 2002-2013  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.

GNU gdb (GDB) 7.6
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-unknown-linux-gnu"...

      KERNEL: /usr/lib/debug/lib/modules/3.12.9-201.bz1055537.1.fc19.x86_64/vmlinux
    DUMPFILE: /var/crash/127.0.0.1-2014.02.25-13:38:12/vmcore  [PARTIAL DUMP]
        CPUS: 32
        DATE: Tue Feb 25 13:38:03 2014
      UPTIME: 12:55:24
LOAD AVERAGE: 2.19, 3.30, 3.32
       TASKS: 2358
    NODENAME: clueet.cern.ch
     RELEASE: 3.12.9-201.bz1055537.1.fc19.x86_64
     VERSION: #1 SMP Wed Jan 29 21:17:10 UTC 2014
     MACHINE: x86_64  (2899 Mhz)
      MEMORY: 64 GB
       PANIC: "kernel BUG at fs/nfs/nfs4xdr.c:910!"
         PID: 11996
     COMMAND: "kworker/6:1"
        TASK: ffff880541d539c0  [THREAD_INFO: ffff88084adac000]
         CPU: 6
       STATE: TASK_RUNNING (PANIC)

crash>

Comment 24 Rosario Esposito 2014-02-25 14:09:17 UTC
[46511.287488] reserve_space: p=0xffff8805eba79070 end=0xffff8805eba791b4 bytes=57348
[46511.301751] ------------[ cut here ]------------
[46511.315562] kernel BUG at fs/nfs/nfs4xdr.c:910!

Comment 25 Jeff Layton 2014-02-25 14:24:45 UTC
Great, please do the following:

rename the vmcore to something like bz1055537-vmcore and then gzip it. Then, upload that file to:

    ftp://dropbox.redhat.com/incoming

...and let me know once it's done uploading. I'm traveling this week and might not get a chance to look at it for a bit, but I'll get to it as soon as I can.

Comment 26 Rosario Esposito 2014-02-25 14:47:52 UTC
Done, bz1055537-vmcore.gz uploaded.
Thanks a lot.

Comment 27 Jeff Layton 2014-02-25 18:24:38 UTC
Thanks. Looks like the debuginfo got gc'ed in koji, so I'm having to rebuild the kernel. Trond seems to think that this may be related to bug 1061707. Once I get a look at the core I'll try to confirm that either way...

In the meantime, it would be good to test a v3.12.12 or later kernel once those show up in koji.

Comment 28 Rosario Esposito 2014-02-25 18:38:26 UTC
I don't seem to be authorized to see bug 1061707 but I trust you :-)
If needed, I still have the debuginfo rpms of kernel 3.12.9-201.bz1055537.1.fc19.x86_64.

Comment 29 Jeff Layton 2014-02-26 16:23:49 UTC
Ok, looking at the vmcore, I think I agree with Trond and this is likely a dup of bug 1050206. The symptoms look a little different, but the same data structures are being corrupted.

It would be best to try a newer kernel on this box that has commit 17ead6c85c3d0ef57a14d1373f1f1cee2ce60ea8. It looks like they're working on v3.13.5 kernels in koji, which have that patch. You may want to try one of those:

    http://koji.fedoraproject.org/koji/buildinfo?buildID=500653

I'm going to go ahead and close this as a dup of that bug. If the newer kernel doesn't help, we'll plan to reopen this bug and continue looking at it.

*** This bug has been marked as a duplicate of bug 1050206 ***

Comment 30 Rosario Esposito 2014-02-26 17:08:55 UTC
Thanks a lot, I'll give it a try !

Comment 31 Rosario Esposito 2014-03-11 22:00:59 UTC
Hi,
no kernel panics observed since I updated to kernel 3.13.5-101.fc19.x86_64.
This seems to have fixed it. Thanks !


Note You need to log in before you can comment on or make changes to this bug.