Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

external USB drive: blk_update_request: I/O error and the USB drive gets another /dev/sd node #777

Closed
f18m opened this issue Jan 31, 2015 · 62 comments
Assignees
Labels
Close within 30 days Issue will be closed within 30 days unless requested to stay open Closing due to inaction Issue likely to be closed due to lack of recent comments Waiting for external input Waiting for a comment from the originator of the issue, or a collaborator.

Comments

@f18m
Copy link

f18m commented Jan 31, 2015

Hi,
I found a quite-reproducible problem (happens quite often!) with the following setup:

(did "rpi-update" on Jan 31 2015)

HOW TO REPRODUCE: just producing traffic on the USB external drives at some point produces:

[ 1116.317108] sd 1:0:0:0: [sdb]  
[ 1116.317199] Result: hostbyte=0x07 driverbyte=0x00
[ 1116.317220] sd 1:0:0:0: [sdb] CDB: 
[ 1116.317233] cdb[0]=0x28: 28 00 13 7b 13 08 00 00 f0 00
[ 1116.317297] blk_update_request: I/O error, dev sdb, sector 326832904

(several times, for different sectors)

and the USB device (e.g., /dev/sdb1) is destroyed and a new dev node is created (e.g., /dev/sdc1).

The dwc_otg driver seems latest one:

root@rasptorrent:~# dmesg | grep dwc_otg
[    0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=1824 bcm2708_fb.fbheight=984 bcm2708.boardrev=0x10 bcm2708.serial=0xee394e21 smsc95xx.macaddr=B8:27:EB:39:4E:21 bcm2708_fb.fbswap=1 bcm2708.disk_led_gpio=47 bcm2708.disk_led_active_low=0 sdhci-bcm2708.emmc_clock_freq=250000000 vc_mem.mem_base=0x1ec00000 vc_mem.mem_size=0x20000000  dwc_otg.lpm_enable=0 console=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait
[    1.583112] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.027416] WARN::dwc_otg_hcd_init:1047: FIQ DMA bounce buffers: virt = 0xdbc14000 dma = 0x5bc14000 len=9024
[    2.054741] dwc_otg: Microframe scheduler enabled
[    2.087234] dwc_otg bcm2708_usb: DWC OTG Controller
[    2.097477] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
[    2.110137] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
[    2.173907] usb usb1: Manufacturer: Linux 3.18.5+ dwc_otg_hcd
[    2.215058] dwc_otg: FIQ enabled
[    2.215085] dwc_otg: NAK holdoff enabled
[    2.215098] dwc_otg: FIQ split-transaction FSM enabled
[    2.696903] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    3.257234] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.617035] usb 1-1.2: new low-speed USB device number 4 using dwc_otg
[    4.117189] usb 1-1.3: new low-speed USB device number 5 using dwc_otg
[    4.647235] usb 1-1.5: new high-speed USB device number 6 using dwc_otg
[    5.287832] usb 1-1.5.2: new high-speed USB device number 7 using dwc_otg
[    5.757505] usb 1-1.5.4: new high-speed USB device number 8 using dwc_otg
[ 1116.837726] usb 1-1.5.4: new high-speed USB device number 9 using dwc_otg

and it seems that "FIQ enabled", "NAK holdoff enabled" " FIQ split-transaction FSM enabled" features are there.

I'm going to attach the dmsg and lsusb outputs. Please let me know if I can try some fix.

@f18m
Copy link
Author

f18m commented Jan 31, 2015

DMESG OUTPUT:

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 3.18.5+ (dc4@dc4-XPS13-9333) (gcc version 4.8.3 20140303 (prerelease) (crosstool-NG linaro-1.13.1+bzr2650 - Linaro GCC 2014.03) ) #744 PREEMPT Fri Jan 30 18:19:07 GMT 2015
[    0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
[    0.000000] Machine model: Raspberry Pi Model B+
[    0.000000] cma: Reserved 8 MiB at 0x1b800000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] On node 0 totalpages: 114688
[    0.000000] free_area_init_node: node 0, pgdat c084d794, node_mem_map db474000
[    0.000000]   Normal zone: 896 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 114688 pages, LIFO batch:31
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 113792
[    0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=1824 bcm2708_fb.fbheight=984 bcm2708.boardrev=0x10 bcm2708.serial=0xee394e21 smsc95xx.macaddr=B8:27:EB:39:4E:21 bcm2708_fb.fbswap=1 bcm2708.disk_led_gpio=47 bcm2708.disk_led_active_low=0 sdhci-bcm2708.emmc_clock_freq=250000000 vc_mem.mem_base=0x1ec00000 vc_mem.mem_size=0x20000000  dwc_otg.lpm_enable=0 console=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait
[    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 437208K/458752K available (5926K kernel code, 358K rwdata, 1876K rodata, 340K init, 734K bss, 21544K reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xffe00000   (2048 kB)
[    0.000000]     vmalloc : 0xdc800000 - 0xff000000   ( 552 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xdc000000   ( 448 MB)
[    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
[    0.000000]       .text : 0xc0008000 - 0xc07a6a60   (7803 kB)
[    0.000000]       .init : 0xc07a7000 - 0xc07fc000   ( 340 kB)
[    0.000000]       .data : 0xc07fc000 - 0xc085582c   ( 359 kB)
[    0.000000]        .bss : 0xc085582c - 0xc090d0c8   ( 735 kB)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] NR_IRQS:522
[    0.000025] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483648000ns
[    0.000076] Switching to timer-based delay loop, resolution 1000ns
[    0.000360] Console: colour dummy device 80x30
[    0.001434] console [tty1] enabled
[    0.001481] Calibrating delay loop (skipped), value calculated using timer frequency.. 2.00 BogoMIPS (lpj=10000)
[    0.001556] pid_max: default: 32768 minimum: 301
[    0.001934] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.002000] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.003011] Initializing cgroup subsys memory
[    0.003101] Initializing cgroup subsys devices
[    0.003159] Initializing cgroup subsys freezer
[    0.003213] Initializing cgroup subsys net_cls
[    0.003263] Initializing cgroup subsys blkio
[    0.003387] CPU: Testing write buffer coherency: ok
[    0.003502] ftrace: allocating 19476 entries in 58 pages
[    0.111287] Setting up static identity map for 0x55c8f8 - 0x55c954
[    0.114119] devtmpfs: initialized
[    0.131804] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
[    0.134975] pinctrl core: initialized pinctrl subsystem
[    0.137561] NET: Registered protocol family 16
[    0.143094] DMA: preallocated 4096 KiB pool for atomic coherent allocations
[    0.171058] cpuidle: using governor ladder
[    0.201120] cpuidle: using governor menu
[    0.201635] bcm2708.uart_clock = 3000000
[    0.204744] No ATAGs?
[    0.204808] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
[    0.204872] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.204936] mailbox: Broadcom VideoCore Mailbox driver
[    0.205100] bcm2708_vcio: mailbox at f200b880
[    0.205244] bcm_power: Broadcom power driver
[    0.205291] bcm_power_open() -> 0
[    0.205321] bcm_power_request(0, 8)
[    0.706070] bcm_mailbox_read -> 00000080, 0
[    0.706118] bcm_power_request -> 0
[    0.706314] Serial: AMBA PL011 UART driver
[    0.706548] dev:f1: ttyAMA0 at MMIO 0x20201000 (irq = 83, base_baud = 0) is a PL011 rev3
[    1.100981] console [ttyAMA0] enabled
[    1.174063] SCSI subsystem initialized
[    1.178165] usbcore: registered new interface driver usbfs
[    1.183985] usbcore: registered new interface driver hub
[    1.189490] usbcore: registered new device driver usb
[    1.196691] Switched to clocksource stc
[    1.228389] FS-Cache: Loaded
[    1.231704] CacheFiles: Loaded
[    1.251999] NET: Registered protocol family 2
[    1.257961] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    1.265140] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
[    1.271925] TCP: Hash tables configured (established 4096 bind 4096)
[    1.278443] TCP: reno registered
[    1.281713] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    1.287641] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    1.294341] NET: Registered protocol family 1
[    1.299428] RPC: Registered named UNIX socket transport module.
[    1.305398] RPC: Registered udp transport module.
[    1.310240] RPC: Registered tcp transport module.
[    1.314972] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.322690] bcm2708_dma: DMA manager at f2007000
[    1.327722] vc-mem: phys_addr:0x00000000 mem_base=0x1ec00000 mem_size:0x20000000(512 MiB)
[    1.337670] futex hash table entries: 256 (order: -1, 3072 bytes)
[    1.343941] audit: initializing netlink subsys (disabled)
[    1.349654] audit: type=2000 audit(1.100:1): initialized
[    1.370529] VFS: Disk quotas dquot_6.5.2
[    1.374867] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.384394] FS-Cache: Netfs 'nfs' registered for caching
[    1.391568] NFS: Registering the id_resolver key type
[    1.396884] Key type id_resolver registered
[    1.401099] Key type id_legacy registered
[    1.406560] msgmni has been set to 869
[    1.412973] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    1.420993] io scheduler noop registered
[    1.424978] io scheduler deadline registered (default)
[    1.430715] io scheduler cfq registered
[    1.437339] BCM2708FB: allocated DMA memory 5bc00000
[    1.442409] BCM2708FB: allocated DMA channel 0 @ f2007000
[    1.473055] Console: switching to colour frame buffer device 228x61
[    1.498788] bcm2708-dmaengine bcm2708-dmaengine: Load BCM2835 DMA engine driver
[    1.506854] uart-pl011 dev:f1: no DMA platform data
[    1.512675] vc-cma: Videocore CMA driver
[    1.516879] vc-cma: vc_cma_base      = 0x00000000
[    1.521706] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
[    1.527338] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
[    1.547180] brd: module loaded
[    1.558029] loop: module loaded
[    1.561762] vchiq: vchiq_init_state: slot_zero = 0xdb800000, is_master = 0
[    1.570138] Loading iSCSI transport class v2.0-870.
[    1.576868] usbcore: registered new interface driver smsc95xx
[    1.583112] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    1.789445] Core Release: 2.80a
[    1.792719] Setting default values for core params
[    1.797772] Finished setting default values for core params
[    2.003690] Using Buffer DMA mode
[    2.007164] Periodic Transfer Interrupt Enhancement - disabled
[    2.013136] Multiprocessor Interrupt Enhancement - disabled
[    2.018869] OTG VER PARAM: 0, OTG VER FLAG: 0
[    2.023343] Dedicated Tx FIFOs mode
[    2.027416] WARN::dwc_otg_hcd_init:1047: FIQ DMA bounce buffers: virt = 0xdbc14000 dma = 0x5bc14000 len=9024
[    2.037560] FIQ FSM acceleration enabled for :
[    2.037560] Non-periodic Split Transactions
[    2.037560] Periodic Split Transactions
[    2.037560] High-Speed Isochronous Endpoints
[    2.054741] dwc_otg: Microframe scheduler enabled
[    2.054912] WARN::hcd_init:473: FIQ at 0xc0400a24
[    2.065113] WARN::hcd_init:474: FIQ ASM at 0xc0400cfc length 36
[    2.076407] WARN::hcd_init:500: MPHI regs_base at 0xdc806000
[    2.087234] dwc_otg bcm2708_usb: DWC OTG Controller
[    2.097477] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
[    2.110137] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
[    2.120825] Init: Port Power? op_state=1
[    2.130042] Init: Power Port (0)
[    2.138990] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    2.151265] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.163881] usb usb1: Product: DWC OTG Controller
[    2.173907] usb usb1: Manufacturer: Linux 3.18.5+ dwc_otg_hcd
[    2.184898] usb usb1: SerialNumber: bcm2708_usb
[    2.195898] hub 1-0:1.0: USB hub found
[    2.205094] hub 1-0:1.0: 1 port detected
[    2.215058] dwc_otg: FIQ enabled
[    2.215085] dwc_otg: NAK holdoff enabled
[    2.215098] dwc_otg: FIQ split-transaction FSM enabled
[    2.215163] Module dwc_common_port init
[    2.215816] usbcore: registered new interface driver usb-storage
[    2.227818] mousedev: PS/2 mouse device common for all mice
[    2.239604] bcm2835-cpufreq: min=700000 max=700000
[    2.250362] sdhci: Secure Digital Host Controller Interface driver
[    2.261929] sdhci: Copyright(c) Pierre Ossman
[    2.271713] DMA channels allocated for the MMC driver
[    2.316781] Load BCM2835 MMC driver
[    2.331254] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.350706] ledtrig-cpu: registered to indicate activity on CPUs
[    2.362406] hidraw: raw HID events driver (C) Jiri Kosina
[    2.376761] usbcore: registered new interface driver usbhid
[    2.389630] usbhid: USB HID core driver
[    2.401417] TCP: cubic registered
[    2.411491] Indeed it is in host mode hprt0 = 00021501
[    2.424006] Initializing XFRM netlink socket
[    2.446855] NET: Registered protocol family 17
[    2.457035] Key type dns_resolver registered
[    2.473343] mmc0: host does not support reading read-only switch, assuming write-enable
[    2.498564] registered taskstats version 1
[    2.517234] vc-sm: Videocore shared memory driver
[    2.527782] mmc0: new high speed SDHC card at address 0007
[    2.546787] [vc_sm_connected_init]: start
[    2.566845] mmcblk0: mmc0:0007 SD8GB 7.42 GiB 
[    2.579315] [vc_sm_connected_init]: end - returning 0
[    2.590437]  mmcblk0: p1 p2
[    2.630942] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    2.645141] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    2.659651] devtmpfs: mounted
[    2.669330] Freeing unused kernel memory: 340K (c07a7000 - c07fc000)
[    2.696903] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.709582] Indeed it is in host mode hprt0 = 00001101
[    2.927400] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    2.939831] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.954401] hub 1-1:1.0: USB hub found
[    2.965038] hub 1-1:1.0: 5 ports detected
[    3.257234] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.387483] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    3.408612] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.427754] smsc95xx v1.0.4
[    3.503670] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:39:4e:21
[    3.617035] usb 1-1.2: new low-speed USB device number 4 using dwc_otg
[    3.744260] usb 1-1.2: New USB device found, idVendor=046d, idProduct=c018
[    3.767621] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    3.789276] usb 1-1.2: Product: USB Optical Mouse
[    3.805242] usb 1-1.2: Manufacturer: Logitech
[    3.833914] input: Logitech USB Optical Mouse as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2:1.0/0003:046D:C018.0001/input/input0
[    3.855465] hid-generic 0003:046D:C018.0001: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-bcm2708_usb-1.2/input0
[    4.117189] usb 1-1.3: new low-speed USB device number 5 using dwc_otg
[    4.270704] usb 1-1.3: New USB device found, idVendor=045e, idProduct=009d
[    4.296993] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    4.326322] usb 1-1.3: Product: Microsoft Wireless Optical Desktop\xffffffc2\xffffffae\xffffffae 2.10
[    4.354791] usb 1-1.3: Manufacturer: Microsoft
[    4.647235] usb 1-1.5: new high-speed USB device number 6 using dwc_otg
[    4.761830] udevd[158]: starting version 175
[    4.787363] usb 1-1.5: New USB device found, idVendor=8564, idProduct=4000
[    4.822461] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    4.856935] usb 1-1.5: Product: USB2.0 Hub
[    4.890417] usb 1-1.5: Manufacturer: Transcend
[    4.920048] hub 1-1.5:1.0: USB hub found
[    4.957035] hub 1-1.5:1.0: 4 ports detected
[    5.287832] usb 1-1.5.2: new high-speed USB device number 7 using dwc_otg
[    5.408179] usb 1-1.5.2: New USB device found, idVendor=2537, idProduct=1068
[    5.446947] usb 1-1.5.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    5.496958] usb 1-1.5.2: Product: NS1068
[    5.526923] usb 1-1.5.2: Manufacturer: Norelsys
[    5.556917] usb 1-1.5.2: SerialNumber: 0123456789ABCDE
[    5.592224] usb-storage 1-1.5.2:1.0: USB Mass Storage device detected
[    5.647044] scsi host0: usb-storage 1-1.5.2:1.0
[    5.757505] usb 1-1.5.4: new high-speed USB device number 8 using dwc_otg
[    5.888236] usb 1-1.5.4: New USB device found, idVendor=2537, idProduct=1066
[    5.927005] usb 1-1.5.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    5.966909] usb 1-1.5.4: Product: NS1066
[    6.007013] usb 1-1.5.4: Manufacturer: Norelsys
[    6.037053] usb 1-1.5.4: SerialNumber: 0123456789ABCDE
[    6.071937] usb-storage 1-1.5.4:1.0: USB Mass Storage device detected
[    6.127431] scsi host1: usb-storage 1-1.5.4:1.0
[    6.619889] usbcore: registered new interface driver uas
[    7.933893] input: Microsoft Microsoft Wireless Optical Desktop\xffffffc2\xffffffae\xffffffae 2.10 as /devices/platform/bcm2708_usb/usb1/1-1/1-1.3/1-1.3:1.0/0003:045E:009D.0002/input/input1
[    8.204413] scsi 0:0:0:0: Direct-Access     ATA      WDC WD5000LPVT-0 1A01 PQ: 0 ANSI: 6
[    8.234695] sd 0:0:0:0: [sda] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[    8.264555] sd 0:0:0:0: [sda] Write Protect is off
[    8.290614] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[    8.291629] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[    8.308739] microsoft 0003:045E:009D.0002: input,hidraw1: USB HID v1.11 Keyboard [Microsoft Microsoft Wireless Optical Desktop\xffffffc2\xffffffae\xffffffae 2.10] on usb-bcm2708_usb-1.3/input0
[    8.685652] scsi 1:0:0:0: Direct-Access     NORELSYS 106X             1C   PQ: 0 ANSI: 6
[    8.716642] input: Microsoft Microsoft Wireless Optical Desktop\xffffffc2\xffffffae\xffffffae 2.10 as /devices/platform/bcm2708_usb/usb1/1-1/1-1.3/1-1.3:1.1/0003:045E:009D.0003/input/input2
[    8.741224] sd 1:0:0:0: [sdb] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[    8.758748] sd 1:0:0:0: [sdb] Write Protect is off
[    8.787000] sd 1:0:0:0: [sdb] Mode Sense: 43 00 00 00
[    8.788025] sd 1:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[    8.957960] microsoft 0003:045E:009D.0003: input,hidraw2: USB HID v1.11 Mouse [Microsoft Microsoft Wireless Optical Desktop\xffffffc2\xffffffae\xffffffae 2.10] on usb-bcm2708_usb-1.3/input1
[    9.317102] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    9.397799] sd 1:0:0:0: Attached scsi generic sg1 type 0
[    9.803564] random: nonblocking pool is initialized
[   10.100864]  sda: sda1 sda2 < sda5 >
[   10.130787] sd 0:0:0:0: [sda] Attached SCSI disk
[   10.305753]  sdb: sdb1
[   10.341365] sd 1:0:0:0: [sdb] Attached SCSI disk
[   13.401277] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[   13.904700] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[   25.040344] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   26.556616] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
[   32.233069] Adding 102396k swap on /var/swap.  Priority:-1 extents:2 across:2134012k SSFS
[   33.159676] EXT4-fs (sda5): Ignoring removed nobh option
[   33.193807] EXT4-fs (sda5): barriers disabled
[   33.220421] EXT4-fs (sda5): warning: maximal mount count reached, running e2fsck is recommended
[   33.226166] EXT4-fs (sda5): mounted filesystem with writeback data mode. Opts: data=writeback,barrier=0,nobh,errors=remount-ro
[   36.867342] fuse init (API version 7.23)
[ 1116.317108] sd 1:0:0:0: [sdb]  
[ 1116.317199] Result: hostbyte=0x07 driverbyte=0x00
[ 1116.317220] sd 1:0:0:0: [sdb] CDB: 
[ 1116.317233] cdb[0]=0x28: 28 00 13 7b 13 08 00 00 f0 00
[ 1116.317297] blk_update_request: I/O error, dev sdb, sector 326832904
[ 1116.416456] usb 1-1.5.4: USB disconnect, device number 8
[ 1116.417966] sd 1:0:0:0: [sdb]  
[ 1116.418006] Result: hostbyte=0x07 driverbyte=0x00
[ 1116.418025] sd 1:0:0:0: [sdb] CDB: 
[ 1116.418038] cdb[0]=0x28: 28 00 13 7b 13 f8 00 00 10 00
[ 1116.418095] blk_update_request: I/O error, dev sdb, sector 326833144
[ 1116.437068] sd 1:0:0:0: [sdb]  
[ 1116.437110] Result: hostbyte=0x01 driverbyte=0x00
[ 1116.437138] sd 1:0:0:0: [sdb] CDB: 
[ 1116.437153] cdb[0]=0x28: 28 00 13 7b 14 08 00 00 f0 00
[ 1116.437210] blk_update_request: I/O error, dev sdb, sector 326833160
[ 1116.437477] sd 1:0:0:0: [sdb]  
[ 1116.437503] Result: hostbyte=0x01 driverbyte=0x00
[ 1116.437523] sd 1:0:0:0: [sdb] CDB: 
[ 1116.437535] cdb[0]=0x28: 28 00 13 7b 14 f8 00 00 10 00
[ 1116.437586] blk_update_request: I/O error, dev sdb, sector 326833400
[ 1116.837726] usb 1-1.5.4: new high-speed USB device number 9 using dwc_otg
[ 1116.938716] usb 1-1.5.4: New USB device found, idVendor=2537, idProduct=1066
[ 1116.938756] usb 1-1.5.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1116.938774] usb 1-1.5.4: Product: NS1066
[ 1116.938791] usb 1-1.5.4: Manufacturer: Norelsys
[ 1116.938808] usb 1-1.5.4: SerialNumber: 0123456789ABCDE
[ 1116.947231] usb-storage 1-1.5.4:1.0: USB Mass Storage device detected
[ 1116.957029] scsi host2: usb-storage 1-1.5.4:1.0
[ 1118.488809] scsi 2:0:0:0: Direct-Access     NORELSYS 106X             1C   PQ: 0 ANSI: 6
[ 1118.493957] sd 2:0:0:0: [sdc] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[ 1118.494854] sd 2:0:0:0: [sdc] Write Protect is off
[ 1118.494893] sd 2:0:0:0: [sdc] Mode Sense: 43 00 00 00
[ 1118.495731] sd 2:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1118.509937] sd 2:0:0:0: Attached scsi generic sg1 type 0
[ 1118.611201]  sdc: sdc1
[ 1118.615762] sd 2:0:0:0: [sdc] Attached SCSI disk
[ 1170.189495] Buffer I/O error on dev sdb1, logical block 15543735, async page read
[ 1170.327858] Buffer I/O error on dev sdb1, logical block 15543735, async page read
[ 1173.386466] Buffer I/O error on dev sdb1, logical block 15543735, async page read
[ 1173.478796] Buffer I/O error on dev sdb1, logical block 15543735, async page read
[ 1176.531657] Buffer I/O error on dev sdb1, logical block 15543735, async page read
[ 1176.624954] Buffer I/O error on dev sdb1, logical block 15543735, async page read
[ 1179.680094] Buffer I/O error on dev sdb1, logical block 87877518, async page read
[ 1179.777933] Buffer I/O error on dev sdb1, logical block 87877518, async page read
[ 1181.891037] Buffer I/O error on dev sdb1, logical block 87877518, async page read
[ 1181.911066] Buffer I/O error on dev sdb1, logical block 87877518, async page read
[ 1181.931217] Buffer I/O error on dev sdb1, logical block 87877518, async page read

