Bug 222898
| Summary: | [iscsi]: panic: page fault - system crashes while working as iSCSI target | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | Base System | Reporter: | emz | ||||||
| Component: | kern | Assignee: | Edward Tomasz Napierala <trasz> | ||||||
| Status: | Closed FIXED | ||||||||
| Severity: | Affects Only Me | CC: | thomsonk, trasz | ||||||
| Priority: | --- | Keywords: | patch | ||||||
| Version: | 11.0-STABLE | ||||||||
| Hardware: | Any | ||||||||
| OS: | Any | ||||||||
| Attachments: |
|
||||||||
|
Description
emz
2017-10-10 12:03:30 UTC
Environment: Uname: FreeBSD san1.lynx.playkey.net 11.0-STABLE FreeBSD 11.0-STABLE #1 r310734M: Thu Sep 21 18:40:08 +05 2017 emz@san1.lynx.playkey.net:/usr/obj-11-r310734/usr/src-11-r310734/sys/GENERIC amd64 Disks: [root@san1:sys/SANDEBUG]# camcontrol devlist <AHCI SGPIO Enclosure 1.00 0001> at scbus4 target 0 lun 0 (ses0,pass0) <AHCI SGPIO Enclosure 1.00 0001> at scbus11 target 0 lun 0 (ses1,pass1) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 8 lun 0 (pass2,da0) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 9 lun 0 (pass3,da1) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 10 lun 0 (pass4,da2) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 11 lun 0 (pass5,da3) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 12 lun 0 (pass6,da4) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 13 lun 0 (pass7,da5) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 14 lun 0 (pass8,da6) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 15 lun 0 (pass9,da7) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 16 lun 0 (pass10,da8) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 17 lun 0 (pass11,da9) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 18 lun 0 (pass12,da10) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 19 lun 0 (pass13,da11) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 20 lun 0 (pass14,da12) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 21 lun 0 (pass15,da13) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 22 lun 0 (pass16,da14) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 23 lun 0 (pass17,da15) <ATA TOSHIBA THNSN81Q 6101> at scbus12 target 24 lun 0 (pass18,da16) <LSI SAS3x40 0601> at scbus12 target 32 lun 0 (ses2,pass19) <ATEN Virtual CDROM YS0J> at scbus13 target 0 lun 0 (pass20,cd0) ctl statistics: # ctladm devlist | wc -l 821 # ctladm islist | wc -l 755 (two disks per initiator, some sometimes lose their target for the reason not related to this ticket) traffic when idling: netstat -I ix0 1 input ix0 output packets errs idrops bytes packets errs bytes colls 50641 0 0 70562167 49719 0 70335884 0 50099 0 0 70148479 48306 0 68437356 0 46561 0 0 65304615 44928 0 63583291 0 48908 0 0 68448307 47207 0 66274503 0 56893 0 0 79810803 55510 0 78770191 0 67500 0 0 94948586 65446 0 93477697 0 49551 0 0 69503383 48396 0 68838826 0 66153 0 0 92608074 65416 0 93358583 0 55500 0 0 77802745 54048 0 77154416 0 44205 0 0 61417486 43995 0 60993381 0 67484 0 0 94723317 69191 0 94908452 0 ^C when non idling traffic can peak up to 700Kpps-9Gbit/sec. This very system, being boot up with debug kernel, built with
crashes somewhere withing 30 seconds after the ctld is started:
WARNING: 10.0.3.211 (iqn.1991-05.com.microsoft:worker379): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 10.0.3.211 (iqn.1991-05.com.microsoft:worker379): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 10.0.3.201 (iqn.1991-05.com.microsoft:worker369): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 213.152.134.47 (iqn.1991-05.com.microsoft:worker18): no ping reply (NOP-Out) after 5 seconds; dropping connecti
on
WARNING: 213.152.134.51 (iqn.1991-05.com.microsoft:worker22): no ping reply (NOP-Out) after 5 seconds; dropping connecti
on
WARNING: 10.0.3.219 (iqn.1991-05.com.microsoft:worker387): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 213.152.138.2 (iqn.2016-04.net.playkey.iscsi:esx11): no ping reply (NOP-Out) after 5 seconds; dropping connecti
on
panic: destroying session with 4 outstanding PDUs
cpuid = 5
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe10555e48f0
vpanic() at vpanic+0x186/frame 0xfffffe10555e4970
kassert_panic() at kassert_panic+0x126/frame 0xfffffe10555e49e0
icl_soft_conn_close() at icl_soft_conn_close+0x1f5/frame 0xfffffe10555e4a10
cfiscsi_maintenance_thread() at cfiscsi_maintenance_thread+0x100/frame 0xfffffe10555e4a70
fork_exit() at fork_exit+0x84/frame 0xfffffe10555e4ab0
fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe10555e4ab0
--- trap 0, rip = 0, rsp = 0, rbp = 0 ---
Uptime: 2m11s
Dumping 8422 out of 65386 MB:..1%..11%..21%..31%..41%..51%..61%..71%..81%..91%
Reading symbols from /boot/kernel/zfs.ko...Reading symbols from /usr/lib/debug//boot/kernel/zfs.ko.debug...done.
done.
Loaded symbols for /boot/kernel/zfs.ko
Reading symbols from /boot/kernel/opensolaris.ko...Reading symbols from /usr/lib/debug//boot/kernel/opensolaris.ko.debug
...done.
done.
Loaded symbols for /boot/kernel/opensolaris.ko
Reading symbols from /boot/kernel/geom_mirror.ko...Reading symbols from /usr/lib/debug//boot/kernel/geom_mirror.ko.debug
...done.
done.
Loaded symbols for /boot/kernel/geom_mirror.ko
Reading symbols from /boot/kernel/pf.ko...Reading symbols from /usr/lib/debug//boot/kernel/pf.ko.debug...done.
done.
Loaded symbols for /boot/kernel/pf.ko
Reading symbols from /boot/kernel/ichwd.ko...Reading symbols from /usr/lib/debug//boot/kernel/ichwd.ko.debug...done.
done.
Loaded symbols for /boot/kernel/ichwd.ko
Reading symbols from /boot/kernel/ctl.ko...Reading symbols from /usr/lib/debug//boot/kernel/ctl.ko.debug...done.
done.
Loaded symbols for /boot/kernel/ctl.ko
Reading symbols from /boot/kernel/iscsi.ko...Reading symbols from /usr/lib/debug//boot/kernel/iscsi.ko.debug...done.
done.
Loaded symbols for /boot/kernel/iscsi.ko
#0 doadump (textdump=1) at pcpu.h:222
222 pcpu.h: No such file or directory.
in pcpu.h
(kgdb) #0 doadump (textdump=1) at pcpu.h:222
#1 0xffffffff80a2e725 in kern_reboot (howto=<value optimized out>)
at /usr/src-11-r310734/sys/kern/kern_shutdown.c:366
#2 0xffffffff80a2ed00 in vpanic (fmt=<value optimized out>,
ap=<value optimized out>)
at /usr/src-11-r310734/sys/kern/kern_shutdown.c:759
#3 0xffffffff80a2eb36 in kassert_panic (fmt=<value optimized out>)
at /usr/src-11-r310734/sys/kern/kern_shutdown.c:649
#4 0xffffffff82875f05 in icl_soft_conn_close (ic=<value optimized out>)
at /usr/src-11-r310734/sys/modules/iscsi/../../dev/iscsi/icl_soft.c:1443
#5 0xffffffff82845560 in cfiscsi_maintenance_thread (
arg=<value optimized out>) at icl_conn_if.h:135
#6 0xffffffff809f2064 in fork_exit (
callout=0xffffffff82845460 <cfiscsi_maintenance_thread>,
arg=0xfffff8033e06cc00, frame=0xfffffe10555e4ac0)
at /usr/src-11-r310734/sys/kern/kern_fork.c:1040
#7 0xffffffff80e7432e in fork_trampoline ()
at /usr/src-11-r310734/sys/amd64/amd64/exception.S:611
#8 0x0000000000000000 in ?? ()
Current language: auto; currently minimal
(kgdb)
This is reproducible, it crashed 3 times in a row from 3 attempts to run the debug kernel. I spoke with mav@, he told me (as far as I undertood) that with is unintended behaviour, and it is probably the possible reason why the target system crashes when running non-debug kernel.
I collected a crashdump from one of the attempts, it's available here along with the kernel and modules binaries, along with non-stripped ones:
http://files2.enaza.ru/ctld-stuck/debug/
Seems like I have planned to add the debug kernel configuration later but totally forgot to do it. So, here it is: ident SANDEBUG include GENERIC options WITNESS options WITNESS_SKIPSPIN options INVARIANTS options INVARIANT_SUPPORT options DIAGNOSTIC options DEADLKRES options MALLOC_DEBUG_MAXZONES=8 options DDB options KDB_UNATTENDED What's the exact version of the kernel you are running? Could you try to upgrade to at least r315520 and see if it changes anything? This happens on a machine running r310734. Unfortunately, on a more recent versions, not sure what the exact revision from, I got this: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=219760 . I could try to reproduce this on a r320056 which I have on a test SAN system in the office, but the test environment doesn't have that much of initiators - only about 3-5, and on a production systems I have several hundreds. So, if this is related to the initiators number, then I guess it won't give anything. However, I will try and post the result back here. Ok, can you try with the r315520.diff applied instead? Created attachment 187144 [details]
r315520
Well, I took a risk and installed a stock r315520. Unfortunately, the behavior is identical: crash within dozens of seconds after starting ctld, same panic message on a debug kernel: ===Cut=== WARNING: 213.152.134.114 (iqn.1991-05.com.microsoft:worker85): no ping reply (NOP-Out) after 5 seconds; dropping connect ion WARNING: 213.152.138.158 (iqn.1991-05.com.microsoft:worker265): no ping reply (NOP-Out) after 5 seconds; dropping connec tion WARNING: 213.152.134.62 (iqn.1991-05.com.microsoft:worker33): no ping reply (NOP-Out) after 5 seconds; dropping connecti on WARNING: 213.152.134.114 (iqn.1991-05.com.microsoft:worker85): no ping reply (NOP-Out) after 5 seconds; dropping connect ion panic: destroying session with 4 outstanding PDUs cpuid = 24 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe105789a8f0 vpanic() at vpanic+0x186/frame 0xfffffe105789a970 kassert_panic() at kassert_panic+0x126/frame 0xfffffe105789a9e0 icl_soft_conn_close() at icl_soft_conn_close+0x20a/frame 0xfffffe105789aa10 cfiscsi_maintenance_thread() at cfiscsi_maintenance_thread+0x100/frame 0xfffffe105789aa70 fork_exit() at fork_exit+0x84/frame 0xfffffe105789aab0 fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe105789aab0 --- trap 0, rip = 0, rsp = 0, rbp = 0 --- Uptime: 1m55s ===Cut=== I am running a non-debug version of r315520 right now (so there's no either explicit regression or improvement over the r310734), it's still tending to crash in random moments of time when loaded by 299 initiators. As a workaround I will try to diminish the load by transferring some initiators to a spare SAN. Crashdumps, binaries and infos: http://files2.enaza.ru/ctld-stuck/r315520/ In the same time I'm still willing to help in any way in resolving this, including the access on a production system, over ssh/IPMI/whatever. Follow-up: it's stock r315520 except the CTL_MAX_PORTS set to 1024, I decided to mention this in case if it matters (but mav@ said that it's very unlikely that this change could affect anything). Is there something more needed from me ? Or may be my last answer was totally discouraging, and installing r315520 wasn't the expected action ? Do I need to test this patch instead ? Because as far as I understood I was given the patch 'cause "Okay, since you claiming that you cannot install r315520 - then take this patch". Did I understand this wrong ? I've spent some time thinking about this, and I believe the KASSERT in question is wrong. It's perfectly ok for PDUs to be allocated at this point - icl_conn_close() is called before terminating the tasks, so there might be eg cfiscsi_done() running in a parallel thread. That's why we have the ic_terminating check in icl_queue(). I believe the KASSERT should be moved from icl_conn_close() to icl_conn_free(). Alexander, do you agree? Having said that - I'd still like to take a look into how things actually look like when this happens, to make sure my reasoning is correct. Eugene, could you try to repeat this with the iscsi-optimize-off.diff applied, with all the other things just as they were before - with INVARIANTS and DIAGNOSTICS enabled? Please also include debug files from usr/lib/debug/boot/kernel/; the ones you've put up contain debug info for the kernel itself, but not for the modules. Or perhaps just build kernel with ctl and iscsi compiled in. Created attachment 187767 [details]
#pragma clang optimize off
A commit references this bug: Author: trasz Date: Thu Mar 15 17:36:14 UTC 2018 New revision: 331013 URL: https://svnweb.freebsd.org/changeset/base/331013 Log: Fix iSCSI target crash on session reinstation. The crash scenario goes like this: there's a thread waiting on "reinstate"; because it doesn't update the timeout counter it gets terminated by the callout; at this point the maintenance thread starts the termination routine. The first thread finishes waiting, proceeds to icl_conn_handoff(), and drops the refcount, which allows the maintenance thread to free its resources. At this point another thread receives a PDU. Boom. PR: 222898, 219866 Reported by: Eugene M. Zheganin <emz at norma.perm.ru> Tested by: Eugene M. Zheganin <emz at norma.perm.ru> Reviewed by: mav@ (earlier version) MFC after: 2 weeks Sponsored by: playkey.net Changes: head/sys/cam/ctl/ctl_frontend_iscsi.c head/sys/cam/ctl/ctl_frontend_iscsi.h *** Bug 210683 has been marked as a duplicate of this bug. *** A commit references this bug: Author: trasz Date: Mon Apr 16 17:24:33 UTC 2018 New revision: 332622 URL: https://svnweb.freebsd.org/changeset/base/332622 Log: MFC r331013: Fix iSCSI target crash on session reinstation. The crash scenario goes like this: there's a thread waiting on "reinstate"; because it doesn't update the timeout counter it gets terminated by the callout; at this point the maintenance thread starts the termination routine. The first thread finishes waiting, proceeds to icl_conn_handoff(), and drops the refcount, which allows the maintenance thread to free its resources. At this point another thread receives a PDU. Boom. PR: 222898, 219866 Sponsored by: playkey.net Changes: _U stable/11/ stable/11/sys/cam/ctl/ctl_frontend_iscsi.c stable/11/sys/cam/ctl/ctl_frontend_iscsi.h |
