rescan-scsi-bus causes arcmsr death

Hi,

We're seeing an odd rare interaction between rescan-scsi-bus and arcmsr, which manifests as these log messages, then a hang/panic:

Feb  9 18:51:19 Space kernel: [ 2624.283565] arcmsr: abort scsi_cmnd(0xffff8807d06cc900), cmnd[0x8a,0x 0,0x 0,0x 0,0x 0,0x 1,0x 8,0xc0,0x2b,0xe8,0x 0,0x 0], scsi_id = 0x 0, scsi_lun = 0x 0.
Feb  9 18:51:19 Space kernel: [ 2624.283604] arcmsr0: to abort command(0xffff8807d06cc900), ccb = 0xffff881058b11180
Feb  9 18:51:21 Space kernel: [ 2625.924838] arcmsr0: abort ccb = 0xffff881058b11180 not done yet, do not force aborting command!

--- Snip many more ---

On the (seemingly less common) occasion that it panics rather than hangs, it looks like this:

Feb  9 11:55:05 Space kernel: [58801.943419] arcmsr9: abort scsi_cmnd(0xffff881027968900), cmnd[0x 0,0x 0,0x 0,0x 0,0x 0,0x 0,0x 0,0x 0,0x 0,0x 0,0x 0,0x 0], scsi_id = 0x 0, scsi_lun = 0x 0.
Feb  9 11:55:05 Space kernel: [58801.943427] arcmsr9: to abort command(0xffff881027968900), ccb = 0xffff88085864a580
Feb  9 11:55:05 Space kernel: [58801.943429] arcmsr9: scsi id = 0 lun = 0 ccb = '0xffff88085864a580' polling a done ccb, abort successfully
Feb  9 11:55:05 Space kernel: [58801.943460] BUG: scheduling while atomic: ksoftirqd/19/85/0x00000100
Feb  9 11:55:05 Space kernel: [58801.943463] Modules linked in: xfs libcrc32c mlx4_ib ib_sa ib_mad ib_core ib_addr mlx4_en mlx4_core myri10ge bonding target_core_mod configfs ip6table_filter ip6_tables iptable_filter ip_tables ebtable_nat ebtables x_tables dm_crypt ipmi_ssif x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd sb_edac microcode edac_core lpc_ich ioatdma tpm_tis ipmi_si ipmi_msghandler 8250_fintek mac_hid nfsd auth_rpcgss pcspkr nfs_acl nfs lockd grace sunrpc fscache ext2 mlx5_core raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq raid1 raid0 multipath linear vxlan ip6_udp_tunnel udp_tunnel bcache hid_generic igb isci usbhid i2c_algo_bit libsas ahci dca hid libahci ptp scsi_transport_sas pps_core arcmsr(OE) [last unloaded: mlx4_core]
Feb  9 11:55:05 Space kernel: [58801.943511] CPU: 19 PID: 85 Comm: ksoftirqd/19 Tainted: G           OE  3.19.0-21-spacev3 #160915
Feb  9 11:55:05 Space kernel: [58801.943512] Hardware name: GBLabs Space+/X9DRH-7TF/7F/iTF/iF, BIOS 3.2  06/04/2015
Feb  9 11:55:05 Space kernel: [58801.943514]  ffff88105bd13a08 ffff88105bd13948 ffffffffaf6e521c 0000000000000000
Feb  9 11:55:05 Space kernel: [58801.943516]  ffff88107fcf29c0 ffff88105bd13958 ffffffffaf6dfa07 ffff88105bd139c8
Feb  9 11:55:05 Space kernel: [58801.943517]  ffffffffaf6e84fc ffff88105bcb41a0 00000000000129c0 ffff88105bd13fd8
Feb  9 11:55:05 Space kernel: [58801.943519] Call Trace:
Feb  9 11:55:05 Space kernel: [58801.943528]  [<ffffffffaf6e521c>] dump_stack+0x45/0x57
Feb  9 11:55:05 Space kernel: [58801.943533]  [<ffffffffaf6dfa07>] __schedule_bug+0x4b/0x59
Feb  9 11:55:05 Space kernel: [58801.943535]  [<ffffffffaf6e84fc>] __schedule+0x75c/0x780
Feb  9 11:55:05 Space kernel: [58801.943537]  [<ffffffffaf6e8549>] schedule+0x29/0x70
Feb  9 11:55:05 Space kernel: [58801.943540]  [<ffffffffaf6eb45b>] schedule_timeout+0x10b/0x210
Feb  9 11:55:05 Space kernel: [58801.943544]  [<ffffffffaf0b0180>] ? internal_add_timer+0x80/0x80
Feb  9 11:55:05 Space kernel: [58801.943546]  [<ffffffffaf0b14e7>] msleep+0x37/0x50
Feb  9 11:55:05 Space kernel: [58801.943552]  [<ffffffffc0342af2>] arcmsr_queue_command+0x82/0xf40 [arcmsr]
Feb  9 11:55:05 Space kernel: [58801.943553]  [<ffffffffaf6e2637>] ? __slab_free+0x101/0x2c1
Feb  9 11:55:05 Space kernel: [58801.943555]  [<ffffffffaf6e2637>] ? __slab_free+0x101/0x2c1
Feb  9 11:55:05 Space kernel: [58801.943561]  [<ffffffffaf4bae0f>] scsi_dispatch_cmd+0xaf/0x310
Feb  9 11:55:05 Space kernel: [58801.943563]  [<ffffffffaf4bdca0>] scsi_request_fn+0x4f0/0x7e0
Feb  9 11:55:05 Space kernel: [58801.943566]  [<ffffffffaf31ecf7>] __blk_run_queue+0x37/0x50
Feb  9 11:55:05 Space kernel: [58801.943568]  [<ffffffffaf31ed86>] blk_run_queue+0x26/0x40
Feb  9 11:55:05 Space kernel: [58801.943570]  [<ffffffffaf4ba970>] scsi_run_queue+0x230/0x2d0
Feb  9 11:55:05 Space kernel: [58801.943572]  [<ffffffffaf4b311d>] ? scsi_put_command+0x7d/0xd0
Feb  9 11:55:05 Space kernel: [58801.943575]  [<ffffffffaf4bb992>] scsi_end_request+0x142/0x1e0
Feb  9 11:55:05 Space kernel: [58801.943576]  [<ffffffffaf4be119>] scsi_io_completion+0x109/0x6b0
Feb  9 11:55:05 Space kernel: [58801.943578]  [<ffffffffaf4b36ff>] scsi_finish_command+0xcf/0x130
Feb  9 11:55:05 Space kernel: [58801.943580]  [<ffffffffaf4bd787>] scsi_softirq_done+0x137/0x160
Feb  9 11:55:05 Space kernel: [58801.943583]  [<ffffffffaf328f13>] blk_done_softirq+0x83/0xa0
Feb  9 11:55:05 Space kernel: [58801.943587]  [<ffffffffaf060aa4>] __do_softirq+0xe4/0x270
Feb  9 11:55:05 Space kernel: [58801.943588]  [<ffffffffaf060c59>] run_ksoftirqd+0x29/0x40
Feb  9 11:55:05 Space kernel: [58801.943593]  [<ffffffffaf07d7f3>] smpboot_thread_fn+0x143/0x1b0
Feb  9 11:55:05 Space kernel: [58801.943596]  [<ffffffffaf07d6b0>] ? SyS_setgroups+0x180/0x180
Feb  9 11:55:05 Space kernel: [58801.943598]  [<ffffffffaf079a02>] kthread+0xd2/0xf0
Feb  9 11:55:05 Space kernel: [58801.943600]  [<ffffffffaf079930>] ? kthread_create_on_node+0x1c0/0x1c0
Feb  9 11:55:05 Space kernel: [58801.943602]  [<ffffffffaf6ec618>] ret_from_fork+0x58/0x90
Feb  9 11:55:05 Space kernel: [58801.943604]  [<ffffffffaf079930>] ? kthread_create_on_node+0x1c0/0x1c0