@f18m
Copy link
Author

f18m commented Jan 31, 2015

LSUSB OUTPUT:

Bus 001 Device 002: ID 0424:9514 Standard Microsystems Corp. 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp. 
Bus 001 Device 004: ID 046d:c018 Logitech, Inc. Optical Wheel Mouse
Bus 001 Device 005: ID 045e:009d Microsoft Corp. Wireless Optical Desktop 3.0
Bus 001 Device 006: ID 8564:4000  
Bus 001 Device 007: ID 2537:1068  
Bus 001 Device 009: ID 2537:1066  

@P33M
Copy link
Contributor

P33M commented Feb 1, 2015

Is there a firmware revision where this behaviour first started? I.e. can you identify which revision of firmware is the first bad one?

@f18m
Copy link
Author

f18m commented Feb 1, 2015

Unfortunately no. I have my raspberry only since a few days. Before buying the powered USB hub, it gave the same problem (back then it was using a raspbmc distribution with kernel 3.12 but the errors in dmesg were similar/identical). Moreover, after /dev/sd node recreation I could also hear the typical noise of the external hard drive having problems starting up... for this reason I thought the problems were due to insufficient power and thus I bought the USB hub.

Now the problem in dmesg is similar/identical but it doesn't really seem a power issue: the hard disk stay on even when attached just to the USB hub and additionally, after the /dev/sd node recreation the hard disk emits no noise...

An additional thing: both the hard disk work just fine under Windows (and also under Linux on my workstation) even under heavy load... I think it must be something with dwc_otg driver...

@f18m
Copy link
Author

f18m commented Feb 1, 2015

Another note: I also tried to power everything from the USB hub (15W should be enough for the 2 external HDD and the raspberry) using a micro USB cable that goes from the hub to the raspberry micro-USB connection. The same problem happens.

Moreover, it also happens apparently randomly even when writing small files on the disk periodically (I have a script that writes 512B every 30 seconds)... for example just now I see:

(....all init messages.....)
[   38.667175] fuse init (API version 7.23)
[19013.716559] sd 0:0:0:0: [sda]
[19013.716599] Result: hostbyte=0x07 driverbyte=0x00
[19013.716618] sd 0:0:0:0: [sda] CDB:
[19013.716631] cdb[0]=0x28: 28 00 04 27 27 7c 00 00 f0 00
[19013.716688] blk_update_request: I/O error, dev sda, sector 69674876
[19013.806554] sd 0:0:0:0: [sda]
[19013.806596] Result: hostbyte=0x07 driverbyte=0x00
[19013.806615] sd 0:0:0:0: [sda] CDB:
[19013.806628] cdb[0]=0x28: 28 00 04 27 28 6c 00 00 10 00
[19013.806682] blk_update_request: I/O error, dev sda, sector 69675116
[19013.865329] usb 1-1.5.2: USB disconnect, device number 7
[19013.866655] sd 0:0:0:0: [sda]
[19013.866691] Result: hostbyte=0x01 driverbyte=0x00
[19013.866712] sd 0:0:0:0: [sda] CDB:
[19013.866724] cdb[0]=0x28: 28 00 04 27 28 7c 00 00 f0 00
[19013.866779] blk_update_request: I/O error, dev sda, sector 69675132
[19013.866944] sd 0:0:0:0: [sda]
[19013.866970] Result: hostbyte=0x01 driverbyte=0x00
[19013.866988] sd 0:0:0:0: [sda] CDB:
[19013.866998] cdb[0]=0x28: 28 00 04 27 29 6c 00 00 10 00
[19013.867047] blk_update_request: I/O error, dev sda, sector 69675372

that is, in idle conditions, after from second 38 to second 19013 no problem, then suddenly the USB failure.

@f18m
Copy link
Author

f18m commented Feb 5, 2015

Tried with another hard disk (again, over USB). I left it idle (mounted on the filesystem but without read/writes from userspace) for ~3days: no problem.
Then I started writing/reading:

[90665.519028] sd 0:0:0:0: [sda]
[90665.519069] Result: hostbyte=0x07 driverbyte=0x00
[90665.519088] sd 0:0:0:0: [sda] CDB:
[90665.519101] cdb[0]=0x28: 28 00 27 25 b9 38 00 00 f0 00
[90665.519167] blk_update_request: I/O error, dev sda, sector 656783672
[90665.618980] sd 0:0:0:0: [sda]
[90665.619022] Result: hostbyte=0x07 driverbyte=0x00
[90665.619041] sd 0:0:0:0: [sda] CDB:
[90665.619053] cdb[0]=0x28: 28 00 27 25 ba 28 00 00 10 00
[90665.619110] blk_update_request: I/O error, dev sda, sector 656783912
[90665.628528] usb 1-1.5.3: USB disconnect, device number 7
[90665.639075] sd 0:0:0:0: [sda]
[90665.639117] Result: hostbyte=0x01 driverbyte=0x00
[90665.639136] sd 0:0:0:0: [sda] CDB:
[90665.639151] cdb[0]=0x28: 28 00 27 25 ba 38 00 00 f0 00
[90665.639209] blk_update_request: I/O error, dev sda, sector 656783928
[90665.639486] EXT4-fs warning (device sda5): ext4_end_bio:317: I/O error -5 writing to inode 2616323 (offset 173670400 size 32768 starting block 119737000)
[90665.639525] Buffer I/O error on device sda5, logical block 5320096
[90665.639549] Buffer I/O error on device sda5, logical block 5320097
[90665.639569] Buffer I/O error on device sda5, logical block 5320098
[90665.639587] Buffer I/O error on device sda5, logical block 5320099
[90665.639605] Buffer I/O error on device sda5, logical block 5320100
[90665.639621] Buffer I/O error on device sda5, logical block 5320101
[90665.639638] Buffer I/O error on device sda5, logical block 5320102
[90665.639657] Buffer I/O error on device sda5, logical block 5320103
[90665.639711] EXT4-fs warning (device sda5): ext4_end_bio:317: I/O error -5 writing to inode 2616323 (offset 175374336 size 32768 starting block 119737416)
[90665.639736] Buffer I/O error on device sda5, logical block 5320512
[90665.639757] Buffer I/O error on device sda5, logical block 5320513
[90665.639823] EXT4-fs warning (device sda5): ext4_end_bio:317: I/O error -5 writing to inode 2616323 (offset 196313088 size 32768 starting block 119742528)
[90665.639899] EXT4-fs warning (device sda5): ext4_end_bio:317: I/O error -5 writing to inode 2616323 (offset 223379456 size 32768 starting block 119749136)

