On Thu, 2018-02-08 at 07:39 -0800, [email protected] wrote:
> On Thu, Feb 08, 2018 at 01:09:57AM +0000, Bart Van Assche wrote:
> > On Wed, 2018-02-07 at 23:48 +0000, Bart Van Assche wrote:
> > > With this patch applied I see requests for which it seems like the
> > > timeout handler
> > > did not get invoked: [ ... ]
> >
> > I just noticed the following in the system log, which is probably the
> > reason why some
> > requests got stuck:
> >
> > Feb 7 15:16:26 ubuntu-vm kernel: BUG: unable to handle kernel NULL pointer
> > dereference at (null)
> > Feb 7 15:16:26 ubuntu-vm kernel: IP: scsi_times_out+0x17/0x2c0 [scsi_mod]
> > Feb 7 15:16:26 ubuntu-vm kernel: PGD 0 P4D 0
> > Feb 7 15:16:26 ubuntu-vm kernel: Oops: 0000 [#1] PREEMPT SMP
> > Feb 7 15:16:26 ubuntu-vm kernel: Modules linked in: dm_service_time ib_srp
> > libcrc32c crc32c_generic scsi_transport_srp target_core_pscsi
> > target_core_file ib_srpt target_core_iblock
> > target_core_mod
> > rdma_rxe ip6_udp_tunnel udp_tunnel ib_umad ib_uverbs scsi_debug brd
> > mq_deadline kyber_iosched deadline_iosched cfq_iosched bfq crct10dif_pclmul
> > crc32_pclmul af_packet ghash_clmulni_intel pcbc
> > aesni_intel aes_x86_64 crypto_simd cryptd glue_helper serio_raw
> > virtio_console virtio_balloon sg button i2c_piix4 dm_multipath dm_mod dax
> > scsi_dh_rdac scsi_dh_emc scsi_dh_alua ib_iser rdma_cm
> > iw_cm
> > ib_cm ib_core configfs iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi
> > ip_tables x_tables ipv6 autofs4 ext4 crc16 mbcache jbd2 sd_mod virtio_net
> > virtio_blk virtio_scsi sr_mod cdrom
> > ata_generic
> > pata_acpi psmouse crc32c_intel i2c_core atkbd
> > Feb 7 15:16:26 ubuntu-vm kernel: uhci_hcd ehci_hcd intel_agp ata_piix
> > intel_gtt agpgart libata virtio_pci usbcore virtio_ring virtio scsi_mod
> > usb_common unix
> > Feb 7 15:16:26 ubuntu-vm kernel: CPU: 0 PID: 146 Comm: kworker/0:1H Not
> > tainted 4.15.0-dbg+ #1
> > Feb 7 15:16:26 ubuntu-vm kernel: Hardware name: QEMU Standard PC (i440FX +
> > PIIX, 1996), BIOS 1.0.0-prebuilt.qemu-project.org 04/01/2014
> > Feb 7 15:16:26 ubuntu-vm kernel: Workqueue: kblockd blk_mq_timeout_work
> > Feb 7 15:16:26 ubuntu-vm kernel: RIP: 0010:scsi_times_out+0x17/0x2c0
> > [scsi_mod]
> > Feb 7 15:16:26 ubuntu-vm kernel: RSP: 0018:ffff98f0c02abd58 EFLAGS:
> > 00010246
> > Feb 7 15:16:26 ubuntu-vm kernel: RAX: 0000000000000000 RBX:
> > ffff965de2b3a2c0 RCX: 0000000000000000
> > Feb 7 15:16:26 ubuntu-vm kernel: RDX: ffffffffc0094740 RSI:
> > 0000000000000000 RDI: ffff965de2b3a2c0
> > Feb 7 15:16:26 ubuntu-vm kernel: RBP: ffff965de2b3a438 R08:
> > fffffffffffffffc R09: 0000000000000007
> > Feb 7 15:16:26 ubuntu-vm kernel: R10: 0000000000000000 R11:
> > 0000000000000000 R12: 0000000000000002
> > Feb 7 15:16:26 ubuntu-vm kernel: R13: 0000000000000000 R14:
> > ffff965de2a44218 R15: ffff965de2a48728
> > Feb 7 15:16:26 ubuntu-vm kernel: FS: 0000000000000000(0000)
> > GS:ffff965dffc00000(0000) knlGS:0000000000000000
> > Feb 7 15:16:26 ubuntu-vm kernel: CS: 0010 DS: 0000 ES: 0000 CR0:
> > 0000000080050033
> > Feb 7 15:16:26 ubuntu-vm kernel: CR2: 0000000000000000 CR3:
> > 000000003ce0f003 CR4: 00000000003606f0
> > Feb 7 15:16:26 ubuntu-vm kernel: DR0: 0000000000000000 DR1:
> > 0000000000000000 DR2: 0000000000000000
> > Feb 7 15:16:26 ubuntu-vm kernel: DR3: 0000000000000000 DR6:
> > 00000000fffe0ff0 DR7: 0000000000000400
> > Feb 7 15:16:26 ubuntu-vm kernel: Call Trace:
> > Feb 7 15:16:26 ubuntu-vm kernel: blk_mq_terminate_expired+0x42/0x80
> > Feb 7 15:16:26 ubuntu-vm kernel: bt_iter+0x3d/0x50
> > Feb 7 15:16:26 ubuntu-vm kernel: blk_mq_queue_tag_busy_iter+0xe9/0x200
> > Feb 7 15:16:26 ubuntu-vm kernel: blk_mq_timeout_work+0x181/0x2e0
> > Feb 7 15:16:26 ubuntu-vm kernel: process_one_work+0x21c/0x6d0
> > Feb 7 15:16:26 ubuntu-vm kernel: worker_thread+0x35/0x380
> > Feb 7 15:16:26 ubuntu-vm kernel: kthread+0x117/0x130
> > Feb 7 15:16:26 ubuntu-vm kernel: ret_from_fork+0x24/0x30
> > Feb 7 15:16:26 ubuntu-vm kernel: Code: ff ff 0f ff e9 fd fe ff ff 90 66 2e
> > 0f 1f 84 00 00 00 00 00 41 55 41 54 55 48 8d af 78 01 00 00 53 48 8b 87 b0
> > 01 00 00 48 89 fb <4c> 8b 28 0f 1f 44 00 00
> > 65
> > 8b 05 6a b5 f8 3f 83 f8 0f 0f 87 ed
> > Feb 7 15:16:26 ubuntu-vm kernel: RIP: scsi_times_out+0x17/0x2c0 [scsi_mod]
> > RSP: ffff98f0c02abd58
> > Feb 7 15:16:26 ubuntu-vm kernel: CR2: 0000000000000000
> > Feb 7 15:16:26 ubuntu-vm kernel: ---[ end trace ce6c20d95bab450e ]---
>
> So, that's dereferencing %rax which is NULL. That gotta be the ->host
> deref in the following.
>
> enum blk_eh_timer_return scsi_times_out(struct request *req)
> {
> struct scsi_cmnd *scmd = blk_mq_rq_to_pdu(req);
> enum blk_eh_timer_return rtn = BLK_EH_NOT_HANDLED;
> struct Scsi_Host *host = scmd->device->host;
> ...
>
> That sounds more like a scsi hotplug bug than an issue in the timeout
> code unless we messed up @req pointer to begin with.
I don't think that this is related to SCSI hotplugging: this crash does not
occur with the v4.15 block layer core and it does not occur with my timeout
handler rework patch applied either. I think that means that we cannot
exclude the block layer core timeout handler rework as a possible cause.
The disassembler output is as follows:
(gdb) disas /s scsi_times_out
Dump of assembler code for function scsi_times_out:
drivers/scsi/scsi_error.c:
282 {
0x0000000000005bd0 <+0>: push %r13
0x0000000000005bd2 <+2>: push %r12
0x0000000000005bd4 <+4>: push %rbp
./include/linux/blk-mq.h:
300 return rq + 1;
0x0000000000005bd5 <+5>: lea 0x178(%rdi),%rbp
drivers/scsi/scsi_error.c:
282 {
0x0000000000005bdc <+12>: push %rbx
283 struct scsi_cmnd *scmd = blk_mq_rq_to_pdu(req);
284 enum blk_eh_timer_return rtn = BLK_EH_NOT_HANDLED;
285 struct Scsi_Host *host = scmd->device->host;
0x0000000000005bdd <+13>: mov 0x1b0(%rdi),%rax
282 {
0x0000000000005be4 <+20>: mov %rdi,%rbx
283 struct scsi_cmnd *scmd = blk_mq_rq_to_pdu(req);
284 enum blk_eh_timer_return rtn = BLK_EH_NOT_HANDLED;
285 struct Scsi_Host *host = scmd->device->host;
0x0000000000005be7 <+23>: mov (%rax),%r13
0x0000000000005bea <+26>: nopl 0x0(%rax,%rax,1)
[ ... ]
(gdb) print /x sizeof(struct request)
$2 = 0x178
(gdb) print &(((struct scsi_cmnd*)0)->device)
$4 = (struct scsi_device **) 0x38 <scsi_cmd_get_serial+8>
(gdb) print &(((struct scsi_device*)0)->host)
$5 = (struct Scsi_Host **) 0x0
The crash is reported at address scsi_times_out+0x17 == scsi_times_out+23. The
instruction at that address tries to dereference scsi_cmnd.device (%rax). The
register dump shows that that pointer has the value NULL. The only function I
know of that clears the scsi_cmnd.device pointer is scsi_req_init(). The only
caller of that function in the SCSI core is scsi_initialize_rq(). That function
has two callers, namely scsi_init_command() and blk_get_request(). However,
the scsi_cmnd.device pointer is not cleared when a request finishes. This is
why I think that the above crash report indicates that scsi_times_out() was
called for a request that was being reinitialized and not by device hotplugging.
Thanks,
Bart.
