RE: scsi_set_medium_removal timeout issue

From: Zengtao (B)
Date: Tue Nov 13 2018 - 21:48:01 EST

Next message: Qian Cai: "BUG: KASAN: slab-out-of-bounds in try_to_unmap_one+0x1c4/0x1af0"
Previous message: Frederic Weisbecker: "[PATCH 16/25] sched/cputime: Allow to pass cputime index on user/guest accounting"
In reply to: Alan Stern: "RE: scsi_set_medium_removal timeout issue"
Next in thread: Alan Stern: "RE: scsi_set_medium_removal timeout issue"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hi Alan:

>-----Original Message-----
>From: Alan Stern [mailto:stern@xxxxxxxxxxxxxxxxxxx]
>Sent: Monday, November 12, 2018 11:33 PM
>To: Zengtao (B) <prime.zeng@xxxxxxxxxxxxx>
>Cc: jejb@xxxxxxxxxxxxxxxxxx; martin.petersen@xxxxxxxxxx;
>gregkh@xxxxxxxxxxxxxxxxxxx; linux-scsi@xxxxxxxxxxxxxxx;
>linux-kernel@xxxxxxxxxxxxxxx; linux-usb@xxxxxxxxxxxxxxx;
>usb-storage@xxxxxxxxxxxxxxxxxxxxxxxx
>Subject: RE: scsi_set_medium_removal timeout issue
>
>On Mon, 12 Nov 2018, Zengtao (B) wrote:
>
>> >> >Something is wrong here. Before sending PREVENT-ALLOW
>MEDIUM
>> >> >REMOVAL, the host should issue SYNCHRONIZE CACHE. This will
>force
>> >> >fsg_lun_fsync_sub to run, and the host should allow a long timeout
>> >> >for this command. Then when PREVENT-ALLOW MEDIUM
>REMOVAL
>> >is sent,
>> >> >nothing will need to be flushed.
>> >> >
>> >>
>> >> Definitely, I haven't seen the SYNCHRONIZE CACHE from the host, it
>> >> directly issued the PREVENT-ALLOW MEDIUM REMOVAL, so maybe
>> >something
>> >> wrong with the scsi layer or something wrong with the mass storage
>> >class driver?
>> >
>> >Or it could be something else. Can you please post the dmesg log
>> >from the host, showing what happens when the device is first plugged
>in?
>> >
>>
>> I have enabled the SCSI log for the host, please refer to the attachment.
>
>The log you attached was incomplete -- it was missing some commands

I just enabled the scsi log in the middle of the umount operation, otherwise I can't
reproduce the issue when the scsi log is enabled.

>from the beginning. In any case, it wasn't what I wanted. I asked you to
>post the dmesg log, not the SCSI log.

Please refer to the new attachment for dmesg log.

Thanks
Zengtao