By the way I'm a C/C++ developer... if you could point me to the right point of the code writing those

"sd 0:0:0:0: [sda]\nResult: hostbyte=0x07 driverbyte=0x00"

I could help you with understanding the failure reason perhaps (althought I don't know much about USB driver routines!)...

@f18m
Copy link
Author

f18m commented Feb 26, 2015

Actually I found that this bug is possibly related to the following long-standing issue in Linux kernel:

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=625922

@MeeGeeVee
Copy link

I have a similar issue

Running crashplan on a raspberry pi

Raspberry PI B with own powersupply - booting from SDCard
Seagate Expansion 2TB USB hard drive 1 - Powered by RPI
NTFS partition was reformatted and did a full scandisk in windows (without errors : chkdsk /F /R /X without error)

USB drive disconnecting as device 4 and reconnecting as 5
First on Linux RPI 3.12.28+
Now on Linux version 3.18.8+

Details:
First running on :
Linux RPI 3.12.28+ #709 PREEMPT Mon Sep 8 15:28:00 BST 2014 armv6l

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 3.12.28+ (dc4@dc4-XPS13-9333) (gcc version 4.8.3 20140303 (prerelease) (crosstool-NG linaro-1.13.1+bzr2650 - Linaro GCC 2014.03) ) #709 PREEMPT Mon Sep 8 15:28:00 BST 2014
 ...
    2.395822] Freeing unused kernel memory: 140K (c05bd000 - c05e0000)
[    2.428097] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.436572] Indeed it is in host mode hprt0 = 00001101
[    2.648426] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
[    2.657030] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.666672] hub 1-1:1.0: USB hub found
[    2.672437] hub 1-1:1.0: 3 ports detected
[    2.958257] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.078587] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    3.087064] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.114979] smsc95xx v1.0.4
[    3.183817] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:4e:3e:35
[    3.308275] usb 1-1.3: new high-speed USB device number 4 using dwc_otg
[    3.421303] usb 1-1.3: New USB device found, idVendor=0bc2, idProduct=2312
[    3.437809] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    3.455266] usb 1-1.3: Product: Expansion
[    3.468109] usb 1-1.3: Manufacturer: Seagate 
[    3.474056] usb 1-1.3: SerialNumber: NA49AKKC
[    3.494274] usb-storage 1-1.3:1.0: USB Mass Storage device detected
[    3.516889] scsi0 : usb-storage 1-1.3:1.0
[    3.973285] udevd[156]: starting version 175
[    4.751726] scsi 0:0:0:0: Direct-Access     Seagate  Expansion        0636 PQ: 0 ANSI: 6
[    4.789472] sd 0:0:0:0: [sda] 3907029167 512-byte logical blocks: (2.00 TB/1.81 TiB)
[    4.818478] sd 0:0:0:0: [sda] Write Protect is off
[    4.824932] sd 0:0:0:0: [sda] Mode Sense: 2b 00 10 08
[    4.838110] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[    4.891840]  sda: sda1 sda2 sda3 sda4
[    4.915313] sd 0:0:0:0: [sda] Attached SCSI disk
[    5.078484] bcm2708_spi bcm2708_spi.0: master is unqueued, this is deprecated
[    5.258377] bcm2708_spi bcm2708_spi.0: SPI Controller at 0x20204000 (irq 80)
[    6.139475] bcm2708-i2s bcm2708-i2s.0: Failed to create debugfs directory
...
[31672.472087] usb 1-1.3: USB disconnect, device number 4
[31672.479681] sd 0:0:0:0: [sda] Unhandled error code
[31672.479722] sd 0:0:0:0: [sda]  
[31672.479736] Result: hostbyte=0x01 driverbyte=0x00
[31672.479749] sd 0:0:0:0: [sda] CDB: 
[31672.479760] cdb[0]=0x2a: 2a 00 24 0b cb 98 00 00 f0 00
[31672.479805] end_request: I/O error, dev sda, sector 604752792
[31672.479827] Buffer I/O error on device sda1, logical block 75593843
[31672.479840] lost page write due to I/O error on sda1
[31672.479871] Buffer I/O error on device sda1, logical block 75593844
[31672.479884] lost page write due to I/O error on sda1
[31672.479903] Buffer I/O error on device sda1, logical block 75593845
[31672.479915] lost page write due to I/O error on sda1
[31672.479933] Buffer I/O error on device sda1, logical block 75593846
[31672.479944] lost page write due to I/O error on sda1
[31672.479964] Buffer I/O error on device sda1, logical block 75593847
[31672.479976] lost page write due to I/O error on sda1
[31672.479994] Buffer I/O error on device sda1, logical block 75593848
[31672.480006] lost page write due to I/O error on sda1
[31672.480023] Buffer I/O error on device sda1, logical block 75593849
[31672.480034] lost page write due to I/O error on sda1
[31672.480051] Buffer I/O error on device sda1, logical block 75593850
[31672.480063] lost page write due to I/O error on sda1
[31672.480081] Buffer I/O error on device sda1, logical block 75593851
[31672.480094] lost page write due to I/O error on sda1
[31672.480112] Buffer I/O error on device sda1, logical block 75593852
[31672.480123] lost page write due to I/O error on sda1
[31672.488629] sd 0:0:0:0: [sda] Unhandled error code
[31672.488669] sd 0:0:0:0: [sda]  
[31672.488683] Result: hostbyte=0x01 driverbyte=0x00
[31672.488700] sd 0:0:0:0: [sda] CDB: 
[31672.488710] cdb[0]=0x2a: 2a 00 24 0b cc 88 00 00 f0 00
[31672.488759] end_request: I/O error, dev sda, sector 604753032
[31672.641346] end_request: I/O error, dev sda, sector 0
[31673.423312] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[31673.423571] sd 0:0:0:0: [sda]  
[31673.423652] Result: hostbyte=0x01 driverbyte=0x00
[31673.665251] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
[31673.769460] usb 1-1.3: New USB device found, idVendor=0bc2, idProduct=2312
[31673.769498] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[31673.769515] usb 1-1.3: Product: Expansion
[31673.769528] usb 1-1.3: Manufacturer: Seagate 
[31673.769541] usb 1-1.3: SerialNumber: NA49AKKC
[31673.773335] usb-storage 1-1.3:1.0: USB Mass Storage device detected
[31673.785103] scsi1 : usb-storage 1-1.3:1.0
[31674.960786] scsi 1:0:0:0: Direct-Access     Seagate  Expansion        0636 PQ: 0 ANSI: 6
[31674.964487] sd 1:0:0:0: Attached scsi generic sg0 type 0
[31674.965575] sd 1:0:0:0: [sdb] 3907029167 512-byte logical blocks: (2.00 TB/1.81 TiB)
[31674.967022] sd 1:0:0:0: [sdb] Write Protect is off
[31674.967066] sd 1:0:0:0: [sdb] Mode Sense: 2b 00 10 08
[31674.968097] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, supports DPO and FUA
[31674.990402]  sdb: sdb1 sdb2 sdb3 sdb4
[31674.994879] sd 1:0:0:0: [sdb] Attached SCSI disk
[31683.364606] quiet_error: 50 callbacks suppressed
[31683.364643] Buffer I/O error on device sda1, logical block 61321656
[31683.395719] Buffer I/O error on device sda1, logical block 61321656
[31683.400650] Buffer I/O error on device sda1, logical block 61321656
[31683.401815] Buffer I/O error on device sda1, logical block 61321656
[31683.403078] Buffer I/O error on device sda1, logical block 61321656
[31683.405692] Buffer I/O error on device sda1, logical block 61321656
[31683.406435] Buffer I/O error on device sda1, logical block 61321656
[31683.426127] Buffer I/O error on device sda1, logical block 61321656
[31683.427185] Buffer I/O error on device sda1, logical block 61321656
[31683.429573] Buffer I/O error on device sda1, logical block 61321656
[31690.220191] quiet_error: 6 callbacks suppressed
[31690.220229] Buffer I/O error on device sda1, logical block 61321656

Did an RpI-update to get lastest firmware
Linux version 3.18.8+

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 3.18.8+ (dc4@dc4-XPS13-9333) (gcc version 4.8.3 20140303 (prerelease) (crosstool-NG linaro-1.13.1+bzr2650 - Linaro GCC 2014.03) ) #763 PREEMPT Sat Feb 28 18:24:36 GMT 2015
[    0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
[    0.000000] Machine model: Raspberry Pi Model B
...
[    2.032382] dwc_otg bcm2708_usb: DWC OTG Controller
[    2.038970] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
[    2.047948] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
[    2.055128] Init: Port Power? op_state=1
[    2.060635] Init: Power Port (0)
[    2.065807] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    2.074242] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.083127] usb usb1: Product: DWC OTG Controller
[    2.089468] usb usb1: Manufacturer: Linux 3.18.8+ dwc_otg_hcd
[    2.096848] usb usb1: SerialNumber: bcm2708_usb
[    2.103972] hub 1-0:1.0: USB hub found
[    2.109565] hub 1-0:1.0: 1 port detected
[    2.115740] dwc_otg: FIQ enabled
[    2.115766] dwc_otg: NAK holdoff enabled
[    2.115779] dwc_otg: FIQ split-transaction FSM enabled
[    2.115837] Module dwc_common_port init
[    2.116395] usbcore: registered new interface driver usb-storage
[    2.124441] mousedev: PS/2 mouse device common for all mice
[    2.132551] bcm2835-cpufreq: min=700000 max=700000
[    2.139409] sdhci: Secure Digital Host Controller Interface driver
[    2.147315] sdhci: Copyright(c) Pierre Ossman
[    2.153533] DMA channels allocated for the MMC driver
[    2.194628] Load BCM2835 MMC driver
[    2.201659] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.217379] ledtrig-cpu: registered to indicate activity on CPUs
[    2.225450] hidraw: raw HID events driver (C) Jiri Kosina
[    2.237085] usbcore: registered new interface driver usbhid
[    2.246444] usbhid: USB HID core driver
[    2.254441] TCP: cubic registered
[    2.260642] Initializing XFRM netlink socket
[    2.268795] NET: Registered protocol family 17
[    2.275188] Key type dns_resolver registered
[    2.282817] registered taskstats version 1
[    2.288915] vc-sm: Videocore shared memory driver
[    2.295360] [vc_sm_connected_init]: start
[    2.302188] [vc_sm_connected_init]: end - returning 0
[    2.310790] Waiting for root device /dev/mmcblk0p2...
[    2.317968] Indeed it is in host mode hprt0 = 00021501
[    2.329261] mmc0: host does not support reading read-only switch, assuming write-enable
[    2.356589] mmc0: new high speed SDHC card at address abdf
[    2.374679] mmcblk0: mmc0:abdf SE08G 7.28 GiB 
[    2.385865]  mmcblk0: p1 p2
[    2.449400] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    2.461059] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    2.471093] devtmpfs: mounted
[    2.477002] Freeing unused kernel memory: 340K (c0791000 - c07e6000)
[    2.524884] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.533390] Indeed it is in host mode hprt0 = 00001101
[    2.745259] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
[    2.757886] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.772879] hub 1-1:1.0: USB hub found
[    2.781141] hub 1-1:1.0: 3 ports detected
[    3.065007] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.175373] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    3.184344] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.214457] smsc95xx v1.0.4
[    3.295211] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:4e:3e:35
[    3.404934] usb 1-1.3: new high-speed USB device number 4 using dwc_otg
[    3.536699] usb 1-1.3: New USB device found, idVendor=0bc2, idProduct=2312
[    3.554755] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    3.564121] usb 1-1.3: Product: Expansion
[    3.584802] usb 1-1.3: Manufacturer: Seagate 
[    3.591102] usb 1-1.3: SerialNumber: NA49AKKC
[    3.613659] usb 1-1.3: The driver for the USB controller dwc_otg_hcd does not support scatter-gather which is
[    3.643193] usb 1-1.3: required by the UAS driver. Please try an other USB controller if you wish to use UAS.
[    3.667239] usb-storage 1-1.3:1.0: USB Mass Storage device detected
[    3.689720] usb-storage 1-1.3:1.0: Quirks match for vid 0bc2 pid 2312: 2000000
[    3.713619] scsi host0: usb-storage 1-1.3:1.0
[    4.277697] udevd[160]: starting version 175
[    4.716141] scsi 0:0:0:0: Direct-Access     Seagate  Expansion        0636 PQ: 0 ANSI: 6
[    4.751315] sd 0:0:0:0: [sda] 3907029167 512-byte logical blocks: (2.00 TB/1.81 TiB)
[    4.782848] sd 0:0:0:0: [sda] Write Protect is off
[    4.810156] sd 0:0:0:0: [sda] Mode Sense: 2b 00 10 08
[    4.811154] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[    4.941307] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    6.960562]  sda: sda1 sda2 sda3 sda4
[    6.985092] sd 0:0:0:0: [sda] Attached SCSI disk
[    7.604701] random: nonblocking pool is initialized
[   10.991558] Adding 1048572k swap on /dev/sda3.  Priority:-1 extents:1 across:1048572k FS
[   11.164822] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[   17.721979] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[   17.845014] fuse init (API version 7.23)
[   23.100890] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   24.521869] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x4DE1
[22340.046505] usb 1-1.3: USB disconnect, device number 4
[22340.055841] sd 0:0:0:0: [sda]  
[22340.055876] Result: hostbyte=0x01 driverbyte=0x00
[22340.055894] sd 0:0:0:0: [sda] CDB: 
[22340.055907] cdb[0]=0x2a: 2a 00 27 dd 64 50 00 00 f0 00
[22340.055966] blk_update_request: I/O error, dev sda, sector 668820560
[22340.055991] Buffer I/O error on dev sda1, logical block 83602314, lost async page write
[22340.056035] Buffer I/O error on dev sda1, logical block 83602315, lost async page write
[22340.056063] Buffer I/O error on dev sda1, logical block 83602316, lost async page write
[22340.056092] Buffer I/O error on dev sda1, logical block 83602317, lost async page write
[22340.056120] Buffer I/O error on dev sda1, logical block 83602318, lost async page write
[22340.056145] Buffer I/O error on dev sda1, logical block 83602319, lost async page write
[22340.056169] Buffer I/O error on dev sda1, logical block 83602320, lost async page write
[22340.056194] Buffer I/O error on dev sda1, logical block 83602321, lost async page write
[22340.056222] Buffer I/O error on dev sda1, logical block 83602322, lost async page write
[22340.056247] Buffer I/O error on dev sda1, logical block 83602323, lost async page write
[22340.066347] sd 0:0:0:0: [sda]  
[22340.066388] Result: hostbyte=0x01 driverbyte=0x00
[22340.066407] sd 0:0:0:0: [sda] CDB: 
[22340.066420] cdb[0]=0x2a: 2a 00 27 dd 65 40 00 00 f0 00
[22340.066480] blk_update_request: I/O error, dev sda, sector 668820800
[22341.211466] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[22341.211804] sd 0:0:0:0: [sda]  
[22341.211830] Result: hostbyte=0x01 driverbyte=0x00
[22341.455565] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
[22341.558879] usb 1-1.3: New USB device found, idVendor=0bc2, idProduct=2312
[22341.558921] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[22341.558942] usb 1-1.3: Product: Expansion
[22341.558959] usb 1-1.3: Manufacturer: Seagate 
[22341.558975] usb 1-1.3: SerialNumber: NA49AKKC
[22341.563203] usb 1-1.3: The driver for the USB controller dwc_otg_hcd does not support scatter-gather which is
[22341.563241] usb 1-1.3: required by the UAS driver. Please try an other USB controller if you wish to use UAS.
[22341.563265] usb-storage 1-1.3:1.0: USB Mass Storage device detected
[22341.569042] usb-storage 1-1.3:1.0: Quirks match for vid 0bc2 pid 2312: 2000000
[22341.572599] scsi host1: usb-storage 1-1.3:1.0
[22341.817079] usbcore: registered new interface driver uas
[22342.759341] scsi 1:0:0:0: Direct-Access     Seagate  Expansion        0636 PQ: 0 ANSI: 6
[22342.764744] sd 1:0:0:0: [sdb] 3907029167 512-byte logical blocks: (2.00 TB/1.81 TiB)
[22342.765235] sd 1:0:0:0: Attached scsi generic sg0 type 0
[22342.765735] sd 1:0:0:0: [sdb] Write Protect is off
[22342.765772] sd 1:0:0:0: [sdb] Mode Sense: 2b 00 10 08
[22342.766749] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, supports DPO and FUA
[22342.787645]  sdb: sdb1 sdb2 sdb3 sdb4
[22342.793223] sd 1:0:0:0: [sdb] Attached SCSI disk
[22348.173746] buffer_io_error: 60 callbacks suppressed
[22348.173789] Buffer I/O error on dev sda1, logical block 786449, async page read
[22348.174803] Buffer I/O error on dev sda1, logical block 786449, async page read
[22348.178741] Buffer I/O error on dev sda1, logical block 786449, async page read
[22348.180791] Buffer I/O error on dev sda1, logical block 786449, async page read
[22350.133189] Buffer I/O error on dev sda1, logical block 786449, async page read
[22350.134229] Buffer I/O error on dev sda1, logical block 786449, async page read
[22350.138038] Buffer I/O error on dev sda1, logical block 786449, async page read
[22350.140092] Buffer I/O error on dev sda1, logical block 786449, async page read
[22352.270635] Buffer I/O error on dev sda1, logical block 61321656, async page read
[22352.272957] Buffer I/O error on dev sda1, logical block 61321656, async page read
[22836.221680] buffer_io_error: 38 callbacks suppressed
[22836.221723] Buffer I/O error on dev sda1, logical block 242143488, async page read
[22836.254434] Buffer I/O error on dev sda1, logical block 61321656, async page read
[22836.255735] Buffer I/O error on dev sda1, logical block 61321656, async page read
[22836.263045] Buffer I/O error on dev sda1, logical block 786449, async page read