We originally saw this in the wild very rarely, but have now replicated it fairly reliably on an internal test system. The basic overview seems to be:
1) Start an ton of simultaneous rescan-scsi-bus processes in a loop.
2) Apply a large load to the block device. It doesn't seem to matter exactly what this load is, but anecdotally the error seems to occur more quickly when reading/writing lots of small files rather than a few big files.
3) ???
4) arcmsr shits the bed.

This has happened on a few different software/hardware flavours out in the field, but on this particular test system we're using:
- kernel 3.19
- arcmsr v1.30.0X.20-20150342 (notably we've also seen this on
v1.30.0X.27-20170206 in the field)
- ARC-1883LP Raid Controller
- Supermicro 12G SAS Backplane
- 8x Samsung SAS SSDs (MZILS480HCGR/003)

Other details:
- There seems to be about ~30 gap where the entire system hangs just
before the arcmsr abort errors show up in the logs.
- Previously (and out in the field) we have LVM in the storage stack
(BD -> LVM -> XFS), but we've also replicated this with just XFS (or EXT4) directly on the BD.

Any ideas?

Many thanks,
- Alex.

Alex Richman
[email protected]

(+Ching Huang)

A SCSI .queuecommand() implementation must not sleep so I think this is a driver bug. Since I'm not familiar with the arcmsr driver I have CC'ed Ching Huang. I hope that he will be able to help you.

Bart.

Please try to reproduce with the current 4.16 kernel.
The arcmsr driver has been modified a bit so it's not that easy to match the log to the current driver.

Cheers,

Hannes

Dr. Hannes Reinecke		   Teamlead Storage & Networking
[email protected]			               +49 911 74053 688
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: F. Imendörffer, J. Smithard, J. Guild, D. Upmanyu, G. Norton
HRB 21284 (AG Nürnberg)