~ # dmesg
Booting Linux on physical CPU 0x0
Linux version 4.9.37 (lpcheng@osdrv) (gcc version 6.3.0 (HC&C V100R002C00B021_20180917) ) #5 SMP Mon Nov 12 19:35:04 HKT 2018
CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
CPU: div instructions available: patching division code
CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
OF: fdt:Machine model: Hisilicon Hi3519AV100 SMP Board
cma: dma_contiguous_reserve(limit ffffffff)
cma: dma_contiguous_reserve: reserving 16 MiB for global area
cma: cma_declare_contiguous(size 0x01000000, base 0x00000000, limit 0xffffffff alignment 0x00000000)
cma: Reserved 16 MiB at 0x31000000
Memory policy: Data cache writealloc
On node 0 totalpages: 65536
free_area_init_node: node 0, pgdat c092d580, node_mem_map cedf1000
Normal zone: 512 pages used for memmap
Normal zone: 0 pages reserved
Normal zone: 65536 pages, LIFO batch:15
percpu: Embedded 13 pages/cpu @cedc6000 s22028 r8192 d23028 u53248
pcpu-alloc: s22028 r8192 d23028 u53248 alloc=13*4096
pcpu-alloc: [0] 0 [0] 1
Built 1 zonelists in Zone order, mobility grouping on. Total pages: 65024
Kernel command line: mem=256M console=ttyAMA0,115200 clk_ignore_unused root=/dev/mtdblock2 rw rootfstype=yaffs2 mtdparts=hinand:1M(boot),4M(kernel),60M(rootfs) nosmp
PID hash table entries: 1024 (order: 0, 4096 bytes)
Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Memory: 234544K/262144K available (5120K kernel code, 184K rwdata, 1368K rodata, 1024K init, 321K bss, 11216K reserved, 16384K cma-reserved, 0K highmem)
Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xd0800000 - 0xff800000 ( 752 MB)
lowmem : 0xc0000000 - 0xd0000000 ( 256 MB)
pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
.text : 0xc0008000 - 0xc0600000 (6112 kB)
.init : 0xc0800000 - 0xc0900000 (1024 kB)
.data : 0xc0900000 - 0xc092e180 ( 185 kB)
.bss : 0xc0930000 - 0xc098072c ( 322 kB)
SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
Hierarchical RCU implementation.
Build-time adjustment of leaf fanout to 32.
RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2.
RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=2
NR_IRQS:16 nr_irqs:16 16
arm_arch_timer: Architected cp15 timer(s) running at 24.00MHz (phys).
clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x588fe9dc0, max_idle_ns: 440795202592 ns
sched_clock: 56 bits at 24MHz, resolution 41ns, wraps every 4398046511097ns
Switching to timer-based delay loop, resolution 41ns
clocksource: hisp804: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 637086815595 ns
Console: colour dummy device 80x30
Calibrating delay loop (skipped), value calculated using timer frequency.. 48.00 BogoMIPS (lpj=120000)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Setting up static identity map for 0x22100000 - 0x22100058
Brought up 1 CPUs
SMP: Total of 1 processors activated (48.00 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 9556302231375000 ns
futex hash table entries: 512 (order: 3, 32768 bytes)
NET: Registered protocol family 16
cma: cma_alloc(cma c095e7a4, count 64, align 6)
cma: cma_alloc(): returned cefd1000
DMA: preallocated 256 KiB pool for atomic coherent allocations
Serial: AMBA PL011 UART driver
4540000.uart: ttyAMA0 at MMIO 0x4540000 (irq = 21, base_baud = 0) is a PL011 rev2
console [ttyAMA0] enabled
vgaarb: loaded
SCSI subsystem initialized
ssp-pl022 4570000.spi: ARM PL022 driver, device ID: 0x00800022
ssp-pl022 4570000.spi: mapped registers from 0x04570000 to d0855000
ssp-pl022 4571000.spi: ARM PL022 driver, device ID: 0x00800022
ssp-pl022 4571000.spi: mapped registers from 0x04571000 to d0857000
ssp-pl022 4572000.spi: ARM PL022 driver, device ID: 0x00800022
ssp-pl022 4572000.spi: mapped registers from 0x04572000 to d0859000
ssp-pl022 4573000.spi: ARM PL022 driver, device ID: 0x00800022
ssp-pl022 4573000.spi: mapped registers from 0x04573000 to d085b000
ssp-pl022 4574000.spi: ARM PL022 driver, device ID: 0x00800022
ssp-pl022 4574000.spi: mapped registers from 0x04574000 to d085d000
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
Linux video capture interface: v2.00
clocksource: Switched to clocksource hisp804
NET: Registered protocol family 2
TCP established hash table entries: 2048 (order: 1, 8192 bytes)
TCP bind hash table entries: 2048 (order: 2, 16384 bytes)
TCP: Hash tables configured (established 2048 bind 2048)
UDP hash table entries: 256 (order: 1, 8192 bytes)
UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
PCI: CLS 0 bytes, default 64
workingset: timestamp_bits=30 max_order=16 bucket_order=0
NFS: Registering the id_resolver key type
Key type id_resolver registered
Key type id_legacy registered
jffs2: version 2.2. (NAND) © 2001-2006 Red Hat, Inc.
fuse init (API version 7.26)
yaffs: yaffs Installing.
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
io scheduler noop registered
io scheduler deadline registered
io scheduler cfq registered (default)
pl061_gpio 45f0000.gpio_chip: PL061 GPIO chip @0x045f0000 registered
pl061_gpio 45f1000.gpio_chip: PL061 GPIO chip @0x045f1000 registered
pl061_gpio 45f2000.gpio_chip: PL061 GPIO chip @0x045f2000 registered
pl061_gpio 45f3000.gpio_chip: PL061 GPIO chip @0x045f3000 registered
pl061_gpio 45f4000.gpio_chip: PL061 GPIO chip @0x045f4000 registered
pl061_gpio 45f5000.gpio_chip: PL061 GPIO chip @0x045f5000 registered
pl061_gpio 45f6000.gpio_chip: PL061 GPIO chip @0x045f6000 registered
pl061_gpio 45f7000.gpio_chip: PL061 GPIO chip @0x045f7000 registered
pl061_gpio 45f8000.gpio_chip: PL061 GPIO chip @0x045f8000 registered
pl061_gpio 45f9000.gpio_chip: PL061 GPIO chip @0x045f9000 registered
pl061_gpio 45fa000.gpio_chip: PL061 GPIO chip @0x045fa000 registered
pl061_gpio 45fb000.gpio_chip: PL061 GPIO chip @0x045fb000 registered
pl061_gpio 45fc000.gpio_chip: PL061 GPIO chip @0x045fc000 registered
pl061_gpio 45fd000.gpio_chip: PL061 GPIO chip @0x045fd000 registered
pl061_gpio 45fe000.gpio_chip: PL061 GPIO chip @0x045fe000 registered
brd: module loaded
cma: cma_alloc(cma c095e7a4, count 2, align 1)
cma: cma_alloc(): returned cefd1800
hisi-sfc hisi_spi_nor.0: SPI Nor ID Table Version 1.2
hisi-sfc hisi_spi_nor.0: unrecognized Manufacturer ID
hisi-sfc hisi_spi_nor.0: spi nor register fail!
hisi-sfc: probe of hisi_spi_nor.0 failed with error -2
SPI Nand ID Table Version 2.7
SPI Nand(cs 0) ID: 0xc2 0x90
nand: device found, Manufacturer ID: 0xc2, Chip ID: 0x90
nand: Macronix MX35UF1G14AC
nand: 128MiB, SLC, page size: 2048
Nand(Auto):
OOB:64B
ECC:4bit/512
nand: ECC provided by Flash Memory Controller
3 cmdlinepart partitions found on MTD device hinand
Creating 3 MTD partitions on "hinand":
0x000000000000-0x000000100000 : "boot"
0x000000100000-0x000000500000 : "kernel"
0x000000500000-0x000004100000 : "rootfs"
libphy: hisi_gemac_mii_bus: probed
libphy: Fixed MDIO Bus: probed
hi_gmac_v200 40e0000.ethernet: invalid resource
hi_gmac_v200 40e0000.ethernet (unnamed net_device) (uninitialized): using random MAC address 7a:22:00:0d:bc:d9
attached PHY 1 to driver Generic PHY, PHY_ID=0x1cc916
cma: cma_alloc(cma c095e7a4, count 4, align 2)
cma: cma_alloc(): returned cefd1880
cma: cma_alloc(cma c095e7a4, count 4, align 2)
cma: cma_alloc(): returned cefd1900
cma: cma_alloc(cma c095e7a4, count 4, align 2)
cma: cma_alloc(): returned cefd1980
cma: cma_alloc(cma c095e7a4, count 4, align 2)
cma: cma_alloc(): returned cefd1a00
cma: cma_alloc(cma c095e7a4, count 4, align 2)
cma: cma_alloc(): returned cefd1a80
cma: cma_alloc(cma c095e7a4, count 4, align 2)
cma: cma_alloc(): returned cefd1b00
cma: cma_alloc(cma c095e7a4, count 4, align 2)
cma: cma_alloc(): returned cefd1b80
cma: cma_alloc(cma c095e7a4, count 43, align 6)
cma: cma_alloc(): returned cefd2000
Higmac dma_sg_phy: 0x31080000
ETH: rgmii, phy_addr=1
usbcore: registered new interface driver r8152
xhci-hcd 4120000.xhci_1: xHCI Host Controller
xhci-hcd 4120000.xhci_1: new USB bus registered, assigned bus number 1
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1840
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1860
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1c00
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1c20
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1c40
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1c60
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1c80
xhci-hcd 4120000.xhci_1: hcc params 0x0220fe6d hci version 0x110 quirks 0x00010010
xhci-hcd 4120000.xhci_1: irq 45, io mem 0x04120000
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 1 port detected
xhci-hcd 4120000.xhci_1: xHCI Host Controller
xhci-hcd 4120000.xhci_1: new USB bus registered, assigned bus number 2
usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
hub 2-0:1.0: USB hub found
hub 2-0:1.0: config failed, hub doesn't have any ports! (err -19)
usbcore: registered new interface driver usb-storage
mousedev: PS/2 mouse device common for all mice
usbcore: registered new interface driver xpad
hibvt_rtc 4550000.rtc: rtc core: registered 4550000.rtc as rtc0
hibvt_rtc 4550000.rtc: RTC driver for hibvt enabled
i2c /dev entries driver
hibvt-i2c 4560000.i2c: hibvt-i2c0@100000hz registered
hibvt-i2c 4561000.i2c: hibvt-i2c1@100000hz registered
hibvt-i2c 4562000.i2c: hibvt-i2c2@100000hz registered
hibvt-i2c 4563000.i2c: hibvt-i2c3@100000hz registered
hibvt-i2c 4564000.i2c: hibvt-i2c4@100000hz registered
hibvt-i2c 4565000.i2c: hibvt-i2c5@100000hz registered
hibvt-i2c 4566000.i2c: hibvt-i2c6@100000hz registered
hibvt-i2c 4567000.i2c: hibvt-i2c7@100000hz registered
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1ca0
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1cc0
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1ce0
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1d00
hibvt-i2c 4568000.i2c: hibvt-i2c8@100000hz registered
hibvt-i2c 4569000.i2c: hibvt-i2c9@100000hz registered
usbcore: registered new interface driver uvcvideo
USB Video Class driver (1.1.1)
sdhci: Secure Digital Host Controller Interface driver
sdhci: Copyright(c) Pierre Ossman
sdhci-pltfm: SDHCI platform and OF driver helper
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1d20
mmc0: SDHCI controller on 40c0000.SD [40c0000.SD] using ADMA 64-bit in legacy mode
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1d40
mmc1: 3.3V output did not became stable
usb 1-1: new high-speed USB device number 2 using xhci-hcd
mmc1: SDHCI controller on 40d0000.SD [40d0000.SD] using ADMA 64-bit in legacy mode
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
hivdmav100 driver inited.
NET: Registered protocol family 10
NET: Registered protocol family 17
8021q: 802.1Q VLAN Support v1.8
Key type dns_resolver registered
Registering SWP/SWPB emulation handler
mmc1: 3.3V output did not became stable
hibvt_rtc 4550000.rtc: setting system clock to 1970-01-01 12:55:13 UTC (46513)
clk: Not disabling unused clocks
uart-pl011 4540000.uart: no DMA platform data
yaffs: dev is 32505858 name is "mtdblock2" rw
yaffs: passed flags ""
yaffs: yaffs: Attempting MTD mount of 31.2,"mtdblock2"
yaffs: yaffs_read_super: is_checkpointed 1
VFS: Mounted root (yaffs2 filesystem) on device 31:2.
devtmpfs: mounted
Freeing unused kernel memory: 1024K (c0800000 - c0900000)
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1d60
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1d80
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1da0
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1dc0
usb-storage 1-1:1.0: USB Mass Storage device detected
mmc1: 3.3V output did not became stable
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1de0
usb-storage 1-1:1.0: Quirks match for vid 0525 pid a4a5: 10000
scsi host0: usb-storage 1-1:1.0
mmc1: 3.3V output did not became stable
udev[81]: starting version 167
scsi 0:0:0:0: Direct-Access Linux File-Stor Gadget 0409 PQ: 0 ANSI: 2
sd 0:0:0:0: [sda] 186368 512-byte logical blocks: (95.4 MB/91.0 MiB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Mode Sense: 0f 00 00 00
sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
sda: sda1
sd 0:0:0:0: [sda] Attached SCSI removable disk
random: fast init done
random: crng init done
usb 1-1: reset high-speed USB device number 2 using xhci-hcd
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1e00
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1e20
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1e40
cma: cma_alloc(cma c095e7a4, count 1, align 0)
cma: cma_alloc(): returned cefd1e60
sda: sda1

Next message: Qian Cai: "BUG: KASAN: slab-out-of-bounds in try_to_unmap_one+0x1c4/0x1af0"
Previous message: Frederic Weisbecker: "[PATCH 16/25] sched/cputime: Allow to pass cputime index on user/guest accounting"
In reply to: Alan Stern: "RE: scsi_set_medium_removal timeout issue"
Next in thread: Alan Stern: "RE: scsi_set_medium_removal timeout issue"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]