I'm not a linux guru, but trying my best to understand things , and solve where possible.
All your assistance is more then welcome

@Razican
Copy link

Razican commented Apr 16, 2015

I confirm that this happens with Raspbery Pi 2 B running:
Linux 3.18.11-v7+ #777 SMP PREEMPT Sat Apr 11 17:30:37 BST 2015 armv7l GNU/Linux

I have a RAID attached via USB 3.0 (limited to 2.0 by RPi hardware) And it seems to happen under heavy traffic load. Is a 2x2TB in RAID 0 (total of 4TB drive). It fails when checking torrent downloads.

@MeeGeeVee
Copy link

In my case it was 100% power related.

I was able to test the drive and generate different load conditions with the command 'badblocks' and tuning of the parameters -d -c- b ( fe: sudo badblocks -e 100 -v /dev/sda1 -s -c 32 -d 50). As a result the drive failed on different blocks or not at all. This was an indication that the individual blocks were ok.

Changing the powersupply of the RPI (2A) did not help neither.

After buying a USB3 Y-cable to power the drive from another USB port, all got solved and my drive is still running fine for weeks now. http://www.ebay.com/sch/i.html?_from=R40&_nkw=usb3+y-cable

Hope this helps your case too.

@Razican
Copy link

Razican commented Apr 17, 2015

In my case, the USB RAID is self-powered, so the power should not be any problem.

@MeeGeeVee
Copy link

Worth to try some badblocks tests to see if you can reproduce a failure? "sudo badblocks -e 100 -v /dev/sda1 -s" will test at maximum speed. If failure should occur each time in different blocks it would put the hard drive out of the scope.

@Razican
Copy link

Razican commented Apr 17, 2015

After checking it with badblocks, after about 6 hours of checking it stopped after this error message:

[21989.512626] usb 1-1.5: reset high-speed USB device number 4 using dwc_otg
[21989.603287] usb 1-1.5: USB disconnect, device number 4
[21989.620170] scsi 0:0:0:0: rejecting I/O to offline device
[21989.625727] scsi 0:0:0:0: [sda] killing request
[21989.630473] scsi 0:0:0:0: [sda]  
[21989.633890] Result: hostbyte=0x01 driverbyte=0x00
[21989.638692] scsi 0:0:0:0: [sda] CDB: 
[21989.642420] cdb[0]=0x88: 88 00 00 00 00 00 50 d4 47 80 00 00 00 80 00 00
[21989.649557] blk_update_request: I/O error, dev sda, sector 1356089216
[21989.656584] Buffer I/O error on dev sda1, logical block 169478128, async page read
[21989.664568] Buffer I/O error on dev sda1, logical block 169478128, async page read
[21989.672388] Buffer I/O error on dev sda1, logical block 169478128, async page read
[21989.680280] Buffer I/O error on dev sda1, logical block 169478128, async page read
[21989.688367] Buffer I/O error on dev sda1, logical block 169478129, async page read
[21989.696346] Buffer I/O error on dev sda1, logical block 169478129, async page read
[21989.704281] Buffer I/O error on dev sda1, logical block 169478129, async page read
[21989.717096] Buffer I/O error on dev sda1, logical block 169478129, async page read
[21989.730112] Buffer I/O error on dev sda1, logical block 169478130, async page read
[21989.742960] Buffer I/O error on dev sda1, logical block 169478130, async page read
[21991.573600] usb 1-1.5: new high-speed USB device number 5 using dwc_otg
[21991.695072] usb 1-1.5: New USB device found, idVendor=152d, idProduct=0539
[21991.703942] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=5
[21991.713205] usb 1-1.5: Product: USB to ATA/ATAPI Bridge
[21991.720824] usb 1-1.5: Manufacturer: JMicron
[21991.727026] usb 1-1.5: SerialNumber: 239C7E548FFF
[21991.738885] usb-storage 1-1.5:1.0: USB Mass Storage device detected
[21991.747727] scsi host1: usb-storage 1-1.5:1.0
[21992.754883] scsi 1:0:0:0: Direct-Access     Sharkoon  H/W RAID0            PQ: 0 ANSI: 5
[21992.767773] sd 1:0:0:0: Attached scsi generic sg0 type 0
[21992.778207] sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
[21992.788120] sd 1:0:0:0: [sdb] 7813857280 512-byte logical blocks: (4.00 TB/3.63 TiB)
[21992.800149] sd 1:0:0:0: [sdb] Write Protect is off
[21992.806690] sd 1:0:0:0: [sdb] Mode Sense: 28 00 00 00
[21992.807146] sd 1:0:0:0: [sdb] No Caching mode page found
[21992.814189] sd 1:0:0:0: [sdb] Assuming drive cache: write through
[21992.823579] sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
[21993.203112]  sdb: sdb1
[21993.209125] sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
[21993.221187] sd 1:0:0:0: [sdb] Attached SCSI disk
[28490.293973] buffer_io_error: 90 callbacks suppressed
[28490.301253] Buffer I/O error on dev sda1, logical block 36, async page read

The last two were me trying to do a ls in the mounted /dev/sda1, that now is called /dev/sdb1, so it won't work.

@f18m
Copy link
Author

f18m commented Apr 18, 2015

By the way I still haven't solved this problem. Just FYI: I see the same problem on both Raspberry PI model B+ and on my BeagleBone.

The hard disks triggering this problem are miscellaneous:

  • WDC WD5000LPVT (500 GB) enclosed in USB3 enclosure (reports itself as Norelsys NS1068)
  • Toshiba MQ01ABD050 (500 GB) enclosed in USB3 enclosure (reports itself as Norelsys NS106X)
  • Toshiba MQ01UBD100 (1 TB) with its own Toshiba USB3 enclosure

It may help if you write down the manufacturers and model names of the hard disks that trigger this problem (the "Result: hostbyte=* driverbyte=*" error message). Thanks!

@f18m
Copy link
Author

f18m commented Apr 18, 2015

Another comment: on my desktop computer running Ubuntu Trusty 14.04 no problem are reported when transferring large files between the disks reported above.

@analyser-
Copy link

I'm not sure if it is related, however I'll share anyway, since it can help someone.

When I was assembling my rpi file server, with two external hard drives plugged into an usb hub, both in those cheap enclosures, I was not be able to use them till I've used a power source of 5.3 V (to the usb hub), instead 5.0 V. So, I strongly recommend trying a higher voltage power source.

@Blindfreddy
Copy link

I have the same error using a WD 2TB USB3 disk, refer https://www.google.de/url?url=https://github.com/raspberrypi/linux/issues/885&rct=j&q=&esrc=s&sa=U&ei=qz82VZIhwaewAYDNgKAN&ved=0CBoQFjAB&sig2=OFhTaepwrroA5QRZuaWnUQ&usg=AFQjCNEzwcQ-hGcApolnu3RnIxP6Et4JdA

HDD: DetailsHDD D
iManufacturer 1 Western Digital
iProduct 2 My Passport 0748

I actually have two Pi's, each with same model USB HDD. 1st on is a Model B, 2nd one a Model 2B. Works fine on the older Model B, but the problem occurs on the newer Model 2 B.

Kernel and Firmware on older Model B
uname -a
Linux rpi1 3.18.7+ #755 PREEMPT Thu Feb 12 17:14:31 GMT 2015 armv6l GNU/Linux
sudo /opt/vc/bin/vcgencmd version
Feb 14 2015 22:17:16
Copyright (c) 2012 Broadcom
version 7789db485409720b0e523a3d6b86b12ed56fd152 (clean) (release)

Kernel and Firmware on newer Model 2 B
uname -a
Linux rpi4 3.18.11-v7+ #780 SMP PREEMPT Mon Apr 20 14:59:10 BST 2015 armv7l GNU/Linux

sudo /opt/vc/bin/vcgencmd version
Apr 20 2015 15:02:24
Copyright (c) 2012 Broadcom
version 423cbd6f9f4f6097643cb90ddfd2c2e4c01ef3fd (clean) (release)

@MeeGeeVee
Copy link

BlindFreddy :
As stated before I'm not a specialist and my incident was power related. Reading your case I can only assist you to suggest some validations if your case isn't power related too. Interestiging in that you have 2 RPI and 2 drives.

  • Are you able to change the drives from one RPI to each other.
  • Are you able to switch the power supply from one RPI to another
  • I believe Western Digital Passport drive gets the power from the USB, are you able to use a y-cable to power the failing drive externally (http://www.ebay.com/sch/i.html?_from=R40&_nkw=usb3+y-cable).
  • Does 'sudo badblocks -e 100 -v /dev/sda1 -s' runs fine or fails each time at the same point ?

The result of the test should perhaps show it the issue remains related to HD, RPI/OS version or power supply .

@Razican
Copy link

Razican commented Apr 24, 2015

I don't think it's a power related error, since it worked perfectly in Raspberry Pi B, but it's not working in Raspberry Pi 2 B. In any case, I might be able to try it again in Raspberry Pi B this weekend.

@Blindfreddy
Copy link

Yes, I can try it out using Pi B and Pi 2B and the two drives. I cannot try external power y-cable - don't have one and also, since it has the drive has been working flawelessly on Pi B using internal power for well over a year, I think it is reasonable to expect it to work on Pi 2B.

@popcornmix
Copy link
Collaborator

Pi2 can use more power that Pi1, so I don't think you can infer a power supply that is good for Pi1 is necessarily good for Pi2.

@Razican
Copy link

Razican commented Apr 24, 2015 via email

@pelwell
Copy link
Contributor

pelwell commented Apr 24, 2015

FYI, Adafruit have released a tutorial on adding an external HDD to a Pi, and they say:

The Raspberry Pi doesn't have enough power to run most external hard drives or SSDs, so unless you have a drive with its own power supply, you'll probably need a powered USB hub.

@f18m
Copy link
Author

f18m commented Apr 24, 2015

In my case, I'm using a powered USB hub (certified for USB 3.0, so that the
hub comes with a 15W power adapter)... all these issues make me feel that
it's not really a power supply issue.

Perhaps to be sure the only way would be attaching an oscope to the USB
lines and see directly if the signal strength over USB D+ and D- lines is
good enough or not.

Honestly, I suspect some driver issue, either on Linux driver side or in
the hard disk / USB adaptor firmware.
Probably Windows is capable of handling such situation (indeed most vendors
only test their hard drives with Windows only), but Linux no.

Just my 2cents,
Francesco M.

2015-04-24 14:17 GMT+02:00 Phil Elwell notifications@github.com:

