------- Comment From dnban...@us.ibm.com 2018-04-24 10:52 EDT-------
<continuing from #169>
Obviously this corruption happened a while ago. I poked around a
bit to see if there is any smoking gun around but nothing that
meets the eye. Since we have been seeing all this in the context
of other qla2xxx issues (where there were trails), I tried to see
if we can find those actors here. And indeed they are in this
scene too:
PID: 1085 TASK: c000200e48e2e000 CPU: 94 COMMAND: "kworker/94:1"
#0 [c000200e48de7940] __schedule at c000000000d05d24
#1 [c000200e48de7a10] schedule at c000000000d065b0
#2 [c000200e48de7a30] schedule_timeout at c000000000d0b3d0
#3 [c000200e48de7b30] msleep at c0000000001b5e2c
#4 [c000200e48de7b60] qlt_free_session_done at c00800000ef1faf0 [qla2xxx]
#5 [c000200e48de7c90] process_one_work at c000000000132bd8
#6 [c000200e48de7d20] worker_thread at c000000000132f78
#7 [c000200e48de7dc0] kthread at c00000000013bba8
#8 [c000200e48de7e30] ret_from_kernel_thread at c00000000000b528
PID: 1750 TASK: c000200e4daf3c00 CPU: 94 COMMAND: "kworker/94:2"
#0 [c000200e4db17940] __schedule at c000000000d05d24
#1 [c000200e4db17a10] schedule at c000000000d065b0
#2 [c000200e4db17a30] schedule_timeout at c000000000d0b3d0
#3 [c000200e4db17b30] msleep at c0000000001b5e2c
#4 [c000200e4db17b60] qlt_free_session_done at c00800000ef1faf0 [qla2xxx]
#5 [c000200e4db17c90] process_one_work at c000000000132bd8
#6 [c000200e4db17d20] worker_thread at c000000000132f78
#7 [c000200e4db17dc0] kthread at c00000000013bba8
#8 [c000200e4db17e30] ret_from_kernel_thread at c00000000000b528
PID: 3937 TASK: c000200e3b1a3f00 CPU: 94 COMMAND: "kworker/94:3"
#0 [c000200e3b2f3940] __schedule at c000000000d05d24
#1 [c000200e3b2f3a10] schedule at c000000000d065b0
#2 [c000200e3b2f3a30] schedule_timeout at c000000000d0b3d0
#3 [c000200e3b2f3b30] msleep at c0000000001b5e2c
#4 [c000200e3b2f3b60] qlt_free_session_done at c00800000ef1faf0 [qla2xxx]
#5 [c000200e3b2f3c90] process_one_work at c000000000132bd8
#6 [c000200e3b2f3d20] worker_thread at c000000000132f78
#7 [c000200e3b2f3dc0] kthread at c00000000013bba8
#8 [c000200e3b2f3e30] ret_from_kernel_thread at c00000000000b528
While they are all sleeping on cpu 94's worker threads, they do
belong to different fc_ports. However, their existence and
their propensity to cause issues because of the way they can be
scheduled does give pause for thought.
While I didn't want to be tunnel visioned w.r.t. free_work/del_work
issues we have seen elsewhere for qla2xxx, I did want to include
the information for completeness. And also, we haven't seen this
with the patch encoding the initial expt w.r.t (free_/del_)work
described in #132.
I then decided to take a look at the bug again, back in history.
And then this thing caught my eye! It was captured in a log by
Indira.
[31751.586142] Sending NMI from CPU 104 to CPUs 1:
[31751.586257] NMI backtrace for cpu 1
[31751.586260] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.15.0-15-generic
#16-Ubuntu
[31751.586262] NIP: c0000000000a40b4 LR: c0000000000a40b4 CTR: c000000000008000
[31751.586264] REGS: c000000ff91bbc40 TRAP: 0100 Not tainted
(4.15.0-15-generic)
[31751.586265] MSR: 9000000000001033 <SF,HV,ME,IR,DR,RI,LE> CR: 24004482
XER: 00000000
[31751.586270] CFAR: c000000ff91bbda0 SOFTE: -4611685949823549440
[31751.586270] GPR00: c0000000000a40b4 c000000ff91bbda0 c0000000016eb400
c000000ff91bbc40
[31751.586270] GPR04: b000000000cpu 0x79: Vector: 700 (Program Check) at
[c000200e5831b450]
pc: c00000000038ba38: kmem_cache_free+0xc8/0x2b0
lr: c0000000002dfd4c: mempool_free_slab+0x2c/0x40
sp: c000200e5831b6d0
msr: 9000000000029033
current = 0xc000200e58205c00
paca = 0xc000000007a73300 softe: 0 irq_happened: 0x01
pid = 0, comm = swapper/121
kernel BUG at /build/linux-QzAGR9/linux-4.15.0/mm/slub.c:296!
Linux version 4.15.0-15-generic (buildd@bos02-ppc64el-002) (gcc version 7.3.0
(Ubuntu 7.3.0-14ubuntu1)) #16-Ubuntu SMP Wed Apr 4 13:57:51 UTC 2018 (Ubuntu
4.15.0-15.16-generic 4.15.15)
cpu 0x9: Vector: 100 (System Reset) at [c000000007f39d80]
pc: c0000000000ed874: kvmppc_got_guest+0x1cc/0x380
lr: c0000000000ed7f0: kvmppc_got_guest+0x148/0x380
sp: c00000042754f4d0
msr: 9000000102883003
current = 0xc0000003a3e87300
paca = 0xc000000007a26300 softe: 0 irq_happened: 0x01
pid = 33539, comm = CPU 3/KVM
Linux version 4.15.0-15-generic (buildd@bos02-ppc64el-002) (gcc version 7.3.0
(Ubuntu 7.3.0-14ubuntu1)) #16-Ubuntu SMP Wed Apr 4 13:57:51 UTC 2018 (Ubuntu
4.15.0-15.16-generic 4.15.15)
cpu 0x22: Vector: 100 (System Reset) at [c000000007e0dd80]
pc: c0000000000eddb8: mc_cont+0x38/0x13c
lr: c0000000000ee5b0: hcall_try_real_mode+0x60/0x7c
sp: c0000004275374d0
msr: 9000000000081033
current = 0xc0000003a3eb8100
paca = 0xc000000007a37600 softe: 0 irq_happened: 0x01
pid = 33540, comm = CPU 4/KVM
Linux version 4.15.0-15-generic (buildd@bos02-ppc64el-002) (gcc version 7.3.0
(Ubuntu 7.3.0-14ubuntu1)) #16-Ubuntu SMP Wed Apr 4 13:57:51 UTC 2018 (Ubuntu
4.15.0-15.16-generic 4.15.15)
cpu 0x31: Vector: 100 (System Reset) at [c000000007d59d80]
pc: c0000000000ed8a8: kvmppc_got_guest+0x200/0x380
lr: c0000000000ed7f0: kvmppc_got_guest+0x148/0x380
sp: c00000048c9c34d0
msr: 9000000102883003
current = 0xc000000429a12b00
paca = 0xc000000007a41b00 softe: 0 irq_happened: 0x01
pid = 33549, comm = CPU 13/KVM
Linux version 4.15.0-15-generic (buildd@bos02-ppc64el-002) (gcc version 7.3.0
(Ubuntu 7.3.0-14ubuntu1)) #16-Ubuntu SMP Wed Apr 4 13:57:51 UTC 2018 (Ubuntu
4.15.0-15.16-generic 4.15.15)
enter ? for help
[c000200e5831b750] c0000000002dfd4c mempool_free_slab+0x2c/0x40
[c000200e5831b770] c0000000002dfc2c mempool_free+0x5c/0x110
[c000200e5831b7b0] c00800000ee9f2c0 qla2x00_sp_free+0x78/0xa0 [qla2xxx]
[c000200e5831b7e0] c00800000ee9f200 qla2x00_sp_timeout+0x98/0xe0 [qla2xxx]
[c000200e5831b820] c0000000001b46b0 call_timer_fn+0x50/0x1c0
[c000200e5831b8a0] c0000000001b4958 expire_timers+0x138/0x1f0
[c000200e5831b910] c0000000001b4b18 run_timer_softirq+0x108/0x270
[c000200e5831b9b0] c000000000d0d6c8 __do_softirq+0x158/0x3e4
[c000200e5831ba90] c000000000114be8 irq_exit+0xe8/0x120
[c000200e5831bab0] c000000000024d0c timer_interrupt+0x9c/0xe0
[c000200e5831bae0] c000000000009014 decrementer_common+0x114/0x120
--- Exception: 901 (Decrementer) at c00000000000a724
replay_interrupt_return+0x0/0x4
[link register ] c000000000016e74 arch_local_irq_restore+0x74/0x90
[c000200e5831bdd0] 0000000000000079 (unreliable)
[c000200e5831bdf0] c000000000acf0b0 cpuidle_enter_state+0xf0/0x450
[c000200e5831be50] c00000000017239c call_cpuidle+0x4c/0x90
[c000200e5831be70] c0000000001727b0 do_idle+0x2b0/0x330
[c000200e5831bec0] c000000000172a68 cpu_startup_entry+0x38/0x50
[c000200e5831bef0] c000000000049db0 start_secondary+0x4f0/0x510
[c000200e5831bf90] c00000000000aa6c start_secondary_prolog+0x10/0x14
And the trap happened because of the following:
BUG_ON(object == fp); /* naive detection of double free or corruption */
So qla2x00_sp_timeout
-> qla2x00_sp_free
-> qla2x00_rel_sp
-> mempool_free(sp, sp->vha->hw->srb_mempool)
has a double free problem!!!
The sp (i.e. srb_t) double free will likely corrupt the
corresponding kmem cache.
It is easy to think of a scenario:
-- T1 frees sp
-- T2 thinks sp is valid and performs operations on it say
increment by 1
-- T2 tries to free sp (double free) and CRASH!
qla2x00_get_sp
-> sp = mempool_alloc(vha->hw->srb_mempool, flag)
qla2x00_mem_alloc
-> ha->srb_mempool = mempool_create_slab_pool(SRB_MIN_REQ, srb_cachep)
In cases where this kind of execution goes untrapped. We were
extremely lucky to get this break in #25 where the new free matched
the free head, i.e. it was barely released. Had slub debug been ON
at that time and we had a dump/log we likely would have info about
who had released it. this will effectively corrupt the freelist
just as we observed in this crash.
>From the code it looks like the sp is allocated & the timer started
for several operations with generally similar formats. Example:
qla2x00_async_login
sp = qla2x00_get_sp(vha, fcport, GFP_KERNEL)
-> sp = mempool_alloc(vha->hw->srb_mempool, flag
sp->type = SRB_LOGIN_CMD
sp->name = "login";
qla2x00_init_timer(sp, qla2x00_get_async_timeout(vha) + 2);
lio = &sp->u.iocb_cmd;
lio->timeout = qla2x00_async_iocb_timeout;
sp->done = qla2x00_async_login_sp_done
rval = qla2x00_start_sp(sp)
return rval
if error
sp->free(sp)
return rval
It'd appear that there is at least one scenario where the timer is
started for an operation and after that for whatever reason the
sp is freed. When the timer pops, it deletes the timer entry
and tries to free the (already freed) sp and crashes.
Unfortunately, the instance in #25 didn't capture enough data
to point to the parallel path.
------- Comment From dnban...@us.ibm.com 2018-04-24 10:57 EDT-------
At this point, I decided to search to see if any double free issues
have been observed for this driver (possibly for this structure
srb_t i.e. sp) and came across the following.
commit eaf75d1815dad230dac2f1e8f1dc0349b2d50071
Author: Quinn Tran <quinn.t...@cavium.com>
Date: Thu Feb 1 10:33:17 2018 -0800
scsi: qla2xxx: Fix double free bug after firmware timeout
This patch is based on Max's original patch.
When the qla2xxx firmware is unavailable, eventually
qla2x00_sp_timeout() is reached, which calls the timeout function and
frees the srb_t instance.
The timeout function always resolves to qla2x00_async_iocb_timeout(),
which invokes another callback function called "done". All of these
qla2x00_*_sp_done() callbacks also free the srb_t instance; after
returning to qla2x00_sp_timeout(), it is freed again.
The fix is to remove the "sp->free(sp)" call from qla2x00_sp_timeout()
and add it to those code paths in qla2x00_async_iocb_timeout() which
do not already free the object.
This is how it looks like with KASAN:
BUG: KASAN: use-after-free in qla2x00_sp_timeout+0x228/0x250
Read of size 8 at addr ffff88278147a590 by task swapper/2/0
Allocated by task 1502:
save_stack+0x33/0xa0
kasan_kmalloc+0xa0/0xd0
kmem_cache_alloc+0xb8/0x1c0
mempool_alloc+0xd6/0x260
qla24xx_async_gnl+0x3c5/0x1100
Freed by task 0:
save_stack+0x33/0xa0
kasan_slab_free+0x72/0xc0
kmem_cache_free+0x75/0x200
qla24xx_async_gnl_sp_done+0x556/0x9e0
qla2x00_async_iocb_timeout+0x1c7/0x420
qla2x00_sp_timeout+0x16d/0x250
call_timer_fn+0x36/0x200
The buggy address belongs to the object at ffff88278147a440
which belongs to the cache qla2xxx_srbs of size 344
The buggy address is located 336 bytes inside of
344-byte region [ffff88278147a440, ffff88278147a598)
Reported-by: Max Kellermann <m...@cm4all.com>
Signed-off-by: Quinn Tran <quinn.t...@cavium.com>
Signed-off-by: Himanshu Madhani <himanshu.madh...@cavium.com>
Cc: Max Kellermann <m...@cm4all.com>
Signed-off-by: Martin K. Petersen <martin.peter...@oracle.com>
diff --git a/drivers/scsi/qla2xxx/qla_init.c b/drivers/scsi/qla2xxx/qla_init.c
index aececf66..2dea112 100644
--- a/drivers/scsi/qla2xxx/qla_init.c
+++ b/drivers/scsi/qla2xxx/qla_init.c
@@ -59,8 +59,6 @@ static void qla24xx_handle_prli_done_event(struct
scsi_qla_host *,
req->outstanding_cmds[sp->handle] = NULL;
iocb = &sp->u.iocb_cmd;
iocb->timeout(sp);
- if (sp->type != SRB_ELS_DCMD)
- sp->free(sp);
spin_unlock_irqrestore(&vha->hw->hardware_lock, flags);
}
@@ -102,7 +100,6 @@ static void qla24xx_handle_prli_done_event(struct
scsi_qla_host *,
srb_t *sp = data;
fc_port_t *fcport = sp->fcport;
struct srb_iocb *lio = &sp->u.iocb_cmd;
- struct event_arg ea;
if (fcport) {
ql_dbg(ql_dbg_disc, fcport->vha, 0x2071,
@@ -117,25 +114,13 @@ static void qla24xx_handle_prli_done_event(struct
scsi_qla_host *,
switch (sp->type) {
case SRB_LOGIN_CMD:
- if (!fcport)
- break;
/* Retry as needed. */
lio->u.logio.data[0] = MBS_COMMAND_ERROR;
lio->u.logio.data[1] = lio->u.logio.flags & SRB_LOGIN_RETRIED ?
QLA_LOGIO_LOGIN_RETRIED : 0;
- memset(&ea, 0, sizeof(ea));
- ea.event = FCME_PLOGI_DONE;
- ea.fcport = sp->fcport;
- ea.data[0] = lio->u.logio.data[0];
- ea.data[1] = lio->u.logio.data[1];
- ea.sp = sp;
- qla24xx_handle_plogi_done_event(fcport->vha, &ea);
+ sp->done(sp, QLA_FUNCTION_TIMEOUT);
break;
case SRB_LOGOUT_CMD:
- if (!fcport)
- break;
- qlt_logo_completion_handler(fcport, QLA_FUNCTION_TIMEOUT);
- break;
case SRB_CT_PTHRU_CMD:
case SRB_MB_IOCB:
case SRB_NACK_PLOGI:
@@ -235,12 +220,10 @@ static void qla24xx_handle_prli_done_event(struct
scsi_qla_host *,
qla2x00_async_logout_sp_done(void *ptr, int res)
{
srb_t *sp = ptr;
- struct srb_iocb *lio = &sp->u.iocb_cmd;
sp->fcport->flags &= ~(FCF_ASYNC_SENT | FCF_ASYNC_ACTIVE);
- if (!test_bit(UNLOADING, &sp->vha->dpc_flags))
- qla2x00_post_async_logout_done_work(sp->vha, sp->fcport,
- lio->u.logio.data);
+ sp->fcport->login_gen++;
+ qlt_logo_completion_handler(sp->fcport, res);
sp->free(sp);
}
This patch needs to be pulled in too to address the double free issue we have
seen. One can hope that this (and the others) will cover the kmem cache
corruption we have seen as well since such kmem cache corruption can
clearly be a consequence of data access after free and double free.
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1762844
Title:
ISST-LTE:KVM:Ubuntu1804:BostonLC:boslcp3: Host crashed & enters into
xmon after moving to 4.15.0-15.16 kernel
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu-power-systems/+bug/1762844/+subscriptions
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