FYI, Adafruit have released a tutorial on adding an external HDD to a Pi,
and they say:

The Raspberry Pi doesn't have enough power to run most external hard
drives or SSDs, so unless you have a drive with its own power supply,
you'll probably need a powered USB hub.


Reply to this email directly or view it on GitHub
#777 (comment).

@igniz-
Copy link

igniz- commented Apr 27, 2015

Hi all, I'm having this very same problem but not on a raspberry, just a regular intel computer. My HDD is attached to a SATA-to-USB adaptor and it shows this exact same behaviour. It actually started after an update to the system, including a Kernel update, so the problem must be there, since no hardware was changed, and I even tested two different linux distros (opensuse 13.2 & ubuntu 15.04) both does exaclty the same. Today I will try a regression to an older linux distro an see if the problem "solves" just to be sure of this.
Hope this narrows the source of the problem a litte.

Regards!

@Razican
Copy link

Razican commented Apr 29, 2015

I can confirm (almost 100% sure) that it is not power related. I have bought a 5V 2A PSU for the Raspberry Pi 2 and a powered USB hub to connect the storage there. As I said before the storage is self powered, so there is no doubt that all has enough power. But it continues to fail. This time after more than 2 hours of use, but it disconects the device and adds it as a new drive (even if UUID is the same).

In my change to the USB hub I also ran into #824. In any case I could do a workaround for that (changing the root delay, as said in the issue comments). The thing is that as we have seen, under heavy load, the device simply disapears from /dev.

Here is, again the dmesg:

[ 7991.378571] sd 0:0:0:0: [sda]  
[ 7991.381813] Result: hostbyte=0x00 driverbyte=0x08
[ 7991.386578] sd 0:0:0:0: [sda]  
[ 7991.389753] Sense Key : 0x3 [current] 
[ 7991.393605] sd 0:0:0:0: [sda]  
[ 7991.396781] ASC=0x3 ASCQ=0x0
[ 7991.399702] sd 0:0:0:0: [sda] CDB: 
[ 7991.403251] cdb[0]=0x88: 88 00 00 00 00 00 f5 d5 a1 f0 00 00 00 f0 00 00
[ 7991.410232] blk_update_request: I/O error, dev sda, sector 4124418544
[ 8022.335762] usb 1-1.5.4: reset high-speed USB device number 5 using dwc_otg
[ 8022.417011] usb 1-1.5.4: USB disconnect, device number 5
[ 8022.435619] sd 0:0:0:0: [sda]  
[ 8022.438833] Result: hostbyte=0x01 driverbyte=0x00
[ 8022.443595] sd 0:0:0:0: [sda] CDB: 
[ 8022.447166] cdb[0]=0x88: 88 00 00 00 00 00 f5 d5 a2 e0 00 00 00 10 00 00
[ 8022.454133] blk_update_request: I/O error, dev sda, sector 4124418784
[ 8022.465193] sd 0:0:0:0: [sda]  
[ 8022.468442] Result: hostbyte=0x01 driverbyte=0x00
[ 8022.473207] sd 0:0:0:0: [sda] CDB: 
[ 8022.476761] cdb[0]=0x88: 88 00 00 00 00 00 f5 d5 a2 f0 00 00 00 f0 00 00
[ 8022.483721] blk_update_request: I/O error, dev sda, sector 4124418800
[ 8024.296853] usb 1-1.5.4: new high-speed USB device number 6 using dwc_otg
[ 8024.330635] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.341511] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.352686] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.363942] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.375431] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.387017] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.398615] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.410269] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.418369] usb 1-1.5.4: New USB device found, idVendor=152d, idProduct=0539
[ 8024.418379] usb 1-1.5.4: New USB device strings: Mfr=1, Product=2, SerialNumber=5
[ 8024.418386] usb 1-1.5.4: Product: USB to ATA/ATAPI Bridge
[ 8024.418392] usb 1-1.5.4: Manufacturer: JMicron
[ 8024.418398] usb 1-1.5.4: SerialNumber: 239C7E548FFF
[ 8024.419830] usb-storage 1-1.5.4:1.0: USB Mass Storage device detected
[ 8024.420271] scsi host1: usb-storage 1-1.5.4:1.0
[ 8024.478674] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8024.490996] Buffer I/O error on dev sda1, logical block 539903643, async page read
[ 8025.417797] scsi 1:0:0:0: Direct-Access     Sharkoon  H/W RAID0            PQ: 0 ANSI: 5
[ 8025.431029] sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
[ 8025.442048] sd 1:0:0:0: [sdb] 7813857280 512-byte logical blocks: (4.00 TB/3.63 TiB)
[ 8025.454605] sd 1:0:0:0: [sdb] Write Protect is off
[ 8025.461347] sd 1:0:0:0: [sdb] Mode Sense: 28 00 00 00
[ 8025.462178] sd 1:0:0:0: [sdb] No Caching mode page found
[ 8025.469414] sd 1:0:0:0: [sdb] Assuming drive cache: write through
[ 8025.479051] sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
[ 8025.494139] sd 1:0:0:0: Attached scsi generic sg0 type 0
[ 8025.968816]  sdb: sdb1
[ 8025.978257] sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
[ 8025.993777] sd 1:0:0:0: [sdb] Attached SCSI disk

@M-Tomohiro
Copy link

I think cause is heat.
Do you set heatsink on CPU and LAN9514?
LAN9514 is USB and Ethernet controller.

@JamesH65
Copy link
Contributor

Neither of those devices requires a heatsink.

@jackpgao
Copy link

same question. model 2 B with USB 3.0 HUB. The problem is the USB3.0. 2.0 works well.

@tehfink
Copy link

tehfink commented Jun 16, 2016

Also seeing this issue with a rpi model 2B & USB 3 self-powered hub, and 4GB USB seagate drive.

@humbledude
Copy link

humbledude commented Aug 10, 2016

I uses 2 external disks and only one disk has the same problem.
Problem is occur on IPTime 3035 external disk case + HDD.
It has external power adapter, so I connected the disk directly to rpi.
I recently bought rpi3 and this issue was not reproduced on my previous rpi1 B+
I guess this could be related to heat, its hot summer here and it seems to be reproduced after some time after reboot.

[123285.840778] usb 1-1.5: reset high-speed USB device number 5 using dwc_otg
[123286.223323] sd 0:0:0:0: [sdb] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[123286.223363] sd 0:0:0:0: [sdb] tag#0 CDB: opcode=0x28 28 00 4d 00 09 08 00 00 08 00
[123286.223390] blk_update_request: I/O error, dev sdb, sector 1291847944

@dminca
Copy link

dminca commented Apr 2, 2017

Having the same issue on a virused USB Flash Kingston DT101 G2 (16GiB). I think the virus affected its boot sectors and now the Kernel is unable to read the size of the device in order to mount it properly.

lsusb output (dimmed):

Bus 001 Device 012: ID 0951:1665 Kingston Technology Digital DataTraveler SE9 64GB

dmesg -T output:

# connect the usb
[Sun Apr  2 14:51:35 2017] usb 1-1.2: new high-speed USB device number 12 using ehci-pci
[Sun Apr  2 14:51:35 2017] usb-storage 1-1.2:1.0: USB Mass Storage device detected
[Sun Apr  2 14:51:35 2017] scsi host6: usb-storage 1-1.2:1.0
[Sun Apr  2 14:51:37 2017] scsi 6:0:0:0: Direct-Access     GENERIC  USB Mass Storage 1.00 PQ: 0 ANSI: 4 CCS
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: Attached scsi generic sg2 type 0
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] Read Capacity(10) failed: Result: hostbyte=0x00 driverbyte=0x08
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] Sense Key : 0x6 [current]
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] ASC=0x28 ASCQ=0x0
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] 0 512-byte logical blocks: (0 B/0 B)
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] 0-byte physical blocks
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] Write Protect is off
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] Mode Sense: 45 00 00 00
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] Read Capacity(10) failed: Result: hostbyte=0x00 driverbyte=0x08
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] Sense Key : 0x6 [current]
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] ASC=0x28 ASCQ=0x0
[Sun Apr  2 14:51:37 2017] sd 6:0:0:0: [sdb] Attached SCSI removable disk

# disconnect the usb
[Sun Apr  2 14:51:44 2017] usb 1-1.2: USB disconnect, device number 12

Since it didn't read the size, he didn't even attach the filesystem /dev/sdX:

  • Read Capacity(10) failed: Result: hostbyte=0x00 driverbyte=0x08 - couldn't guess the capacity of the Flash USB
  • [sdb] 0 512-byte logical blocks: (0 B/0 B) - no size, couldn't mount it.

output of lsblk:

NAME              MAJ:MIN RM   SIZE RO TYPE MOUNTPOINT
sda                 8:0    0 232.9G  0 disk
└─sda1              8:1    0 232.9G  0 part
  ├─root--vg-boot 254:0    0   3.1G  0 lvm  /boot
  ├─root--vg-root 254:1    0    50G  0 lvm  /
  ├─root--vg-swap 254:2    0   500M  0 lvm  [SWAP]
  └─root--vg-home 254:3    0   150G  0 lvm  /home
sr0                11:0    1  1024M  0 rom

CONCLUSION boot sectors affected, USB Flash is bricked. 🗑️ ♻️

@adde88
Copy link

adde88 commented Apr 23, 2017

Hi from the OpenWRT community! ✋
I was curious to if a solution was found to this problem?
I'm having the exact same problem on my device on kernel versions: 3.18.20 to 3.18.36 !
It seems to be related to the SD-card. Replacing my SD-card with a USB-thumb drive (mounted exactly similar), "fixes" the problem. But i miss my SD-card. 😭

When it happens very similar error-messages as above shows, and the sd-card disconnects from the device, and then re-appears a second later with a new identifier each time (/dev/sda -> /dev/sdb - /dev/sdc)
Running badblocks on the sd-card will also trigger it each time.
Very often when simply reading/writing to the device it happens, but never on standby.

I know this thread is about Raspberry Pi, not OpenWRT. But i had to ask if you guys found a solution, because i'm pretty desperate to get this fixed. 😃

@P33M
Copy link
Contributor

P33M commented May 4, 2017

For everyone experiencing random device disconnects, what happens if you put a USB hub between the Pi and the device in question?

@JamesH65 JamesH65 added the Waiting for external input Waiting for a comment from the originator of the issue, or a collaborator. label May 18, 2017
@ben-ba
Copy link

ben-ba commented May 28, 2017

Same problem here with
OSMC (up to date)
RaspberryPi 3
USB 2.0 Hub (Hama 1 to 4 - https://de.hama.com/00078472/hama-usb-20-hub-14-with-power-supply-black-cardboard-box?srcLang=0&targetLang=1 )

Details about the usb hub, maybe to identify the chipset. Also have a look at the max power of 100mA, the drives have a max power up to 500mA. Maybe this would explain, why some hubs works (especially some chipsets) and others not, and why sometimes it seems, that a better power supply would do the trick also.:

osmc@osmc:$ lsusb -D /dev/bus/usb/001/030
Device: ID 1a40:0101 Terminus Technology Inc. 4-Port HUB
Couldn't open device, some information will be missing
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 9 Hub
bDeviceSubClass 0 Unused
bDeviceProtocol 1 Single TT
bMaxPacketSize0 64
idVendor 0x1a40 Terminus Technology Inc.
idProduct 0x0101 4-Port HUB
bcdDevice 1.11
iManufacturer 0
iProduct 1
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 25
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xe0
Self Powered
Remote Wakeup
MaxPower 100mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 9 Hub
bInterfaceSubClass 0 Unused
bInterfaceProtocol 0 Full speed (or root) hub
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0001 1x 1 bytes
bInterval 12
osmc@osmc:
$

osmc@osmc:~$ sudo lsusb -t
/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M
|__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/5p, 480M
|__ Port 1: Dev 3, If 0, Class=Vendor Specific Class, Driver=smsc95xx, 480M
|__ Port 3: Dev 30, If 0, Class=Hub, Driver=hub/4p, 480M
|__ Port 3: Dev 33, If 0, Class=Mass Storage, Driver=usb-storage, 480M
|__ Port 4: Dev 34, If 0, Class=Mass Storage, Driver=usb-storage, 480M

two usb drives on hub, both WD MyPassport, 4TB,
one (sda1) NTFS, the other one (sbb1) is ext4 formatted.

/dev/sda1 /media/6080669B80667804 fuseblk rw,nosuid,nodev,relatime,user_id=0,group_id=0,default_permissions,allow_other,blksize=4096 0 0
/dev/sdb1 /media/MyPassport2 ext4 rw,noatime,data=ordered 0 0

Getting trouble when i rsync all data (nearly 4TB) from the "NTFS" drive to the "ext4" drive, dmsg output:

[ +0,001428] sd 17:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
[ +0,001299] sd 17:0:0:0: [sdb] Attached SCSI disk
[ +1,116244] buffer_io_error: 3498 callbacks suppressed
[ +0,000016] Buffer I/O error on dev sdc1, logical block 38374017, async page read
[ +0,000207] Buffer I/O error on dev sdc1, logical block 38374049, async page read
[ +0,000109] Buffer I/O error on dev sdc1, logical block 38374017, async page read
[ +0,003382] Buffer I/O error on dev sdc1, logical block 38374081, async page read
[ +0,000358] Buffer I/O error on dev sdc1, logical block 38374113, async page read
[ +0,000115] Buffer I/O error on dev sdc1, logical block 38374081, async page read
[ +0,005591] Buffer I/O error on dev sdc1, logical block 38374145, async page read
[ +0,000228] Buffer I/O error on dev sdc1, logical block 38374177, async page read
[ +0,000840] Buffer I/O error on dev sdc1, logical block 38374145, async page read
[ +0,002943] Buffer I/O error on dev sdc1, logical block 38374209, async page read
[ +0,160145] scsi 16:0:0:1: Attached scsi generic sg3 type 13
[ +0,047971] sda: sda1
[ +0,001202] sd 16:0:0:0: [sda] Very big device. Trying to use READ CAPACITY(16).
[ +0,001244] sd 16:0:0:0: [sda] Attached SCSI disk
[ +4,783473] buffer_io_error: 3893 callbacks suppressed
[ +0,000017] Buffer I/O error on dev sdc1, logical block 38520130, async page read
[ +0,006422] Buffer I/O error on dev sdc1, logical block 38520194, async page read
[ +0,000415] Buffer I/O error on dev sdc1, logical block 38520226, async page read
[ +0,000144] Buffer I/O error on dev sdc1, logical block 38520194, async page read
[ +0,004098] Buffer I/O error on dev sdc1, logical block 38520258, async page read
[ +0,000234] Buffer I/O error on dev sdc1, logical block 38520290, async page read
[ +0,000098] Buffer I/O error on dev sdc1, logical block 38520258, async page read
[ +0,003047] Buffer I/O error on dev sdc1, logical block 38520322, async page read
[ +0,000409] Buffer I/O error on dev sdc1, logical block 38520354, async page read
[ +0,000153] Buffer I/O error on dev sdc1, logical block 38520322, async page read

u see now sdc1 because the target drive, with ext4 get auto remounted as read only.

a manually remount did the trick for a few hours copying data...

all my drive in detail:

osmc@osmc:~$ parted -l
Model: WD My Passport 259D (scsi)
Disk /dev/sda: 4001GB
Sector size (logical/physical): 512B/4096B
Partition Table: gpt
Disk Flags:

Number Start End Size File system Name Flags
1 1049kB 4001GB 4001GB ntfs My Passport msftdata

Model: WD My Passport 25E2 (scsi)
Disk /dev/sdb: 4001GB
Sector size (logical/physical): 512B/4096B
Partition Table: gpt
Disk Flags:

Number Start End Size File system Name Flags
1 1049kB 4001GB 4001GB ext4 MyPassport2

Model: SD SL64G (sd/mmc)
Disk /dev/mmcblk0: 63,9GB
Sector size (logical/physical): 512B/512B
Partition Table: msdos
Disk Flags:

Number Start End Size Type File system Flags
1 1049kB 256MB 255MB primary fat32 lba
2 257MB 63,9GB 63,6GB primary ext4

osmc@osmc:~$

@JamesH65
Copy link
Contributor

@P33M Is this covered by other USB issues? Can it be closed?

@JamesH65 JamesH65 added the Closing due to inaction Issue likely to be closed due to lack of recent comments label Sep 13, 2017
@M-Tomohiro
Copy link

hi, I explain about my case.

1st:"environment"
raspberry pi 2 model B.
SSD connect to USB port.
OS ubuntu for raspberry pi.

Test case is copy 50GB(1000 files) to SSD from PC.
error : Buffer I/O error on dev sdxx.

2nd:"environment"
raspberry pi 2 model B.(not 1st device, it mean the i have two raspberry pi. )
SSD connect to USB port.(device is same as 1st)
OS ubuntu for raspberry pi.(device is same as 1st)

Test case is copy 50GB(1000 files) to SSD from PC.
It worked very well.

Different point is raspberry pi only. other all environment same as 1st.
So, In my understanding it is a problem of raspberry pi HW.

@JamesH65
Copy link
Contributor

JamesH65 commented Dec 4, 2017

@P33M @M-Tomohiro Any further progress on this one?

@M-Tomohiro
Copy link

@JamesH65 Yes, there is no progress.

@Dreaky255
Copy link

Same issue for me, and solved.
It was a power issue : My raspberry and hard drive (2Tb) were both powered through an usb hub-powered (2.5A).
I had a DC power switch (jack) to the hub to easily power on and off my raspberry. The switch was actually too resistent to let pass enough power to the whole thing. It was working with a 1TB hard drive, but not with my brand new 2TB.
After deleting the switch and directly powering the hub with the DC adaptor, problem has disappeared.

Hope it helps some of you.

Sry for my poor english.

@JamesH65
Copy link
Contributor

This issue will be closed within 30 days unless further interactions are posted. If you wish this issue to remain open, please add a comment. A closed issue may be reopened if requested.

@JamesH65 JamesH65 added the Close within 30 days Issue will be closed within 30 days unless requested to stay open label Jun 27, 2018
@adde88
Copy link

adde88 commented Jul 4, 2018

I would like this issue to remain open, as i've yet to find a fix for it anywhere. And that would be really awesome to get. :)
But if it needs to be closed, i also respect that.

@JamesH65
Copy link
Contributor

JamesH65 commented Jul 4, 2018

@adde88 I presume that you are using an up to date Raspbian, and that everything is sufficiently well powered?

@adde88
Copy link

adde88 commented Jul 4, 2018

No, i'm not. That's why i'm ok with you closing it.
The reason i wanted this open is because i'm having the exact same issue on another emedded device, running OpenWRT. (Me and alot of other people)
My device is running the exact same version of the kernel.
Based on that my gut is telling me that there's "something" with this kernel version.
I also haven't found another place where this issue has been discussed.
So therefore i was hoping that someone found what's the cause of this. If it's power-related, or a kernel-bug, anything would be interesting to find out. As it could lead to the bug being fixed on our devices as well.

But again, i respect your decision to close this, considering my issue is not directly related to the Raspberry Pi.

@JamesH65
Copy link
Contributor

JamesH65 commented Jul 5, 2018

OK, since this is no longer an RPi issue (as far as I can tell), I'll close it.

@JamesH65 JamesH65 closed this as completed Jul 5, 2018
@pelwell
Copy link
Contributor

pelwell commented Jul 5, 2018

Note that closed issues can still be searched and commented on.

@risa2000
Copy link

FWIW I have just "discovered" the same problem. I am running latest Raspbian Stretch Linux version 4.14.62-v7+, on Raspberry Pi 3 Model B Rev 1.2. When connecting my brand new USB<>SATA adapter cable called "Qicent" (https://www.amazon.de/gp/product/B01MAWO4V2) which is identified by kernel log as:

[    4.541428] usb 1-1.4: new high-speed USB device number 8 using dwc_otg
[    4.672042] usb 1-1.4: New USB device found, idVendor=2537, idProduct=1068
[    4.672055] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    4.672063] usb 1-1.4: Product: NS106X
[    4.672072] usb 1-1.4: Manufacturer: Norelsys
[    4.672080] usb 1-1.4: SerialNumber: 0123456789ABCDE
[    4.672813] usb-storage 1-1.4:1.0: USB Mass Storage device detected
[    4.675619] scsi host1: usb-storage 1-1.4:1.0
...
[    9.258261] scsi 1:0:0:0: Direct-Access     Generic  HDD              0    PQ: 0 ANSI: 0
[    9.259226] sd 1:0:0:0: Attached scsi generic sg1 type 0
[    9.261147] sd 1:0:0:0: [sdb] Attached SCSI removable disk

It seems the Manufacturer and Product is similar to the already reported bridge chips above. The sudo lsusb -v -d 2537:1068 shows:

Bus 001 Device 008: ID 2537:1068
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.10
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  idVendor           0x2537
  idProduct          0x1068
  bcdDevice            1.00
  iManufacturer           1 Norelsys
  iProduct                2 NS106X
  iSerial                 3 0123456789ABCDE
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength           32
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0
    bmAttributes         0xc0
      Self Powered
    MaxPower                2mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     80 Bulk-Only
      iInterface              0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
Binary Object Store Descriptor:
  bLength                 5
  bDescriptorType        15
  wTotalLength           22
  bNumDeviceCaps          2
  USB 2.0 Extension Device Capability:
    bLength                 7
    bDescriptorType        16
    bDevCapabilityType      2
    bmAttributes   0x00000002
      Link Power Management (LPM) Supported
  SuperSpeed USB Device Capability:
    bLength                10
    bDescriptorType        16
    bDevCapabilityType      3
    bmAttributes         0x00
    wSpeedsSupported   0x000e
      Device can operate at Full Speed (12Mbps)
      Device can operate at High Speed (480Mbps)
      Device can operate at SuperSpeed (5Gbps)
    bFunctionalitySupport   1
      Lowest fully-functional device speed is Full Speed (12Mbps)
    bU1DevExitLat          10 micro seconds
    bU2DevExitLat        2047 micro seconds
Device Status:     0x0001
  Self Powered

What I find interesting is MaxPower 2mA.

In my case I am running two additional USB devices on my RPi 3B:
ZWave USB stick
64GB flash stick
so the RPi is pretty loaded (uses 2.5A PS - at least it is written there), but what I find interesting is that I observe the complete USB reset in kernel, when I connect the Qicent cable even without any disk attached, just the adapter is enough to break it down. On the other hand, disconnecting the cable does not do anything to the system. Rebooting with the cable already connected and with the disk attached is also fine.

Below is the dmesg from the crashing system, which shows that once the new USB device is attached, current devices become unavailable and then they are re-enumerated, which moves my USB flash stick from /dev/sda to /dev/sdb and completely confuses the system.

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.14.62-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1134 SMP Tue Aug 14 17:10:10 BST 2018
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 8 MiB at 0x3ac00000
[    0.000000] On node 0 totalpages: 242688
[    0.000000] free_area_init_node: node 0, pgdat 80c85000, node_mem_map ba39f000
[    0.000000]   Normal zone: 2133 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 242688 pages, LIFO batch:31
[    0.000000] percpu: Embedded 17 pages/cpu @ba348000 s38720 r8192 d22720 u69632
[    0.000000] pcpu-alloc: s38720 r8192 d22720 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555
[    0.000000] Kernel command line: 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=e784d122-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 940228K/970752K available (7168K kernel code, 575K rwdata, 2076K rodata, 1024K init, 706K bss, 22332K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xbb800000 - 0xff800000   (1088 MB)
                   lowmem  : 0x80000000 - 0xbb400000   ( 948 MB)
                   modules : 0x7f000000 - 0x80000000   (  16 MB)
                     .text : 0x80008000 - 0x80800000   (8160 kB)
                     .init : 0x80b00000 - 0x80c00000   (1024 kB)
                     .data : 0x80c00000 - 0x80c8fef4   ( 576 kB)
                      .bss : 0x80c96f34 - 0x80d478b4   ( 707 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 25267 entries in 75 pages
[    0.000000] Hierarchical RCU implementation.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000023] Switching to timer-based delay loop, resolution 52ns
[    0.000274] Console: colour dummy device 80x30
[    0.000807] console [tty1] enabled
[    0.000845] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.000884] pid_max: default: 32768 minimum: 301
[    0.001212] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001244] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.002197] Disabling memory control group subsystem
[    0.002291] CPU: Testing write buffer coherency: ok
[    0.002713] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.003131] Setting up static identity map for 0x100000 - 0x10003c
[    0.003271] Hierarchical SRCU implementation.
[    0.003965] smp: Bringing up secondary CPUs ...
[    0.004761] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.005598] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.006417] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.006522] smp: Brought up 1 node, 4 CPUs
[    0.006595] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.006615] CPU: All CPU(s) started in HYP mode.
[    0.006633] CPU: Virtualization extensions available.
[    0.007528] devtmpfs: initialized
[    0.017708] random: get_random_u32 called from bucket_table_alloc+0xfc/0x24c with crng_init=0
[    0.018380] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.018623] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.018667] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.019236] pinctrl core: initialized pinctrl subsystem
[    0.020033] NET: Registered protocol family 16
[    0.022632] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.027464] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.027496] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.027715] Serial: AMBA PL011 UART driver
[    0.029382] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.029862] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[    0.061637] bcm2835-dma 3f007000.dma: DMA legacy API manager at bb813000, dmachans=0x1
[    0.063079] SCSI subsystem initialized
[    0.063329] usbcore: registered new interface driver usbfs
[    0.063398] usbcore: registered new interface driver hub
[    0.063499] usbcore: registered new device driver usb
[    0.070079] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-08-16 17:30
[    0.071413] clocksource: Switched to clocksource arch_sys_counter
[    0.147891] VFS: Disk quotas dquot_6.6.0
[    0.148003] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.148205] FS-Cache: Loaded
[    0.148420] CacheFiles: Loaded
[    0.157326] NET: Registered protocol family 2
[    0.158062] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.158191] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.158392] TCP: Hash tables configured (established 8192 bind 8192)
[    0.158537] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.158597] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.158840] NET: Registered protocol family 1
[    0.159314] RPC: Registered named UNIX socket transport module.
[    0.159338] RPC: Registered udp transport module.
[    0.159357] RPC: Registered tcp transport module.
[    0.159376] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.160866] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.163663] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.171816] FS-Cache: Netfs 'nfs' registered for caching
[    0.172439] NFS: Registering the id_resolver key type
[    0.172482] Key type id_resolver registered
[    0.172501] Key type id_legacy registered
[    0.172530] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.174477] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    0.174634] io scheduler noop registered
[    0.174656] io scheduler deadline registered (default)
[    0.174951] io scheduler cfq registered
[    0.174972] io scheduler mq-deadline registered
[    0.174993] io scheduler kyber registered
[    0.177706] BCM2708FB: allocated DMA memory fad10000
[    0.177750] BCM2708FB: allocated DMA channel 0 @ bb813000
[    0.186287] Console: switching to colour frame buffer device 82x26
[    0.194555] bcm2835-rng 3f104000.rng: hwrng registered
[    0.196977] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.202140] vc-sm: Videocore shared memory driver
[    0.204722] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    0.218987] brd: module loaded
[    0.229904] loop: module loaded
[    0.232229] Loading iSCSI transport class v2.0-870.
[    0.235193] libphy: Fixed MDIO Bus: probed
[    0.237566] usbcore: registered new interface driver lan78xx
[    0.239893] usbcore: registered new interface driver smsc95xx
[    0.242073] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.272132] dwc_otg 3f980000.usb: base=0xf0980000
[    0.474503] Core Release: 2.80a
[    0.476681] Setting default values for core params
[    0.478943] Finished setting default values for core params
[    0.681521] Using Buffer DMA mode
[    0.683797] Periodic Transfer Interrupt Enhancement - disabled
[    0.686191] Multiprocessor Interrupt Enhancement - disabled
[    0.688567] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.690902] Dedicated Tx FIFOs mode
[    0.693547] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xbad04000 dma = 0xfad04000 len=9024
[    0.698124] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    0.709027] dwc_otg: Microframe scheduler enabled
[    0.709075] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x805e8e80
[    0.711332] WARN::hcd_init_fiq:460: FIQ ASM at 0x805e91e8 length 36
[    0.713562] WARN::hcd_init_fiq:486: MPHI regs_base at 0xf0006000
[    0.715895] dwc_otg 3f980000.usb: DWC OTG Controller
[    0.718175] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    0.720510] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[    0.722848] Init: Port Power? op_state=1
[    0.725105] Init: Power Port (0)
[    0.727482] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.729793] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.732109] usb usb1: Product: DWC OTG Controller
[    0.734360] usb usb1: Manufacturer: Linux 4.14.62-v7+ dwc_otg_hcd
[    0.736634] usb usb1: SerialNumber: 3f980000.usb
[    0.739467] hub 1-0:1.0: USB hub found
[    0.741703] hub 1-0:1.0: 1 port detected
[    0.744259] dwc_otg: FIQ enabled
[    0.744265] dwc_otg: NAK holdoff enabled
[    0.744270] dwc_otg: FIQ split-transaction FSM enabled
[    0.744279] Module dwc_common_port init
[    0.744500] usbcore: registered new interface driver usb-storage
[    0.746786] mousedev: PS/2 mouse device common for all mice
[    0.749007] IR NEC protocol handler initialized
[    0.751174] IR RC5(x/sz) protocol handler initialized
[    0.753403] IR RC6 protocol handler initialized
[    0.755582] IR JVC protocol handler initialized
[    0.757660] IR Sony protocol handler initialized
[    0.759745] IR SANYO protocol handler initialized
[    0.761849] IR Sharp protocol handler initialized
[    0.763843] IR MCE Keyboard/mouse protocol handler initialized
[    0.765871] IR XMP protocol handler initialized
[    0.768538] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[    0.770879] bcm2835-cpufreq: min=600000 max=1200000
[    0.773359] sdhci: Secure Digital Host Controller Interface driver
[    0.775486] sdhci: Copyright(c) Pierre Ossman
[    0.777916] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[    0.780386] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    0.782703] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.786295] ledtrig-cpu: registered to indicate activity on CPUs
[    0.788709] hidraw: raw HID events driver (C) Jiri Kosina
[    0.791181] usbcore: registered new interface driver usbhid
[    0.793508] usbhid: USB HID core driver
[    0.796323] vchiq: vchiq_init_state: slot_zero = bad80000, is_master = 0
[    0.800059] [vc_sm_connected_init]: start
[    0.808792] [vc_sm_connected_init]: end - returning 0
[    0.811724] Initializing XFRM netlink socket
[    0.814100] NET: Registered protocol family 17
[    0.816556] Key type dns_resolver registered
[    0.819319] Registering SWP/SWPB emulation handler
[    0.822325] registered taskstats version 1
[    0.830565] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    0.833157] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[    0.839766] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[    0.842325] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[    0.902032] sdhost: log_buf @ bad07000 (fad07000)
[    0.940670] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    0.944660] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.948504] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.953480] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    0.961541] Indeed it is in host mode hprt0 = 00021501
[    1.023669] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    1.026805] of_cfs_init
[    1.028945] of_cfs_init: OK
[    1.031341] Waiting for root device PARTUUID=e784d122-02...
[    1.041907] random: fast init done
[    1.136121] mmc1: new high speed SDIO card at address 0001
[    1.162690] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.170524] mmc0: new high speed SDHC card at address aaaa
[    1.172822] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    1.175211] Indeed it is in host mode hprt0 = 00001101
[    1.237845] mmcblk0: mmc0:aaaa SC16G 14.8 GiB
[    1.245539]  mmcblk0: p1 p2
[    1.282911] NOHZ: local_softirq_pending 40
[    1.285010] NOHZ: local_softirq_pending 40
[    1.286994] NOHZ: local_softirq_pending 40
[    1.288886] NOHZ: local_softirq_pending 40
[    1.290771] NOHZ: local_softirq_pending 40
[    1.292658] NOHZ: local_softirq_pending 40
[    1.294539] NOHZ: local_softirq_pending 40
[    1.296326] NOHZ: local_softirq_pending 40
[    1.298012] NOHZ: local_softirq_pending 40
[    1.299605] NOHZ: local_softirq_pending 40
[    1.306622] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.309961] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.322504] devtmpfs: mounted
[    1.327165] Freeing unused kernel memory: 1024K
[    1.421737] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    1.423517] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.425845] hub 1-1:1.0: USB hub found
[    1.427575] hub 1-1:1.0: 5 ports detected
[    1.741447] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    1.790741] systemd[1]: System time before build time, advancing clock.
[    1.881715] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    1.883635] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.888239] smsc95xx v1.0.6
[    1.911538] NET: Registered protocol family 10
[    1.914806] Segment Routing with IPv6
[    1.929501] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.949449] random: systemd: uninitialized urandom read (16 bytes read)
[    1.957102] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    1.965647] systemd[1]: Detected architecture arm.
[    1.975197] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:0b:02:74
[    1.992750] systemd[1]: Set hostname to <raspberrypi>.
[    2.022314] random: systemd: uninitialized urandom read (16 bytes read)
[    2.038409] random: systemd-cryptse: uninitialized urandom read (16 bytes read)
[    2.071481] usb 1-1.5: new full-speed USB device number 4 using dwc_otg
[    2.171471] usb 1-1.5: device descriptor read/64, error -32
[    2.391466] usb 1-1.5: device descriptor read/64, error -32
[    2.555319] systemd[1]: Listening on udev Kernel Socket.
[    2.562026] systemd[1]: Created slice System Slice.
[    2.568274] systemd[1]: Created slice system-getty.slice.
[    2.574163] systemd[1]: Listening on fsck to fsckd communication Socket.
[    2.582776] systemd[1]: Mounting Debug File System...
[    2.589819] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    2.599183] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    2.611483] usb 1-1.5: new full-speed USB device number 5 using dwc_otg
[    2.711558] usb 1-1.5: device descriptor read/64, error -32
[    2.931475] usb 1-1.5: device descriptor read/64, error -32
[    3.051667] usb 1-1-port5: attempt power cycle
[    3.135819] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    3.711494] usb 1-1.5: new full-speed USB device number 6 using dwc_otg
[    3.745238] usb 1-1.5: New USB device found, idVendor=0658, idProduct=0200
[    3.745256] usb 1-1.5: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.806610] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    3.809561] bcm2835_alsa bcm2835_alsa: card created with 8 channels
[    3.950697] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[    3.956499] brcmfmac: brcmf_fw_map_chip_to_name: using brcm/brcmfmac43430-sdio.bin for chip 0x00a9a6(43430) rev 0x000001
[    3.956733] usbcore: registered new interface driver brcmfmac
[    4.041526] usb 1-1.3: new high-speed USB device number 7 using dwc_otg
[    4.172266] usb 1-1.3: New USB device found, idVendor=0781, idProduct=5571
[    4.172280] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    4.172298] usb 1-1.3: Product: Cruzer Fit
[    4.172312] usb 1-1.3: Manufacturer: SanDisk
[    4.172324] usb 1-1.3: SerialNumber: 4C530001140213103403
[    4.174677] usb-storage 1-1.3:1.0: USB Mass Storage device detected
[    4.200875] scsi host0: usb-storage 1-1.3:1.0
[    4.217435] brcmfmac: brcmf_c_preinit_dcmds: Firmware version = wl0: Oct 23 2017 03:55:53 version 7.45.98.38 (r674442 CY) FWID 01-e58d219f
[    4.218206] brcmfmac: brcmf_c_preinit_dcmds: CLM version = API: 12.2 Data: 7.11.15 Compiler: 1.24.2 ClmImport: 1.24.1 Creation: 2014-05-26 10:53:55 Inc Data: 9.10.39 Inc Compiler: 1.29.4 Inc ClmImport: 1.36.3 Creation: 2017-10-23 03:47:14 
[    4.273494] cdc_acm 1-1.5:1.0: ttyACM0: USB ACM device
[    4.274616] usbcore: registered new interface driver cdc_acm
[    4.274627] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
[    5.272561] scsi 0:0:0:0: Direct-Access     SanDisk  Cruzer Fit       1.00 PQ: 0 ANSI: 6
[    5.274101] sd 0:0:0:0: [sda] 123174912 512-byte logical blocks: (63.1 GB/58.7 GiB)
[    5.275380] sd 0:0:0:0: [sda] Write Protect is off
[    5.275395] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[    5.275732] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[    5.291943] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    5.301203]  sda: sda1
[    5.304416] sd 0:0:0:0: [sda] Attached SCSI removable disk
[    5.527104] random: crng init done
[    5.527119] random: 7 urandom warning(s) missed due to ratelimiting
[    5.692289] F2FS-fs (sda1): Mounted with checkpoint version = 4bbc4
[    5.858488] systemd-journald[116]: Received request to flush runtime journal from PID 1
[    6.578811] uart-pl011 3f201000.serial: no DMA platform data
[    7.115333] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    7.115346] brcmfmac: power management disabled
[    7.171062] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[    7.933569] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[    9.472460] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC1E1
[   11.026294] Bluetooth: Core ver 2.22
[   11.026372] NET: Registered protocol family 31
[   11.026380] Bluetooth: HCI device and connection manager initialized
[   11.026400] Bluetooth: HCI socket layer initialized
[   11.026414] Bluetooth: L2CAP socket layer initialized
[   11.026444] Bluetooth: SCO socket layer initialized
[   11.040637] Bluetooth: HCI UART driver ver 2.3
[   11.040652] Bluetooth: HCI UART protocol H4 registered
[   11.040658] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   11.040858] Bluetooth: HCI UART protocol Broadcom registered
[   11.212986] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   11.212993] Bluetooth: BNEP filters: protocol multicast
[   11.213007] Bluetooth: BNEP socket layer initialized
[   30.184963] NET: Registered protocol family 38
[  140.139184] usb 1-1.3: USB disconnect, device number 7
[  140.166996] ------------[ cut here ]------------
[  140.167039] WARNING: CPU: 0 PID: 499 at fs/fs-writeback.c:2162 __mark_inode_dirty+0x2f4/0x408
[  140.167045] bdi-block not registered
[  140.167050] Modules linked in: aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm serdev bluetooth ecdh_generic sg cdc_acm brcmfmac brcmutil cfg80211 rfkill snd_bcm2835(C) snd_pcm snd_timer snd fixed uio_pdrv_genirq uio ip_tables x_tables ipv6
[  140.167204] CPU: 0 PID: 499 Comm: rs:main Q:Reg Tainted: G         C      4.14.62-v7+ #1134
[  140.167209] Hardware name: BCM2835
[  140.167240] [<8010ffd8>] (unwind_backtrace) from [<8010c240>] (show_stack+0x20/0x24)
[  140.167258] [<8010c240>] (show_stack) from [<80787284>] (dump_stack+0xd4/0x118)
[  140.167277] [<80787284>] (dump_stack) from [<8011da6c>] (__warn+0xf8/0x110)
[  140.167291] [<8011da6c>] (__warn) from [<8011dacc>] (warn_slowpath_fmt+0x48/0x50)
[  140.167307] [<8011dacc>] (warn_slowpath_fmt) from [<802bb818>] (__mark_inode_dirty+0x2f4/0x408)
[  140.167330] [<802bb818>] (__mark_inode_dirty) from [<80429628>] (f2fs_set_page_dirty_nobuffers+0x114/0x144)
[  140.167349] [<80429628>] (f2fs_set_page_dirty_nobuffers) from [<8042978c>] (f2fs_set_data_page_dirty+0x134/0x148)
[  140.167369] [<8042978c>] (f2fs_set_data_page_dirty) from [<8022c284>] (set_page_dirty+0x84/0xcc)
[  140.167387] [<8022c284>] (set_page_dirty) from [<804222e0>] (f2fs_write_end+0x11c/0x2a4)
[  140.167403] [<804222e0>] (f2fs_write_end) from [<8021e830>] (generic_perform_write+0x118/0x1b0)
[  140.167420] [<8021e830>] (generic_perform_write) from [<802210c8>] (__generic_file_write_iter+0x19c/0x1f8)
[  140.167437] [<802210c8>] (__generic_file_write_iter) from [<8040621c>] (f2fs_file_write_iter+0xe4/0x218)
[  140.167458] [<8040621c>] (f2fs_file_write_iter) from [<8028b05c>] (__vfs_write+0xe0/0x138)
[  140.167475] [<8028b05c>] (__vfs_write) from [<8028b27c>] (vfs_write+0xb4/0x1bc)
[  140.167491] [<8028b27c>] (vfs_write) from [<8028b4cc>] (SyS_write+0x54/0xb0)
[  140.167509] [<8028b4cc>] (SyS_write) from [<80108060>] (ret_fast_syscall+0x0/0x28)
[  140.167545] ---[ end trace 406cdc4a71053c21 ]---
[  140.196584] blk_partition_remap: fail for partition 1
[  140.941828] usb 1-1.4: new high-speed USB device number 8 using dwc_otg
[  141.072573] usb 1-1.4: New USB device found, idVendor=2537, idProduct=1068
[  141.072580] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  141.072585] usb 1-1.4: Product: NS106X
[  141.072589] usb 1-1.4: Manufacturer: Norelsys
[  141.072593] usb 1-1.4: SerialNumber: 0123456789ABCDE
[  141.073042] usb-storage 1-1.4:1.0: USB Mass Storage device detected
[  141.073255] scsi host1: usb-storage 1-1.4:1.0
[  141.091343] ------------[ cut here ]------------
[  141.091362] WARNING: CPU: 1 PID: 499 at fs/fs-writeback.c:2162 __mark_inode_dirty+0x2f4/0x408
[  141.091366] bdi-block not registered
[  141.091368] Modules linked in: aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm serdev bluetooth ecdh_generic sg cdc_acm brcmfmac brcmutil cfg80211 rfkill snd_bcm2835(C) snd_pcm snd_timer snd fixed uio_pdrv_genirq uio ip_tables x_tables ipv6
[  141.091444] CPU: 1 PID: 499 Comm: rs:main Q:Reg Tainted: G        WC      4.14.62-v7+ #1134
[  141.091447] Hardware name: BCM2835
[  141.091466] [<8010ffd8>] (unwind_backtrace) from [<8010c240>] (show_stack+0x20/0x24)
[  141.091476] [<8010c240>] (show_stack) from [<80787284>] (dump_stack+0xd4/0x118)
[  141.091485] [<80787284>] (dump_stack) from [<8011da6c>] (__warn+0xf8/0x110)
[  141.091493] [<8011da6c>] (__warn) from [<8011dacc>] (warn_slowpath_fmt+0x48/0x50)
[  141.091500] [<8011dacc>] (warn_slowpath_fmt) from [<802bb818>] (__mark_inode_dirty+0x2f4/0x408)
[  141.091513] [<802bb818>] (__mark_inode_dirty) from [<80424148>] (reserve_new_blocks+0x36c/0x40c)
[  141.091522] [<80424148>] (reserve_new_blocks) from [<8042434c>] (f2fs_reserve_block+0x134/0x190)
[  141.091530] [<8042434c>] (f2fs_reserve_block) from [<80418a1c>] (f2fs_convert_inline_page+0x1a8/0x370)
[  141.091537] [<80418a1c>] (f2fs_convert_inline_page) from [<80418df8>] (f2fs_convert_inline_inode+0x214/0x294)
[  141.091545] [<80418df8>] (f2fs_convert_inline_inode) from [<80426ad8>] (f2fs_preallocate_blocks+0x144/0x164)
[  141.091553] [<80426ad8>] (f2fs_preallocate_blocks) from [<804061b0>] (f2fs_file_write_iter+0x78/0x218)
[  141.091564] [<804061b0>] (f2fs_file_write_iter) from [<8028b05c>] (__vfs_write+0xe0/0x138)
[  141.091572] [<8028b05c>] (__vfs_write) from [<8028b27c>] (vfs_write+0xb4/0x1bc)
[  141.091581] [<8028b27c>] (vfs_write) from [<8028b4cc>] (SyS_write+0x54/0xb0)
[  141.091590] [<8028b4cc>] (SyS_write) from [<80108060>] (ret_fast_syscall+0x0/0x28)
[  141.091594] ---[ end trace 406cdc4a71053c22 ]---
[  141.091643] blk_partition_remap: fail for partition 1
[  141.711864] usb 1-1.3: new high-speed USB device number 9 using dwc_otg
[  141.842724] usb 1-1.3: New USB device found, idVendor=0781, idProduct=5571
[  141.842736] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  141.842745] usb 1-1.3: Product: Cruzer Fit
[  141.842754] usb 1-1.3: Manufacturer: SanDisk
[  141.842762] usb 1-1.3: SerialNumber: 4C530001140213103403
[  141.843505] usb-storage 1-1.3:1.0: USB Mass Storage device detected
[  141.843886] scsi host2: usb-storage 1-1.3:1.0
[  142.873046] scsi 2:0:0:0: Direct-Access     SanDisk  Cruzer Fit       1.00 PQ: 0 ANSI: 6
[  142.874077] sd 2:0:0:0: Attached scsi generic sg0 type 0
[  142.875605] sd 2:0:0:0: [sdb] 123174912 512-byte logical blocks: (63.1 GB/58.7 GiB)
[  142.876866] sd 2:0:0:0: [sdb] Write Protect is off
[  142.876879] sd 2:0:0:0: [sdb] Mode Sense: 43 00 00 00
[  142.877276] sd 2:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[  142.882339] ------------[ cut here ]------------
[  142.882369] WARNING: CPU: 1 PID: 499 at fs/fs-writeback.c:2162 __mark_inode_dirty+0x2f4/0x408
[  142.882375] bdi-block not registered
[  142.882381] Modules linked in: aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm serdev bluetooth ecdh_generic sg cdc_acm brcmfmac brcmutil cfg80211 rfkill snd_bcm2835(C) snd_pcm snd_timer snd fixed uio_pdrv_genirq uio ip_tables x_tables ipv6
[  142.882513] CPU: 1 PID: 499 Comm: rs:main Q:Reg Tainted: G        WC      4.14.62-v7+ #1134
[  142.882518] Hardware name: BCM2835
[  142.882548] [<8010ffd8>] (unwind_backtrace) from [<8010c240>] (show_stack+0x20/0x24)
[  142.882565] [<8010c240>] (show_stack) from [<80787284>] (dump_stack+0xd4/0x118)
[  142.882582] [<80787284>] (dump_stack) from [<8011da6c>] (__warn+0xf8/0x110)
[  142.882596] [<8011da6c>] (__warn) from [<8011dacc>] (warn_slowpath_fmt+0x48/0x50)
[  142.882611] [<8011dacc>] (warn_slowpath_fmt) from [<802bb818>] (__mark_inode_dirty+0x2f4/0x408)
[  142.882632] [<802bb818>] (__mark_inode_dirty) from [<80429628>] (f2fs_set_page_dirty_nobuffers+0x114/0x144)
[  142.882654] [<80429628>] (f2fs_set_page_dirty_nobuffers) from [<8042978c>] (f2fs_set_data_page_dirty+0x134/0x148)
[  142.882673] [<8042978c>] (f2fs_set_data_page_dirty) from [<8022c284>] (set_page_dirty+0x84/0xcc)
[  142.882692] [<8022c284>] (set_page_dirty) from [<804222e0>] (f2fs_write_end+0x11c/0x2a4)
[  142.882707] [<804222e0>] (f2fs_write_end) from [<8021e830>] (generic_perform_write+0x118/0x1b0)
[  142.882723] [<8021e830>] (generic_perform_write) from [<802210c8>] (__generic_file_write_iter+0x19c/0x1f8)
[  142.882740] [<802210c8>] (__generic_file_write_iter) from [<8040621c>] (f2fs_file_write_iter+0xe4/0x218)
[  142.882759] [<8040621c>] (f2fs_file_write_iter) from [<8028b05c>] (__vfs_write+0xe0/0x138)
[  142.882776] [<8028b05c>] (__vfs_write) from [<8028b27c>] (vfs_write+0xb4/0x1bc)
[  142.882791] [<8028b27c>] (vfs_write) from [<8028b4cc>] (SyS_write+0x54/0xb0)
[  142.882809] [<8028b4cc>] (SyS_write) from [<80108060>] (ret_fast_syscall+0x0/0x28)
[  142.882817] ---[ end trace 406cdc4a71053c23 ]---
[  142.903226]  sdb: sdb1
[  142.905375] sd 2:0:0:0: [sdb] Attached SCSI removable disk
[  145.658687] scsi 1:0:0:0: Direct-Access     Generic  HDD              0    PQ: 0 ANSI: 0
[  145.659579] sd 1:0:0:0: Attached scsi generic sg1 type 0
[  145.664857] sd 1:0:0:0: [sdc] Attached SCSI removable disk
[  149.206338] ------------[ cut here ]------------
[  149.206372] WARNING: CPU: 2 PID: 919 at fs/fs-writeback.c:2162 __mark_inode_dirty+0x2f4/0x408
[  149.206378] bdi-block not registered
[  149.206382] Modules linked in: aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm serdev bluetooth ecdh_generic sg cdc_acm brcmfmac brcmutil cfg80211 rfkill snd_bcm2835(C) snd_pcm snd_timer snd fixed uio_pdrv_genirq uio ip_tables x_tables ipv6
[  149.206513] CPU: 2 PID: 919 Comm: pihole-FTL Tainted: G        WC      4.14.62-v7+ #1134
[  149.206518] Hardware name: BCM2835
[  149.206545] [<8010ffd8>] (unwind_backtrace) from [<8010c240>] (show_stack+0x20/0x24)
[  149.206562] [<8010c240>] (show_stack) from [<80787284>] (dump_stack+0xd4/0x118)
[  149.206578] [<80787284>] (dump_stack) from [<8011da6c>] (__warn+0xf8/0x110)
[  149.206592] [<8011da6c>] (__warn) from [<8011dacc>] (warn_slowpath_fmt+0x48/0x50)
[  149.206607] [<8011dacc>] (warn_slowpath_fmt) from [<802bb818>] (__mark_inode_dirty+0x2f4/0x408)
[  149.206627] [<802bb818>] (__mark_inode_dirty) from [<80429628>] (f2fs_set_page_dirty_nobuffers+0x114/0x144)
[  149.206646] [<80429628>] (f2fs_set_page_dirty_nobuffers) from [<8042978c>] (f2fs_set_data_page_dirty+0x134/0x148)
[  149.206665] [<8042978c>] (f2fs_set_data_page_dirty) from [<8022c284>] (set_page_dirty+0x84/0xcc)
[  149.206683] [<8022c284>] (set_page_dirty) from [<804222e0>] (f2fs_write_end+0x11c/0x2a4)
[  149.206698] [<804222e0>] (f2fs_write_end) from [<8021e830>] (generic_perform_write+0x118/0x1b0)
[  149.206714] [<8021e830>] (generic_perform_write) from [<802210c8>] (__generic_file_write_iter+0x19c/0x1f8)
[  149.206730] [<802210c8>] (__generic_file_write_iter) from [<8040621c>] (f2fs_file_write_iter+0xe4/0x218)
[  149.206750] [<8040621c>] (f2fs_file_write_iter) from [<8028b05c>] (__vfs_write+0xe0/0x138)
[  149.206766] [<8028b05c>] (__vfs_write) from [<8028b27c>] (vfs_write+0xb4/0x1bc)
[  149.206782] [<8028b27c>] (vfs_write) from [<8028b4cc>] (SyS_write+0x54/0xb0)
[  149.206798] [<8028b4cc>] (SyS_write) from [<80108060>] (ret_fast_syscall+0x0/0x28)
[  149.206806] ---[ end trace 406cdc4a71053c24 ]---
[  183.088969] ------------[ cut here ]------------
[  183.088998] WARNING: CPU: 0 PID: 499 at fs/fs-writeback.c:2162 __mark_inode_dirty+0x2f4/0x408
[  183.089004] bdi-block not registered
[  183.089009] Modules linked in: aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm serdev bluetooth ecdh_generic sg cdc_acm brcmfmac brcmutil cfg80211 rfkill snd_bcm2835(C) snd_pcm snd_timer snd fixed uio_pdrv_genirq uio ip_tables x_tables ipv6
[  183.089140] CPU: 0 PID: 499 Comm: rs:main Q:Reg Tainted: G        WC      4.14.62-v7+ #1134
[  183.089145] Hardware name: BCM2835
[  183.089175] [<8010ffd8>] (unwind_backtrace) from [<8010c240>] (show_stack+0x20/0x24)
[  183.089191] [<8010c240>] (show_stack) from [<80787284>] (dump_stack+0xd4/0x118)
[  183.089208] [<80787284>] (dump_stack) from [<8011da6c>] (__warn+0xf8/0x110)
[  183.089221] [<8011da6c>] (__warn) from [<8011dacc>] (warn_slowpath_fmt+0x48/0x50)
[  183.089236] [<8011dacc>] (warn_slowpath_fmt) from [<802bb818>] (__mark_inode_dirty+0x2f4/0x408)
[  183.089256] [<802bb818>] (__mark_inode_dirty) from [<80429628>] (f2fs_set_page_dirty_nobuffers+0x114/0x144)
[  183.089275] [<80429628>] (f2fs_set_page_dirty_nobuffers) from [<8042978c>] (f2fs_set_data_page_dirty+0x134/0x148)
[  183.089294] [<8042978c>] (f2fs_set_data_page_dirty) from [<8022c284>] (set_page_dirty+0x84/0xcc)
[  183.089312] [<8022c284>] (set_page_dirty) from [<804222e0>] (f2fs_write_end+0x11c/0x2a4)
[  183.089328] [<804222e0>] (f2fs_write_end) from [<8021e830>] (generic_perform_write+0x118/0x1b0)
[  183.089343] [<8021e830>] (generic_perform_write) from [<802210c8>] (__generic_file_write_iter+0x19c/0x1f8)
[  183.089361] [<802210c8>] (__generic_file_write_iter) from [<8040621c>] (f2fs_file_write_iter+0xe4/0x218)
[  183.089380] [<8040621c>] (f2fs_file_write_iter) from [<8028b05c>] (__vfs_write+0xe0/0x138)
[  183.089396] [<8028b05c>] (__vfs_write) from [<8028b27c>] (vfs_write+0xb4/0x1bc)
[  183.089412] [<8028b27c>] (vfs_write) from [<8028b4cc>] (SyS_write+0x54/0xb0)
[  183.089429] [<8028b4cc>] (SyS_write) from [<80108060>] (ret_fast_syscall+0x0/0x28)
[  183.089437] ---[ end trace 406cdc4a71053c25 ]---

@oskar-skog
Copy link

oskar-skog commented Sep 23, 2018

Could it be the USB-SATA adapter that's buggy? I've had severe issues with a Revoltec enclosure, several dead sectors when using it. Can't read the bloody chip, but I think it's a Revoltec RS076 enclosure.

@risa2000
Copy link

risa2000 commented Sep 24, 2018

Could it be the USB-SATA adapter that's buggy?

It could, but when I tried it in normal PC (Windows 7), there was no problem (but I probably did not have other devices on the same USB hub either).
The fact that it completely resets the USB interface points to the hardware bug, rather than software, but whether it is the bridge chip, or the USB hub in RPi, I do not know, nor if it is really HW bug, or some linux kernel mechanism.

@adde88
Copy link

adde88 commented Dec 13, 2018

I've done ALOT of debugging on my OpenWRT device. (Pineapple NANO)
I managed to cross-compile the latest kernel (4.14.81) in the hope that this would squash the bug.
But the same error keeps dropping. Though i'm noticing a pattern.

In ALL of the error messages it failed while using the SCSI OPCODE: 0x28 (READ)
So, i'm currently trying to locate exactly which driver is failing, as the kernel have loaded both OHCI and EHCI.
I also tried to uninstall the "scsci-generic" module.
It's not using any MMC driver to manage the SD-card.

Here's some info about the device from lsusb:

root@Pineapple:~# lsusb
Bus 001 Device 008: ID 05e3:0745 Genesys Logic, Inc. Logilink CR0012
Bus 001 Device 003: ID 0cf3:9271 Qualcomm Atheros Communications AR9271 802.11n
Bus 001 Device 002: ID 058f:6254 Alcor Micro Corp. USB Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

root@Pineapple:~# lsusb -v -d 05e3:0745

Bus 001 Device 008: ID 05e3:0745 Genesys Logic, Inc. Logilink CR0012
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.01
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  idVendor           0x05e3 Genesys Logic, Inc.
  idProduct          0x0745 Logilink CR0012
  bcdDevice            9.33
  iManufacturer           0
  iProduct                1 USB Storage
  iSerial                 2 000000000933
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength           32
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0
    bmAttributes         0xa0
      (Bus Powered)
      Remote Wakeup
    MaxPower              500mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     80 Bulk-Only
      iInterface              0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
Binary Object Store Descriptor:
  bLength                 5
  bDescriptorType        15
  wTotalLength           12
  bNumDeviceCaps          1
  USB 2.0 Extension Device Capability:
    bLength                 7
    bDescriptorType        16
    bDevCapabilityType      2
    bmAttributes   0x00000002
      Link Power Management (LPM) Supported
Device Status:     0x0000
  (Bus Powered)

I'll provide more feedback if i find anything of interest.

@awwit
Copy link

awwit commented Dec 19, 2021

This error may be related to this problem (I don't know how to solve it yet): https://en.opensuse.org/SDB:USB_3.0_Hard_Drive_troubleshooting

@RENANZG
Copy link

RENANZG commented Aug 18, 2023

qbitorrent would get cascading I/O errors (Input/Output Error), almost always with 50+ GB downloads. In addition, qbittorrent kept eating all my ram. Changing "File Pool Size" in the advanced options to something like 500 (instead of 5000), might be worth a try (or lower) if you're still having issues.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Close within 30 days Issue will be closed within 30 days unless requested to stay open Closing due to inaction Issue likely to be closed due to lack of recent comments Waiting for external input Waiting for a comment from the originator of the issue, or a collaborator.
Projects
None yet
Development

No branches or pull requests