Opened 8 years ago
Last modified 6 years ago
#976 investigate bug
USB Disk mounting is unstable
Reported by: | rughis | Owned by: | |
---|---|---|---|
Priority: | normal | Milestone: | |
Component: | fon-base-firmware | Version: | 2.3.6.1 (Gari jr.) |
Severity: | unknown | ||
Cc: | Hardware: | 2.0n (FON2300) |
Description
I need often to reboot my Fonera 2.0n (Gari jr. installed) because the USB disk is often not visible through FTP, Samba and Fonera's web GUI.
After I reboot the Fonera the disk is again visible and all works fine.
PS. I normally access the Fonera through WAN port.
Attachments (3)
Change History (39)
comment:1 Changed 8 years ago by ddomee@…
comment:2 Changed 8 years ago by mihaly.reg@…
Same problem here ! Fonera 2.0N 2.3.6.1, using also Transmission 2.11. Sometime accessing by ftp the sda1 it shows empty disk, also ssh "ls" command shows empty list. My disk is a 1.5TB Samsung Story, with 3 partitions, 2 partitions EXT2 and the last one FAT.
comment:3 Changed 8 years ago by calvinturbo@…
It seems that it has something to do with disk that are larger than 1 terabyte. I have this issue as well with a 1,5 TeraByte? disk. I have this issue with Tranmission 2.11, but with older versions too. Even without using those disk, they disappear
comment:4 Changed 8 years ago by ddomee@…
I haven't a disk larger then 1 Tb. My disk is only 80 Gb...
comment:5 Changed 8 years ago by calvinturbo@…
Oh, that is strange. Please fix this Matthijs!
comment:6 Changed 8 years ago by anonymous
same problem here.
comment:7 Changed 8 years ago by ate@…
same problem here with fonera 2.0n on firmware 2.3.6.1 Using wd 1 Tb harddisk and after some time the usb-disk is lost by fonera. Just unplug and plug the USB-disk isn't good enough, need to reboot fonera 2.0n.
comment:8 Changed 8 years ago by Jeroensky
I also have this problem.
But when i reboot, the Fonera2.1 2.3.6.1 gets in sort of reboot loop. It reboots, try to get isp connection, but hartbeat led keeps flashing, sometimes usb webcam not recognised, and after some minutes it reboots again.
Main power interrupt is then (sometimes) solution to give it a reboot with detected usb devices and wan internet stable. What also works is, disconnect usb(hub) from usb port, and then reboot, waittill 2.3.6.1 2.0n is stable booted with non flashing heartbeat ledwan), and then connct usb devices again(hdd and webcam here)
Hdd is a Samsung greenline 1.5TB usb2.0 with ext3 filesystem(one giant partition).
comment:9 Changed 7 years ago by andrepinto@…
This instability also happens with my 1tb hd from iomega. Firmware 2.3.7.0 Beta 2
comment:10 Changed 7 years ago by anonymous
500GB WD usb hdd, Firmware 2.3.7.0 Beta 2... same problem... temp solution: http://forum.fon.com/forum/viewtopic.php?t=136
comment:11 Changed 6 years ago by matthijs
- Status changed from new to investigate
There have been some stability improvements related to mountd, the deamon responsible for mounting the USB disks in recent releases. Does this problem still occur for people with the 2.3.7.0 rc2 release?
comment:12 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
This does still occur on v2.3.7.0 rc 1
Personally i think it that it looks like waking up the HDD takes too long.
But this shouldn't make the filesystem show an empty disk, would it?
comment:13 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
this happens nearly every day:
root@Fonera:~# dmesg Linux version 2.6.21.7 (buildbot@veriton) (gcc version 4.1.2) #1 Fri Oct 5 06:02:52 CEST 2012 The CPU feqenuce set to 384 MHz CPU revision is: 0001964c Determined physical RAM map: memory: 04000000 @ 00000000 (usable) On node 0 totalpages: 16384 DMA zone: 128 pages used for memmap DMA zone: 0 pages reserved DMA zone: 16256 pages, LIFO batch:3 Normal zone: 0 pages used for memmap Built 1 zonelists. Total pages: 16256 Kernel command line: console=ttyS1,57600n8 root=/dev/mtdblock5 init=/etc/preinit Primary instruction cache 32kB, physically tagged, 4-way, linesize 32 bytes. Primary data cache 16kB, 4-way, linesize 32 bytes. Synthesized TLB refill handler (20 instructions). Synthesized TLB load handler fastpath (32 instructions). Synthesized TLB store handler fastpath (32 instructions). Synthesized TLB modify handler fastpath (31 instructions). Cache parity protection disabled cause = 10800000, status = 1100ff00 PID hash table entries: 256 (order: 8, 1024 bytes) calculating r4koff... 003a9800(3840000) CPU frequency 384.00 MHz Using 192.000 MHz high precision timer. Dentry cache hash table entries: 8192 (order: 3, 32768 bytes) Inode-cache hash table entries: 4096 (order: 2, 16384 bytes) Memory: 61988k/65536k available (2153k kernel code, 3484k reserved, 562k data, 104k init, 0k highmem) Calibrating delay loop... 255.59 BogoMIPS (lpj=1277952) Mount-cache hash table entries: 512 NET: Registered protocol family 16 SCSI subsystem initialized Generic PHY: Registered new driver usbcore: registered new interface driver usbfs usbcore: registered new interface driver hub usbcore: registered new device driver usb Time: MIPS clocksource has been installed. NET: Registered protocol family 2 IP route cache hash table entries: 1024 (order: 0, 4096 bytes) TCP established hash table entries: 2048 (order: 2, 16384 bytes) TCP bind hash table entries: 2048 (order: 1, 8192 bytes) TCP: Hash tables configured (established 2048 bind 2048) TCP reno registered ramips_gpio: done squashfs: version 3.2-r2 (2007/01/15) Phillip Lougher squashfs: LZMA suppport for slax.org by jro Registering mini_fo version $Id$ JFFS2 version 2.2. (NAND) (SUMMARY) (C) 2001-2006 Red Hat, Inc. io scheduler noop registered io scheduler deadline registered (default) ramips_wdt: loaded Serial: 8250/16550 driver $Revision: 1.3 $ 2 ports, IRQ sharing disabled serial8250: ttyS0 at I/O 0xb0000500 (irq = 37) is a 16550A serial8250: ttyS1 at I/O 0xb0000c00 (irq = 12) is a 16550A Ralink SoC physically mapped flash: Found 1 x16 devices at 0x0 in 16-bit bank Ralink SoC physically mapped flash: Found an alias at 0x800000 for the chip at 0x0 Amd/Fujitsu Extended Query Table at 0x0040 number of CFI chips: 1 cfi_cmdset_0002: Disabling erase-suspend-program due to code brokenness. ramips_mtd: kernel size is 885345 Creating 6 MTD partitions on "Ralink SoC physically mapped flash": 0x00000000-0x00030000 : "uboot" 0x00030000-0x00040000 : "uboot-config" 0x00040000-0x00050000 : "boardconfig" 0x00050000-0x00800000 : "image" 0x00050000-0x00150000 : "linux" 0x00150000-0x00800000 : "rootfs" mtd: partition "rootfs" set to be root filesystem mtd: partition "rootfs_data" created automatically, ofs=5B0000, len=250000 0x005b0000-0x00800000 : "rootfs_data" ramips_mtd: 0x1000000 at 0xbf000000 MAC_ADRH -- : 0x00000000 MAC_ADRL -- : 0x00000000 Ralink APSoC Ethernet Driver Initilization. v2.0 64 rx/tx descriptors allocated, mtu = 1500! NAPI enable, weight = 0, Tx Ring = 64, Rx Ring = 64 MAC_ADRH -- : 0x00000018 MAC_ADRL -- : 0x84889267 PROC INIT OK! setting fonera20n ethernet Initializing USB Mass Storage driver... usbcore: registered new interface driver usb-storage USB Mass Storage support registered. usbcore: registered new interface driver libusual dwc_otg: version 2.72a 24-JUN-2008 DWC_otg: Core Release: 2.66a DWC_otg: Periodic Transfer Interrupt Enhancement - disabled DWC_otg: Multiprocessor Interrupt Enhancement - disabled DWC_otg: Using DMA mode DWC_otg: Device using Buffer DMA mode dwc_otg lm0: DWC OTG Controller drivers/usb/core/inode.c: creating file 'devices' drivers/usb/core/inode.c: creating file '001' dwc_otg lm0: new USB bus registered, assigned bus number 1 dwc_otg lm0: irq 18, io mem 0x00000000 DWC_otg: Init: Port Power? op_state=1 DWC_otg: Init: Power Port (0) usb usb1: default language 0x0409 usb usb1: new device strings: Mfr=3, Product=2, SerialNumber=1 usb usb1: Product: DWC OTG Controller usb usb1: Manufacturer: Linux 2.6.21.7 dwc_otg_hcd usb usb1: SerialNumber: lm0 usb usb1: uevent usb usb1: usb_probe_device usb usb1: configuration #1 chosen from 1 choice usb usb1: adding 1-0:1.0 (config #1, interface 0) usb 1-0:1.0: uevent hub 1-0:1.0: usb_probe_interface hub 1-0:1.0: usb_probe_interface - got id hub 1-0:1.0: USB hub found hub 1-0:1.0: 1 port detected hub 1-0:1.0: standalone hub hub 1-0:1.0: ganged power switching hub 1-0:1.0: individual port over-current protection hub 1-0:1.0: Single TT hub 1-0:1.0: TT requires at most 8 FS bit times (666 ns) hub 1-0:1.0: power on to power good time: 2ms hub 1-0:1.0: local power source is good hub 1-0:1.0: enabling power on all ports hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0000 drivers/usb/core/inode.c: creating file '001' hub 1-0:1.0: port 1, status 0101, change 0001, 12 Mb/s Registered led device: gpio7 Registered led device: gpio9 Registered led device: gpio11 Registered led device: gpio14 nf_conntrack version 0.5.0 (512 buckets, 4096 max) ip_tables: (C) 2000-2006 Netfilter Core Team, Type=Linux TCP cubic registered NET: Registered protocol family 1 NET: Registered protocol family 17 802.1Q VLAN Support v1.8 Ben Greear <greearb@candelatech.com> All bugs added by David S. Miller <davem@redhat.com> VFS: Mounted root (squashfs filesystem) readonly. Freeing unused kernel memory: 104k freed Warning: unable to open an initial console. hub 1-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x101 usb 1-1: new high speed USB device using dwc_otg and address 2 Algorithmics/MIPS FPU Emulator v1.5 usb 1-1: default language 0x0409 usb 1-1: new device strings: Mfr=1, Product=2, SerialNumber=3 usb 1-1: Product: FreeAgentDesktop usb 1-1: Manufacturer: Seagate usb 1-1: SerialNumber: 9QG2DCVZ usb 1-1: uevent usb 1-1: usb_probe_device usb 1-1: configuration #1 chosen from 1 choice usb 1-1: adding 1-1:1.0 (config #1, interface 0) usb 1-1:1.0: uevent usb-storage 1-1:1.0: usb_probe_interface usb-storage 1-1:1.0: usb_probe_interface - got id scsi0 : SCSI emulation for USB Mass Storage devices usb-storage: device found at 2 usb-storage: waiting for device to settle before scanning drivers/usb/core/inode.c: creating file '002' hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0002 hub 1-0:1.0: port 1 enable change, status 00000503 usb usb1: uevent usb 1-0:1.0: uevent usb 1-1: uevent usb 1-1:1.0: uevent mini_fo: using base directory: / mini_fo: using storage directory: /jffs RT305x_ESW: Link Status Changed eth0.1: add 01:00:5e:00:00:01 mcast address to master interface eth0.1: dev_set_promiscuity(master, 1) device eth0 entered promiscuous mode device eth0.1 entered promiscuous mode br-lan: port 1(eth0.1) entering learning state br-lan: topology change detected, propagating br-lan: port 1(eth0.1) entering forwarding state scsi 0:0:0:0: Direct-Access Seagate FreeAgentDesktop 100D PQ: 0 ANSI: 4 SCSI device sda: 976773168 512-byte hdwr sectors (500108 MB) sda: Write Protect is off sda: Mode Sense: 1c 00 00 00 sda: assuming drive cache: write through SCSI device sda: 976773168 512-byte hdwr sectors (500108 MB) sda: Write Protect is off sda: Mode Sense: 1c 00 00 00 sda: assuming drive cache: write through sda: sda1 sd 0:0:0:0: Attached scsi disk sda usb-storage: device scan complete loop: loaded (max 8 devices) PPP generic driver version 2.4.2 tun: Universal TUN/TAP device driver, 1.6 tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com> br-lan: port 1(eth0.1) entering disabled state br-lan: port 1(eth0.1) entering learning state br-lan: topology change detected, propagating br-lan: port 1(eth0.1) entering forwarding state IMQ starting with 2 devices... IMQ driver loaded successfully. Hooking IMQ before NAT on PREROUTING. Hooking IMQ after NAT on POSTROUTING. ipt_time loading nf_conntrack_h323: Unknown symbol ip6_route_output nf_nat_h323: Unknown symbol nat_callforwarding_hook nf_nat_h323: Unknown symbol nat_t120_hook nf_nat_h323: Unknown symbol set_h225_addr_hook nf_nat_h323: Unknown symbol set_ras_addr_hook nf_nat_h323: Unknown symbol nat_q931_hook nf_nat_h323: Unknown symbol nat_rtp_rtcp_hook nf_nat_h323: Unknown symbol set_sig_addr_hook nf_nat_h323: Unknown symbol get_h225_addr nf_nat_h323: Unknown symbol nat_h245_hook nf_nat_h323: Unknown symbol set_h245_addr_hook rt2860v2_ap: module license 'unspecified' taints kernel. usbcore: registered new interface driver usblp drivers/usb/class/usblp.c: v0.13: USB Printer Device Class driver usbcore: registered new interface driver usbserial drivers/usb/serial/usb-serial.c: USB Serial Driver core Linux video capture interface: v2.00 hso: drivers/usb/serial/hso.c: 1.6-Option Option Wireless usbcore: registered new interface driver hso drivers/usb/serial/usb-serial.c: USB Serial support registered for GSM modem (1-port) usbcore: registered new interface driver option drivers/usb/serial/option.c: USB Driver for GSM modems: v0.7.2 drivers/usb/serial/usb-serial.c: USB Serial support registered for Sierra USB modem (1 port) drivers/usb/serial/usb-serial.c: USB Serial support registered for Sierra USB modem (3 port) usbcore: registered new interface driver sierra drivers/usb/serial/sierra.c: USB Driver for Sierra Wireless USB modems: v.1.0.6 fuse init (API version 7.8) usbcore: registered new interface driver uvcvideo USB Video Class driver (SVN r215) setting region code 1 setting region code 7 RA_WIFI using 2 SSIDs geo beacon private:0 public:0 MAC: 00:18:84:88:92:64 0x1300 = 00064320 device ra0 entered promiscuous mode br-lan: port 2(ra0) entering learning state br-lan: topology change detected, propagating br-lan: port 2(ra0) entering forwarding state eth0.2: add 01:00:5e:00:00:01 mcast address to master interface eth0.2: del 01:00:5e:00:00:01 mcast address from vlan interface eth0.2: del 01:00:5e:00:00:01 mcast address from master interface eth0.2: add 01:00:5e:00:00:01 mcast address to master interface eth0.2: del 01:00:5e:00:00:01 mcast address from vlan interface eth0.2: del 01:00:5e:00:00:01 mcast address from master interface eth0.2: add 01:00:5e:00:00:01 mcast address to master interface eth0.2: del 01:00:5e:00:00:01 mcast address from vlan interface eth0.2: del 01:00:5e:00:00:01 mcast address from master interface eth0.2: add 01:00:5e:00:00:01 mcast address to master interface MASQUERADE: br-lan ate my IP address MASQUERADE: br-lan ate my IP address br-lan: port 2(ra0) entering disabled state br-lan: port 1(eth0.1) entering disabled state eth0.1: del 01:00:5e:00:00:01 mcast address from vlan interface eth0.1: del 01:00:5e:00:00:01 mcast address from master interface device ra0 left promiscuous mode br-lan: port 2(ra0) entering disabled state device eth0.1 left promiscuous mode br-lan: port 1(eth0.1) entering disabled state eth0.1: dev_set_promiscuity(master, -1) device eth0 left promiscuous mode eth0.1: add 01:00:5e:00:00:01 mcast address to master interface eth0.1: del 01:00:5e:00:00:01 mcast address from vlan interface eth0.1: del 01:00:5e:00:00:01 mcast address from master interface eth0.1: add 01:00:5e:00:00:01 mcast address to master interface eth0.1: dev_set_promiscuity(master, 1) device eth0 entered promiscuous mode device eth0.1 entered promiscuous mode br-lan: port 1(eth0.1) entering learning state br-lan: topology change detected, propagating br-lan: port 1(eth0.1) entering forwarding state setting region code 1 setting region code 7 RA_WIFI using 2 SSIDs geo beacon private:0 public:0 MAC: 00:18:84:88:92:64 0x1300 = 00064320 br-lan: port 1(eth0.1) entering disabled state br-lan: port 1(eth0.1) entering learning state br-lan: topology change detected, propagating br-lan: port 1(eth0.1) entering forwarding state device ra0 entered promiscuous mode br-lan: port 2(ra0) entering learning state br-lan: topology change detected, propagating br-lan: port 2(ra0) entering forwarding state kjournald starting. Commit interval 5 seconds EXT3 FS on sda1, internal journal EXT3-fs: recovery complete. EXT3-fs: mounted filesystem with ordered data mode. Adding 129528k swap on /tmp/mounts/FreeAgent//FoneraApps/torrent.2.3.7.0.swp. Priority:-1 extents:34 across:130716k sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 434372687 EXT3-fs error (device sda1): ext3_get_inode_loc: unable to read inode block - inode=13574164, block=54296578 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 63 Buffer I/O error on device sda1, logical block 0 lost page write due to I/O error on sda1 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 331874543 EXT3-fs error (device sda1): ext3_get_inode_loc: unable to read inode block - inode=10371741, block=41484310 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 827403623 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 827403623 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 827403623 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 331746687 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 10327 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 10327 EXT3-fs error (device sda1): ext3_find_entry: reading directory #2 offset 0 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 63 Buffer I/O error on device sda1, logical block 0 lost page write due to I/O error on sda1 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 85319871 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 85319871 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 85319871 EXT2-fs error (device loop1): ext2_get_inode: unable to read inode block - inode=4049, block=16387 root@Fonera:~#
everything is normal at first, including:
Adding 129528k swap on /tmp/mounts/FreeAgent//FoneraApps/torrent.2.3.7.0.swp. Priority:-1 extents:34 across:130716k
but after a while access is requested and the device is not ready:
sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 434372687
this makes the ext3 filesystem go mad:
EXT3-fs error (device sda1): ext3_get_inode_loc: unable to read inode block - inode=13574164, block=54296578
and again:
sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 63
which makes the buffer i/o notice that there's an error on the sda1 device (but it was just not ready, there is no real error on the device!):
Buffer I/O error on device sda1, logical block 0 lost page write due to I/O error on sda1
comment:14 Changed 6 years ago by matthijs
- Status changed from investigate to infoneeded
Thanks for your logs and analysis, it seems weird that stuff starts failing even when the device is just not read yet.
However, looking more closely at the code it seems that the device is not going to become ready on its own. When I look up ASC=0x4 ASCQ=0x2 in the SPC-3 specification (section 4.5, table 28, page 49), the actual sense code means: "LOGICAL UNIT NOT READY, INITIALIZING COMMAND REQUIRED". A few similar sense codes are handled by simply waiting for a bit, but the code in drivers/scsi/scsi_lib.c doesn't have this particular code listed, so it falls back to failure (which is probably correct, since it would probably retry indefinately otherwise).
At first glance I don't see any scsi code to handle this particular case (I do see something to handle 0x4/0x3 "LOGICAL UNIT NOT READY, MANUAL INTERVENTION REQUIRED" by triggering a spinup and something to handle 0x4/0x2 for CD drives by opening up the CD tray which apparently initializes the CD drive). Assuming that this disk will work properly on newer kernels and/or regular PC hardware, one can wonder where the difference is.
I'm also wondering where this particular error code is generated. Is this from the disk, the USB->SATA converter, the USB (mass-storage) driver or the scsi drivers? For this it would help to get:
- The make and model of your external USB disk
- The contents of the /proc/bus/usb/devices file
Could you paste those in a comment here?
comment:15 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
i guess the contents of /proc/bus/usb/devices also answer the first question :)
root@Fonera:~# cat /proc/bus/usb/devices T: Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=480 MxCh= 1 B: Alloc= 0/800 us ( 0%), #Int= 0, #Iso= 0 D: Ver= 2.00 Cls=09(hub ) Sub=00 Prot=01 MxPS=64 #Cfgs= 1 P: Vendor=0000 ProdID=0000 Rev= 2.06 S: Manufacturer=Linux 2.6.21.7 dwc_otg_hcd S: Product=DWC OTG Controller S: SerialNumber=lm0 C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub E: Ad=81(I) Atr=03(Int.) MxPS= 4 Ivl=256ms T: Bus=01 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#= 2 Spd=480 MxCh= 0 D: Ver= 2.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1 P: Vendor=0bc2 ProdID=3000 Rev= 0.00 S: Manufacturer=Seagate S: Product=FreeAgentDesktop S: SerialNumber= 9QG2DCVZ C:* #Ifs= 1 Cfg#= 1 Atr=c0 MxPwr= 0mA I:* If#= 0 Alt= 0 #EPs= 2 Cls=08(stor.) Sub=06 Prot=50 Driver=usb-storage E: Ad=01(O) Atr=02(Bulk) MxPS= 512 Ivl=0ms E: Ad=81(I) Atr=02(Bulk) MxPS= 512 Ivl=0ms root@Fonera:~#
comment:16 Changed 6 years ago by matthijs
Indeed, thanks!
comment:17 Changed 6 years ago by matthijs
Ok, from that I learned that your USB -> sata converter (and it seems all of them do) takes raw SCSI commands (Prot=50 means USB storage passes transparent SCSI commands). This suggests that your disk is actually returning this "initializing command required" status. The SPC-3 spec isn't very clear on what it actually means, the T10/08-038r3 document tries to clarify this status, but suggests that it is only relevant for media changer hardware. Various other forum postings suggest that this error is more commonly caused by disks going into standby (I've seen references about both Maxtor and Seagate disks) and suggest raising the standby time or disabling it alltogether, but that's not really an option.
This page suggests that this status should be resolved by issueing a start/stop command, which is exactly what the sd (SCSI disk) driver is doing for some different status codes, but that only seems to happen on power on and/or when reconnecting the drive etc.
I have a few ideas for patches that could perhaps fix this, but I'm not very confident yet. First, two more questions:
- Have you compiled a custom firmware before and could you try a few patches for me, or would you rather have me compile some firmware images with the different patches for you?
- If this happens again, could you get the output of the "logread" command instead of "dmesg", since that one contains timestamps and potentially other useful information (might be needed to let "logread -f" run in an SSH terminal, to prevent the useful info from scrolling out of the logread buffer).
comment:18 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
1) i have some experience in this but not for the fonera
2) i'll not be online until 25th so i'll try to give as much info today.
i just found this in the log:
root@Fonera:~# logread |grep -v transmission Mar 13 11:08:43 Fonera authpriv.info dropbear[6726]: exit after auth (root): Disconnect received Mar 13 11:34:41 Fonera user.info kernel: sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 Mar 13 11:34:41 Fonera user.info kernel: ASC=0x4 ASCQ=0x2 Mar 13 11:34:41 Fonera user.warn kernel: end_request: I/O error, dev sda, sector 67371087 Mar 13 11:34:41 Fonera user.crit kernel: EXT3-fs error (device sda1): ext3_get_inode_loc: unable to read inode block - inode=2105345, block=8421378 Mar 13 11:34:41 Fonera user.info kernel: sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 Mar 13 11:34:41 Fonera user.info kernel: ASC=0x4 ASCQ=0x2 Mar 13 11:34:41 Fonera user.warn kernel: end_request: I/O error, dev sda, sector 63 Mar 13 11:34:41 Fonera user.err kernel: Buffer I/O error on device sda1, logical block 0 Mar 13 11:34:41 Fonera user.warn kernel: lost page write due to I/O error on sda1 Mar 13 11:52:28 Fonera local6.info chillispot[5238]: options.c: 782: Rereading configuration file and doing DNS lookup Mar 13 12:52:28 Fonera local6.info chillispot[5238]: options.c: 782: Rereading configuration file and doing DNS lookup Mar 13 12:56:29 Fonera authpriv.info dropbear[7716]: Child connection from <removed>:45678 Mar 13 12:56:30 Fonera authpriv.notice dropbear[7716]: pubkey auth succeeded for 'root' with key md5 <removed> from <removed>:45678 root@Fonera:~#
comment:19 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
BusyBox v1.11.1 (2012-10-05 05:27:25 CEST) built-in shell (ash) Enter 'help' for a list of built-in commands. /|/| / / / _/ |_|_ .' `. | @ \__ | `\ | ___) | ,___/ | / | | | | / | _____________________.' ; .' / / / / | | / / | | | | \__\ ; \ / \ ________ / | | | `--.__ ,-` | | | \ /| | | | | | | \ | | | | | | | | | | | \ |\__\ | |_\ \__\ \__\ Paco the alpaca ------ Fonera 2.0n Firmware (v2.3.7.0 rc 1) ------- * Based on OpenWrt - http://openwrt.org * Powered by FON - http://www.fon.com ---------------------------------------------------- root@Fonera:~# logread |grep -v transmission && logread -f |grep -v transmission Mar 13 13:07:09 Fonera user.crit mountd[2442]: mounting /tmp/run/mountd/sda1 Mar 13 13:07:09 Fonera user.crit mountd[2547]: mount -t ext3 -o rw,noatime,defaults /dev/sda1 /tmp/run/mountd/sda1 Mar 13 13:07:09 Fonera user.crit fonstated: finished running /etc/fonstated/FWallDaemon Mar 13 13:07:09 Fonera user.crit fonstated: running event /etc/fonstated/StartTorrent Mar 13 13:07:10 Fonera user.crit fonstated: finished running /etc/fonstated/StartTorrent Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: OpenVPN 2.2.2 mipsel-linux [SSL] [LZO2] built on Oct 5 2012 Mar 13 13:07:10 Fonera daemon.warn openvpn(openvpn)[2566]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts Mar 13 13:07:10 Fonera user.crit fonstated: enqueue --> StartFonsmcd Mar 13 13:07:10 Fonera user.crit fonstated: enqueue --> Online Mar 13 13:07:10 Fonera user.crit fonstated: running event /etc/fonstated/StartFonsmcd Mar 13 13:07:10 Fonera user.crit fonstated: finished running /etc/fonstated/StartFonsmcd Mar 13 13:07:10 Fonera user.crit fonstated: running event /etc/fonstated/Online Mar 13 13:07:10 Fonera user.info kernel: kjournald starting. Commit interval 5 seconds Mar 13 13:07:10 Fonera user.warn kernel: EXT3-fs warning: mounting fs with errors, running e2fsck is recommended Mar 13 13:07:10 Fonera user.info kernel: EXT3 FS on sda1, internal journal Mar 13 13:07:10 Fonera user.info kernel: EXT3-fs: recovery complete. Mar 13 13:07:10 Fonera user.info kernel: EXT3-fs: mounted filesystem with ordered data mode. Mar 13 13:07:10 Fonera user.crit mountd[2442]: ----------> mount ret = 0 Mar 13 13:07:10 Fonera user.notice root: runnow --> /etc/fonstated/HotspotStart Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: Diffie-Hellman initialized with 1024 bit key Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: TLS-Auth MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ] Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: Socket Buffers: R=[109568->131072] S=[109568->131072] Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: TUN/TAP device tun-ovpn opened Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: TUN/TAP TX queue length set to 100 Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: /sbin/ifconfig tun-ovpn 10.8.0.1 netmask 255.255.255.0 mtu 1500 broadcast 10.8.0.255 Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ] Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: UDPv4 link local (bound): [undef]:1194 Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: UDPv4 link remote: [undef] Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: MULTI: multi_init called, r=256 v=256 Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: IFCONFIG POOL: base=10.8.0.2 size=126 Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: IFCONFIG POOL LIST Mar 13 13:07:10 Fonera daemon.notice openvpn(openvpn)[2566]: Initialization Sequence Completed Mar 13 13:07:13 Fonera local6.info chillispot[2811]: tun.c: 664: 2 (No such file or directory) TX queue length set to 100 Mar 13 13:07:13 Fonera local6.info chillispot[2811]: ChilliSpot 1.0-coova.4. Copyright 2002-2005 Mondru AB. Licensed under GPL. Copyright 2006 Coova Technologies Ltd. Licensed under GPL. See http://www.chillispot.org for credits. Mar 13 13:07:13 Fonera user.notice root: runnow --> /etc/fonstated/RestartNtpclient Mar 13 13:07:14 Fonera user.crit fonstated: finished running /etc/fonstated/Online Mar 13 13:07:14 Fonera user.crit fonstated: enqueue --> hotspot_wdt_start Mar 13 13:07:14 Fonera user.crit fonstated: running fast event hotspot_wdt_start Mar 13 13:07:14 Fonera user.crit fonstated: starting chilli wdt Mar 13 13:07:15 Fonera user.crit fonstated: enqueue --> SetupDlmd Mar 13 13:07:15 Fonera user.crit fonstated: running event /etc/fonstated/SetupDlmd Mar 13 13:07:15 Fonera user.crit fonstated: finished running /etc/fonstated/SetupDlmd Mar 13 13:07:16 Fonera user.crit mountd[2581]: starting torrent sda1 Mar 13 13:07:16 Fonera user.notice root: adding tun-ovpn to firewall zone vpn Mar 13 13:07:17 Fonera user.notice root: adding br-lan to firewall zone lan Mar 13 13:07:17 Fonera user.info kernel: Adding 129528k swap on /tmp/mounts/FreeAgent//FoneraApps/torrent.2.3.7.0.swp. Priority:-1 extents:34 across:130716k Mar 13 13:07:18 Fonera user.notice root: adding eth0.2 to firewall zone wan Mar 13 13:07:19 Fonera user.notice root: adding tun0 to firewall zone hotspot Mar 13 13:08:05 Fonera user.alert fonstated: redirector failed Mar 13 13:08:05 Fonera user.crit fonstated: enqueue --> RestartChilli Mar 13 13:08:05 Fonera user.crit fonstated: running event /etc/fonstated/RestartChilli Mar 13 13:08:06 Fonera local6.info chillispot[3380]: tun.c: 664: 2 (No such file or directory) TX queue length set to 100 Mar 13 13:08:06 Fonera local6.info chillispot[3380]: ChilliSpot 1.0-coova.4. Copyright 2002-2005 Mondru AB. Licensed under GPL. Copyright 2006 Coova Technologies Ltd. Licensed under GPL. See http://www.chillispot.org for credits. Mar 13 13:08:06 Fonera user.crit fonstated: finished running /etc/fonstated/RestartChilli Mar 13 13:08:06 Fonera user.crit fonstated: enqueue --> hotspot_wdt_stop Mar 13 13:08:06 Fonera user.crit fonstated: running fast event hotspot_wdt_stop Mar 13 13:08:06 Fonera user.crit fonstated: stopping chilli wdt Mar 13 13:08:06 Fonera user.crit fonstated: enqueue --> hotspot_wdt_start Mar 13 13:08:06 Fonera user.crit fonstated: running fast event hotspot_wdt_start Mar 13 13:08:06 Fonera user.crit fonstated: starting chilli wdt Mar 13 13:08:43 Fonera authpriv.info dropbear[4113]: Child connection from <removed>:45832 Mar 13 13:08:44 Fonera authpriv.notice dropbear[4113]: pubkey auth succeeded for 'root' with key md5 <removed> from <removed>:45832 Mar 13 13:52:07 Fonera user.info kernel: sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 Mar 13 13:52:07 Fonera user.info kernel: ASC=0x4 ASCQ=0x2 Mar 13 13:52:07 Fonera user.warn kernel: end_request: I/O error, dev sda, sector 442065279 Mar 13 13:52:07 Fonera user.info kernel: sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 Mar 13 13:52:07 Fonera user.info kernel: ASC=0x4 ASCQ=0x2 Mar 13 13:52:07 Fonera user.warn kernel: end_request: I/O error, dev sda, sector 442065279 Mar 13 13:52:07 Fonera user.info kernel: sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 Mar 13 13:52:07 Fonera user.info kernel: ASC=0x4 ASCQ=0x2 Mar 13 13:52:07 Fonera user.warn kernel: end_request: I/O error, dev sda, sector 442065279
comment:20 Changed 6 years ago by matthijs
- Status changed from infoneeded to investigate
Ok, I'm compiling a firmware for you to try now. It should be done in 30-60 minutes or something, I'll put up a link here when it is done.
This firmware will have:
- A patch to show a backtrace in the "Device not ready" case and resubmit the command in the queue
- USB debugging enabled, just in case there is some weird condition in the USB stack that is relevent
- Timestamps on kernel logmessages in dmesg
Apart from that, it is just a plain trunk firmware.
I'm not sure if this patch will actually help, it's mostly a directed guess of something that could help. It could also mean that the SCSI stack deadlocks itself by continuously retrying the same (failing) command, which you could probably fix by unplugging the disk or rebooting.
For further info, I'm doing a bit of testing with my Seagate GoFlex? 3TB disk here and I've not seen similar problems yet. The disk spins down after a while, but then running ls /tmp/mounts/* blocks for a dozen or so seconds while the disk spins up and then everything seems to work ok. Perhaps there is something peculiar with these FreeAgent? Desktop drivers wrt how they handle spindown...
comment:21 Changed 6 years ago by matthijs
It was done quicker than expected, here's the firmware: http://www.stderr.nl/static/tmp/firmware-fonera2n-retry-device-busy.tgz
To install it, just upload it through the WebUI (Settings -> Advanced IIRC). It should preserve all your settings normally.
If the device busy error occurs again, then it should show a backtrace but hopefully not the subsequent filesystem errors. Could you see what happens with this firmware?
comment:22 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
my fonera has quite some duties and before i accidentally ruin it i'd like to have a complete backup of it (this time...). last time (just 4 months ago) i also thought i'd "just" upgrade it but nearly bricked it.
back then it took me quite some hours to bring it up again, including openvpn, dropbear with pubkey auth, transmission including the old torrent files, find and reinstall all the additional opkg packages, find unrar, compile the dav2fs module as mentioned in some other ticket, and some additional scripting like having an additional application image mapped to /usr/local which enables me to have more programs available than the fonera flash could support.
as mentioned i'll not be online until 25th and i have to do some preparation for that. i promise to prepare everything as soon as i'm back and i'll try to provide the requested backtrace as soon as possible. thanks for your understanding!
comment:23 Changed 6 years ago by matthijs
Ah, when I say "all your settings", I actually mean all regular settings from the WebUI. Custom installed apps etc. are not preserved, so you'll have to manually backup those. It could help to have a look at the files in /jffs on your Fonera, those are all the files that are different or new compared to the original (read-only) firmware image (the read-only image is in /rom, / is an overlay of /rom with /jffs on top).
Putting this on hold until after the 25th is no problem, I'm glad to have some proper debug info for this issue in the first place, so thanks already!
comment:24 Changed 6 years ago by matthijs
I just attached the patch that I applied to the firmware image in comment:21, for future reference (and so I can remove it from my local build tree for now).
comment:25 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
i've
- backed up my fonera's jffs
- flashed http://www.stderr.nl/static/tmp/firmware-fonera2n-retry-device-busy.tgz
- merged resp. restored several files from the jffs archive
- reinstalled all missing modules
currently
- everything seems to be back up and running
- the error has not been seen by now
=> the patch seems to work so far!
i'll give an update in a few days - thanks!
comment:26 follow-up: ↓ 28 Changed 6 years ago by matthijs
Great! Could you see if the message "Checking spinup status..." appears in logread now? It probably appears once when connecting the drive, but I'm more interested if it appears later on as well.
comment:27 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
after booting up without the disk attached i get the following output:
BusyBox v1.11.1 (2013-03-13 14:55:49 CET) built-in shell (ash) Enter 'help' for a list of built-in commands. ------ Fonera 2.0n Firmware (SVN trunk) ----------- * Based on OpenWrt - http://openwrt.org * Powered by FON - http://www.fon.com ---------------------------------------------------- root@Fonera:~# logread |grep -v transmission && logread -f |grep -v transmission Mar 13 14:03:04 Fonera user.info kernel: [42949381.900000] br-lan: port 1(eth0.1) entering learning state Mar 13 14:03:04 Fonera user.info kernel: [42949381.910000] br-lan: topology change detected, propagating Mar 13 14:03:04 Fonera user.info kernel: [42949381.920000] br-lan: port 1(eth0.1) entering forwarding state Mar 13 14:03:05 Fonera user.warn kernel: [42949383.320000] rt2860v2_ap: module license 'unspecified' taints kernel. Mar 13 14:03:06 Fonera user.info kernel: [42949383.520000] usbcore: registered new interface driver usblp Mar 13 14:03:06 Fonera user.info kernel: [42949383.530000] drivers/usb/class/usblp.c: v0.13: USB Printer Device Class driver Mar 13 14:03:06 Fonera user.info kernel: [42949383.890000] usbcore: registered new interface driver usbserial Mar 13 14:03:06 Fonera user.info kernel: [42949383.900000] drivers/usb/serial/usb-serial.c: USB Serial Driver core Mar 13 14:03:06 Fonera user.info kernel: [42949384.030000] Linux video capture interface: v2.00 Mar 13 14:03:06 Fonera user.info kernel: [42949384.240000] hso: drivers/usb/serial/hso.c: 1.6-Option Option Wireless Mar 13 14:03:06 Fonera user.info kernel: [42949384.250000] usbcore: registered new interface driver hso Mar 13 14:03:06 Fonera user.info kernel: [42949384.300000] drivers/usb/serial/usb-serial.c: USB Serial support registered for GSM modem (1-port) Mar 13 14:03:06 Fonera user.info kernel: [42949384.310000] usbcore: registered new interface driver option Mar 13 14:03:06 Fonera user.info kernel: [42949384.320000] drivers/usb/serial/option.c: USB Driver for GSM modems: v0.7.2 Mar 13 14:03:07 Fonera user.info kernel: [42949384.520000] drivers/usb/serial/usb-serial.c: USB Serial support registered for Sierra USB modem (1 port) Mar 13 14:03:07 Fonera user.info kernel: [42949384.530000] drivers/usb/serial/usb-serial.c: USB Serial support registered for Sierra USB modem (3 port) Mar 13 14:03:07 Fonera user.info kernel: [42949384.540000] usbcore: registered new interface driver sierra Mar 13 14:03:07 Fonera user.info kernel: [42949384.550000] drivers/usb/serial/sierra.c: USB Driver for Sierra Wireless USB modems: v.1.0.6 Mar 13 14:03:07 Fonera user.warn kernel: [42949384.740000] fuse init (API version 7.8) Mar 13 14:03:07 Fonera user.info kernel: [42949384.940000] usbcore: registered new interface driver uvcvideo Mar 13 14:03:07 Fonera user.info kernel: [42949384.950000] USB Video Class driver (SVN r215) Mar 13 14:03:07 Fonera user.info : switch reg write offset=48, value=1001 Mar 13 14:03:08 Fonera user.info : iptables: No chain/target/match by that name Mar 13 14:03:08 Fonera user.info : iptables: No chain/target/match by that name Mar 13 14:03:08 Fonera user.info : iptables: No chain/target/match by that name Mar 13 14:03:08 Fonera user.info : iptables: No chain/target/match by that name Mar 13 14:03:08 Fonera user.info : iptables: No chain/target/match by that name Mar 13 14:03:08 Fonera user.info : iptables: No chain/target/match by that name Mar 13 14:03:09 Fonera user.info : ifconfig: SIOCGIFFLAGS: No such device Mar 13 14:03:09 Fonera user.info : ifconfig: SIOCGIFFLAGS: No such device Mar 13 14:03:09 Fonera user.info : killall: ap_client: no process killed Mar 13 14:03:09 Fonera user.warn kernel: [42949386.700000] setting region code 1 Mar 13 14:03:09 Fonera user.warn kernel: [42949386.710000] setting region code 7 Mar 13 14:03:09 Fonera user.warn kernel: [42949386.720000] RA_WIFI using 2 SSIDs Mar 13 14:03:09 Fonera user.warn kernel: [42949386.730000] geo beacon private:0 public:0 Mar 13 14:03:09 Fonera user.warn kernel: [42949386.770000] MAC: 00:18:84:88:92:64 Mar 13 14:03:12 Fonera user.warn kernel: [42949389.490000] 0x1300 = 00064320 Mar 13 14:03:13 Fonera user.info kernel: [42949390.480000] device ra0 entered promiscuous mode Mar 13 14:03:13 Fonera user.info kernel: [42949390.490000] br-lan: port 2(ra0) entering learning state Mar 13 14:03:13 Fonera user.info kernel: [42949390.500000] br-lan: topology change detected, propagating Mar 13 14:03:13 Fonera user.info kernel: [42949390.510000] br-lan: port 2(ra0) entering forwarding state Mar 13 14:03:13 Fonera user.info : Loading defaults Mar 13 14:03:13 Fonera user.info : Loading synflood protection Mar 13 14:03:13 Fonera user.info : Adding custom chains Mar 13 14:03:13 Fonera user.info : Loading zones Mar 13 14:03:14 Fonera user.info : iptables: Chain already exists Mar 13 14:03:14 Fonera user.info : iptables: Chain already exists Mar 13 14:03:14 Fonera user.info : iptables: Chain already exists Mar 13 14:03:14 Fonera user.info : iptables: Chain already exists Mar 13 14:03:14 Fonera user.info : iptables: Chain already exists Mar 13 14:03:14 Fonera user.info : iptables: Chain already exists Mar 13 14:03:14 Fonera user.info : Loading rules Mar 13 14:03:14 Fonera user.info : Loading forwarding Mar 13 14:03:14 Fonera user.info : Loading redirects Mar 13 14:03:14 Fonera user.info : Loading includes Mar 13 14:03:14 Fonera user.info : /etc/firewall.fon Mar 13 14:03:14 Fonera user.info : FWallFON Mar 13 14:03:15 Fonera user.info : FWallDaemon Mar 13 14:03:15 Fonera user.info : iptables v1.4.0: invalid port/service `uci' specified Mar 13 14:03:15 Fonera user.info : Try `iptables -h' or 'iptables --help' for more information. Mar 13 14:03:15 Fonera user.info : iptables v1.4.0: invalid port/service `get' specified Mar 13 14:03:15 Fonera user.info : Try `iptables -h' or 'iptables --help' for more information. Mar 13 14:03:15 Fonera user.info : iptables v1.4.0: invalid port/service `services.openvpn.tcp_port' specified Mar 13 14:03:15 Fonera user.info : Try `iptables -h' or 'iptables --help' for more information. Mar 13 14:03:15 Fonera user.info : iptables v1.4.0: invalid port/service `uci' specified Mar 13 14:03:15 Fonera user.info : Try `iptables -h' or 'iptables --help' for more information. Mar 13 14:03:15 Fonera user.info : iptables v1.4.0: invalid port/service `get' specified Mar 13 14:03:15 Fonera user.info : Try `iptables -h' or 'iptables --help' for more information. Mar 13 14:03:15 Fonera user.info : iptables v1.4.0: invalid port/service `services.openvpn.udp_port' specified Mar 13 14:03:15 Fonera user.info : Try `iptables -h' or 'iptables --help' for more information. Mar 13 14:03:15 Fonera user.info : killall: chilli: no process killed Mar 13 14:03:15 Fonera user.info : /etc/firewall.user Mar 13 14:03:16 Fonera user.notice root: adding tun-ovpn to firewall zone vpn Mar 13 14:03:16 Fonera user.notice root: adding br-lan to firewall zone lan Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: Found user 'nobody' (UID 65534) and group 'nogroup' (GID 65534). Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: Successfully dropped root privileges. Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: avahi-daemon 0.6.25 starting up. Mar 13 14:03:17 Fonera daemon.warn avahi-daemon[1401]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns! Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: No service file found in /tmp/mdns/. Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: Joining mDNS multicast group on interface br-lan.IPv4 with address 10.0.0.98. Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: New relevant interface br-lan.IPv4 for mDNS. Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: Network interface enumeration completed. Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: Registering new address record for 10.0.0.98 on br-lan.IPv4. Mar 13 14:03:17 Fonera daemon.info avahi-daemon[1401]: Registering HINFO record with values 'MIPS'/'LINUX'. Mar 13 14:03:18 Fonera daemon.info avahi-daemon[1401]: Server startup complete. Host name is Fonera.local. Local service cookie is 1706607918. Mar 13 14:03:18 Fonera user.notice root: setting up led : powerg Mar 13 14:03:18 Fonera user.notice root: setting up led : wifi Mar 13 14:03:18 Fonera user.crit fonstated: fonstated - v2.0 Mar 13 14:03:18 Fonera user.crit fonstated: loaded fontimer for "/bin/thinclient dummy" period=17280 Mar 13 14:03:18 Fonera user.crit fonstated: loaded fontimer for "/etc/fonstated/RestartNtpclient" period=17280 Mar 13 14:03:18 Fonera user.crit fonstated: loaded fontimer for "/etc/init.d/fonsmcd" period=12 Mar 13 14:03:18 Fonera user.crit fonstated: loaded fontimer for "/etc/fonstated/StartHttpd" period=2150 Mar 13 14:03:18 Fonera user.crit fonstated: starting chillispot fonstate plugin Mar 13 14:03:18 Fonera user.crit fs: Failed to connect to socket (/tmp/fonstated.sock): No such file or directory Mar 13 14:03:18 Fonera user.crit fonstated: added fontimer libcallback period=60 Mar 13 14:03:18 Fonera user.crit fonstated: added fontimer libcallback period=17280 Mar 13 14:03:18 Fonera user.crit fonstated: added fonevent hotspot_decount -> libcallback 1 Mar 13 14:03:18 Fonera user.crit fonstated: added fonevent hotspot_inccount -> libcallback 1 Mar 13 14:03:18 Fonera user.crit fonstated: added fonevent hotspot_resetcount -> libcallback 1 Mar 13 14:03:18 Fonera user.crit fonstated: added fonevent hotspot_wdt_start -> libcallback 1 Mar 13 14:03:18 Fonera user.crit fonstated: added fonevent hotspot_wdt_stop -> libcallback 1 Mar 13 14:03:18 Fonera user.crit fonstated: enqueue --> UMTS Mar 13 14:03:18 Fonera user.crit fonstated: enqueue --> SetupHosts Mar 13 14:03:18 Fonera user.crit fonstated: enqueue --> BootServices Mar 13 14:03:18 Fonera user.crit fonstated: enqueue --> FWallDaemon Mar 13 14:03:18 Fonera user.crit fonstated: enqueue --> StartTorrent Mar 13 14:03:18 Fonera user.crit fonstated: running event /etc/fonstated/UMTS Mar 13 14:03:18 Fonera user.crit fonstated: finished running /etc/fonstated/UMTS Mar 13 14:03:18 Fonera user.crit fonstated: running event /etc/fonstated/SetupHosts Mar 13 14:03:18 Fonera user.crit fonstated: finished running /etc/fonstated/SetupHosts Mar 13 14:03:18 Fonera user.crit fonstated: running event /etc/fonstated/BootServices Mar 13 14:03:18 Fonera user.notice root: runnow --> /etc/fonstated/Redirect Mar 13 14:03:18 Fonera user.notice root: runnow --> /etc/fonstated/StartFonsmcd Mar 13 14:03:18 Fonera user.notice root: runnow --> /etc/fonstated/RestartMountd Mar 13 14:03:19 Fonera user.crit mountd[1617]: Starting OpenWrt (auto)mountd V1 Mar 13 14:03:19 Fonera daemon.info fonsmcd[1601]: Sucessfully started Mar 13 14:03:19 Fonera user.notice root: runnow --> /etc/fonstated/StartHttpd Mar 13 14:03:19 Fonera user.crit mountd[1617]: trying to mount /tmp/run/mountd/ as the autofs root Mar 13 14:03:20 Fonera user.crit fonstated: finished running /etc/fonstated/BootServices Mar 13 14:03:20 Fonera user.crit fonstated: running event /etc/fonstated/FWallDaemon Mar 13 14:03:20 Fonera user.emerg syslog: starting onlined Mar 13 14:03:20 Fonera user.notice root: runnow --> /etc/fonstated/SetupDlmd Mar 13 14:03:20 Fonera user.emerg syslog: new online state Online Mar 13 14:03:20 Fonera authpriv.info dropbear[1658]: Not backgrounding Mar 13 14:03:20 Fonera daemon.info dnsmasq[1675]: started, version 2.45 cachesize 150 Mar 13 14:03:20 Fonera daemon.info dnsmasq[1675]: compile time options: IPv6 GNU-getopt ISC-leasefile no-DBus no-I18N TFTP Mar 13 14:03:20 Fonera daemon.info dnsmasq[1675]: DHCP, IP range 10.0.0.100 -- 10.0.0.250, lease time 12h Mar 13 14:03:20 Fonera user.info syslog: whitelist file: /etc/fon/whitelist.dnsmasq Mar 13 14:03:20 Fonera daemon.info dnsmasq[1675]: using local addresses only for domain lan Mar 13 14:03:20 Fonera daemon.info dnsmasq[1675]: reading /tmp/resolv.conf.auto Mar 13 14:03:20 Fonera daemon.info dnsmasq[1675]: using nameserver 10.0.0.1#53 Mar 13 14:03:20 Fonera daemon.info dnsmasq[1675]: using local addresses only for domain lan Mar 13 14:03:20 Fonera daemon.info dnsmasq[1675]: read /etc/hosts - 2 addresses Mar 13 14:03:20 Fonera daemon.err dnsmasq[1675]: failed to read /etc/ethers:No such file or directory Mar 13 14:03:21 Fonera user.crit fonstated: finished running /etc/fonstated/FWallDaemon Mar 13 14:03:21 Fonera user.crit fonstated: running event /etc/fonstated/StartTorrent Mar 13 14:03:21 Fonera user.crit fonstated: finished running /etc/fonstated/StartTorrent Mar 13 14:03:21 Fonera daemon.info avahi-daemon[1401]: Got SIGHUP, reloading. Mar 13 14:03:21 Fonera daemon.info avahi-daemon[1401]: Loading service file /tmp/mdns//ftp.service. Mar 13 14:03:21 Fonera daemon.info avahi-daemon[1401]: Loading service file /tmp/mdns//smb.service. Mar 13 14:03:21 Fonera daemon.info avahi-daemon[1401]: Loading service file /tmp/mdns//ssh.service. Mar 13 14:03:21 Fonera daemon.info avahi-daemon[1401]: Got SIGHUP, reloading. Mar 13 14:03:21 Fonera daemon.info avahi-daemon[1401]: Got SIGHUP, reloading. Mar 13 14:03:22 Fonera user.crit fonstated: enqueue --> Online Mar 13 14:03:22 Fonera user.crit fonstated: running event /etc/fonstated/Online Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: OpenVPN 2.2.2 mipsel-linux [SSL] [LZO2] built on Mar 13 2013 Mar 13 14:03:22 Fonera daemon.warn openvpn(openvpn)[1716]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts Mar 13 14:03:22 Fonera daemon.info avahi-daemon[1401]: Service "Fonera2.0 SSH" (/tmp/mdns//ssh.service) successfully established. Mar 13 14:03:22 Fonera daemon.info avahi-daemon[1401]: Service "LaFonera" (/tmp/mdns//smb.service) successfully established. Mar 13 14:03:22 Fonera daemon.info avahi-daemon[1401]: Service "Fonera2.0 FTP Server" (/tmp/mdns//ftp.service) successfully established. Mar 13 14:03:22 Fonera user.notice root: runnow --> /etc/fonstated/HotspotStart Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: Diffie-Hellman initialized with 1024 bit key Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: TLS-Auth MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ] Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: Socket Buffers: R=[109568->131072] S=[109568->131072] Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: TUN/TAP device tun-ovpn opened Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: TUN/TAP TX queue length set to 100 Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: /sbin/ifconfig tun-ovpn 10.8.0.1 netmask 255.255.255.0 mtu 1500 broadcast 10.8.0.255 Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ] Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: UDPv4 link local (bound): [undef]:1194 Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: UDPv4 link remote: [undef] Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: MULTI: multi_init called, r=256 v=256 Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: IFCONFIG POOL: base=10.8.0.2 size=126 Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: IFCONFIG POOL LIST Mar 13 14:03:22 Fonera daemon.notice openvpn(openvpn)[1716]: Initialization Sequence Completed Mar 13 14:03:24 Fonera user.notice root: adding tun0 to firewall zone hotspot Mar 13 14:03:24 Fonera local6.info chillispot[1851]: tun.c: 664: 2 (No such file or directory) TX queue length set to 100 Mar 13 14:03:24 Fonera local6.info chillispot[1851]: ChilliSpot 1.0-coova.4. Copyright 2002-2005 Mondru AB. Licensed under GPL. Copyright 2006 Coova Technologies Ltd. Licensed under GPL. See http://www.chillispot.org for credits. Mar 13 14:03:24 Fonera user.notice root: runnow --> /etc/fonstated/RestartNtpclient Mar 13 14:03:25 Fonera user.crit fonstated: finished running /etc/fonstated/Online Mar 13 14:03:25 Fonera user.crit fonstated: enqueue --> hotspot_wdt_start Mar 13 14:03:25 Fonera user.crit fonstated: running fast event hotspot_wdt_start Mar 13 14:03:25 Fonera user.crit fonstated: starting chilli wdt Mar 13 14:03:25 Fonera user.notice root: starting ntpclient Mar 25 12:34:46 Fonera local6.info chillispot[1851]: options.c: 782: Rereading configuration file and doing DNS lookup Mar 25 12:34:46 Fonera authpriv.info dropbear[1928]: Child connection from <removed> Mar 25 12:34:47 Fonera authpriv.notice dropbear[1928]: pubkey auth succeeded for 'root' <removed>
after plugging in the disk the following output is printed:
Mar 25 12:35:41 Fonera user.debug kernel: [42949458.050000] hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0002 Mar 25 12:35:41 Fonera user.debug kernel: [42949458.050000] hub 1-0:1.0: port 1, status 0101, change 0001, 12 Mb/s Mar 25 12:35:41 Fonera user.debug kernel: [42949458.210000] hub 1-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x101 Mar 25 12:35:41 Fonera user.info kernel: [42949458.390000] usb 1-1: new high speed USB device using dwc_otg and address 2 Mar 25 12:35:41 Fonera user.debug kernel: [42949458.610000] usb 1-1: default language 0x0409 Mar 25 12:35:41 Fonera user.debug kernel: [42949458.620000] usb 1-1: new device strings: Mfr=1, Product=2, SerialNumber=3 Mar 25 12:35:41 Fonera user.info kernel: [42949458.620000] usb 1-1: Product: FreeAgentDesktop Mar 25 12:35:41 Fonera user.info kernel: [42949458.630000] usb 1-1: Manufacturer: Seagate Mar 25 12:35:41 Fonera user.info kernel: [42949458.640000] usb 1-1: SerialNumber: 9QG2DCVZ Mar 25 12:35:41 Fonera user.debug kernel: [42949458.650000] usb 1-1: uevent Mar 25 12:35:41 Fonera user.debug kernel: [42949458.650000] usb 1-1: usb_probe_device Mar 25 12:35:41 Fonera user.info kernel: [42949458.650000] usb 1-1: configuration #1 chosen from 1 choice Mar 25 12:35:42 Fonera user.debug kernel: [42949458.660000] usb 1-1: adding 1-1:1.0 (config #1, interface 0) Mar 25 12:35:42 Fonera user.debug kernel: [42949458.660000] usb 1-1:1.0: uevent Mar 25 12:35:42 Fonera user.debug kernel: [42949458.660000] usb-storage 1-1:1.0: usb_probe_interface Mar 25 12:35:42 Fonera user.debug kernel: [42949458.660000] usb-storage 1-1:1.0: usb_probe_interface - got id Mar 25 12:35:42 Fonera user.info kernel: [42949458.660000] scsi0 : SCSI emulation for USB Mass Storage devices Mar 25 12:35:42 Fonera user.debug kernel: [42949458.670000] usb-storage: device found at 2 Mar 25 12:35:42 Fonera user.debug kernel: [42949458.670000] usb-storage: waiting for device to settle before scanning Mar 25 12:35:42 Fonera user.debug kernel: [42949458.670000] drivers/usb/core/inode.c: creating file '002' Mar 25 12:35:42 Fonera user.debug kernel: [42949458.670000] hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0002 Mar 25 12:35:42 Fonera user.debug kernel: [42949458.670000] hub 1-0:1.0: port 1 enable change, status 00000503 Mar 25 12:35:42 Fonera user.notice usb-modeswitch: 1-1:1.0: Manufacturer=Seagate Product=FreeAgentDesktop Serial=_9QG2DCVZ Mar 25 12:35:47 Fonera user.notice kernel: [42949463.670000] scsi 0:0:0:0: Direct-Access Seagate FreeAgentDesktop 100D PQ: 0 ANSI: 4 Mar 25 12:35:47 Fonera user.notice kernel: [42949463.680000] sda: Checking spinup status... sense_valid: 1, sense_key: 2, asc: 4, ascq: 2 Mar 25 12:35:47 Fonera user.notice kernel: [42949463.690000] sda: Spinning up disk... Mar 25 12:35:57 Fonera user.info kernel: . Mar 25 12:35:57 Fonera user.notice kernel: sda: Checking spinup status... sense_valid: 1, sense_key: 0, asc: 0, ascq: 0 Mar 25 12:35:57 Fonera user.warn kernel: [42949474.080000] ready Mar 25 12:35:57 Fonera user.notice kernel: [42949474.090000] SCSI device sda: 976773168 512-byte hdwr sectors (500108 MB) Mar 25 12:35:57 Fonera user.notice kernel: [42949474.100000] sda: Write Protect is off Mar 25 12:35:57 Fonera user.debug kernel: [42949474.110000] sda: Mode Sense: 1c 00 00 00 Mar 25 12:35:57 Fonera user.err kernel: [42949474.110000] sda: assuming drive cache: write through Mar 25 12:35:57 Fonera user.notice kernel: [42949474.120000] sda: Checking spinup status... sense_valid: 0, sense_key: 0, asc: 0, ascq: 0 Mar 25 12:35:57 Fonera user.notice kernel: [42949474.130000] SCSI device sda: 976773168 512-byte hdwr sectors (500108 MB) Mar 25 12:35:57 Fonera user.notice kernel: [42949474.140000] sda: Write Protect is off Mar 25 12:35:57 Fonera user.debug kernel: [42949474.150000] sda: Mode Sense: 1c 00 00 00 Mar 25 12:35:57 Fonera user.err kernel: [42949474.150000] sda: assuming drive cache: write through Mar 25 12:35:57 Fonera user.info kernel: [42949474.160000] sda: Mar 25 12:35:57 Fonera user.info kernel: sda1 Mar 25 12:35:57 Fonera user.notice kernel: [42949474.180000] sd 0:0:0:0: Attached scsi disk sda Mar 25 12:35:57 Fonera user.debug kernel: [42949474.190000] usb-storage: device scan complete Mar 25 12:35:58 Fonera user.crit mountd[1617]: new mount : FreeAgent -> sda1 (EXT3) Mar 25 12:35:58 Fonera user.crit mountd[1617]: mounting /tmp/run/mountd/sda1 Mar 25 12:35:58 Fonera user.crit mountd[1976]: mount -t ext3 -o rw,noatime,defaults /dev/sda1 /tmp/run/mountd/sda1 Mar 25 12:35:58 Fonera user.info kernel: [42949475.210000] kjournald starting. Commit interval 5 seconds Mar 25 12:35:58 Fonera user.info kernel: [42949475.220000] EXT3 FS on sda1, internal journal Mar 25 12:35:58 Fonera user.info kernel: [42949475.230000] EXT3-fs: recovery complete. Mar 25 12:35:58 Fonera user.info kernel: [42949475.240000] EXT3-fs: mounted filesystem with ordered data mode. Mar 25 12:35:58 Fonera user.crit mountd[1617]: ----------> mount ret = 0 Mar 25 12:36:03 Fonera user.crit fonstated: enqueue --> SetupDlmd Mar 25 12:36:03 Fonera user.crit fonstated: running event /etc/fonstated/SetupDlmd Mar 25 12:36:03 Fonera user.crit fonstated: finished running /etc/fonstated/SetupDlmd Mar 25 12:36:03 Fonera user.crit mountd[1982]: starting torrent sda1 Mar 25 12:36:04 Fonera user.info kernel: [42949481.120000] Adding 129528k swap on /tmp/mounts/FreeAgent//FoneraApps/torrent.2.3.8.0.swp. Priority:-1 extents:34 across:130716k
so to answer the question: YES, "Checking spinup status[...]" is being printed:
Mar 25 12:35:47 Fonera user.notice kernel: [42949463.680000] sda: Checking spinup status... sense_valid: 1, sense_key: 2, asc: 4, ascq: 2 Mar 25 12:35:47 Fonera user.notice kernel: [42949463.690000] sda: Spinning up disk... Mar 25 12:35:57 Fonera user.info kernel: . Mar 25 12:35:57 Fonera user.notice kernel: sda: Checking spinup status... sense_valid: 1, sense_key: 0, asc: 0, ascq: 0 Mar 25 12:35:57 Fonera user.warn kernel: [42949474.080000] ready Mar 25 12:35:57 Fonera user.notice kernel: [42949474.090000] SCSI device sda: 976773168 512-byte hdwr sectors (500108 MB) Mar 25 12:35:57 Fonera user.notice kernel: [42949474.100000] sda: Write Protect is off Mar 25 12:35:57 Fonera user.debug kernel: [42949474.110000] sda: Mode Sense: 1c 00 00 00 Mar 25 12:35:57 Fonera user.err kernel: [42949474.110000] sda: assuming drive cache: write through Mar 25 12:35:57 Fonera user.notice kernel: [42949474.120000] sda: Checking spinup status... sense_valid: 0, sense_key: 0, asc: 0, ascq: 0
as of now i didn't manage to trace a line like the above while spinning up the disk after it had gone to standby. but - as mentioned before - the system now definitely correctly waits for the drive to spin up and successfully continues operation :)
comment:28 in reply to: ↑ 26 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
Replying to matthijs:
Great! Could you see if the message "Checking spinup status..." appears in logread now? It probably appears once when connecting the drive, but I'm more interested if it appears later on as well.
the message definitely doesn't appear later on while spinning up. when spinning up after having been connected in standby there actually doesn't come up any message in logread.
but most important - probably in the name of many people having issues with fonera's perceived stability - thanks for fixing this issue!
comment:29 Changed 6 years ago by matthijs
Thanks for reporting back.
The fact that the message does not show up when the disk spins up tells me that in this case no explicit "spin up" message is being sent, as I expected. This also means that just waiting for the disk to spin up is sufficient, even though the disk replies with a "MANUAL INTERVENTION REQUIRED" message. I think this means that the disk you are using is somehow breaking the standard by this.
Given that, I'm not sure if I can just apply the patch to the main firmware, since it might break or cause deadlock for other disks...
It would be interesting to see if this problem also occurs on a more recent kernel and/or on a regular PC. Do you happen to have a PC with Linux installed where you could try to reproduce this problem?
comment:30 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
i never noticed the problem on my main machine:
Linux matrix 3.5.0-26-generic #42-Ubuntu SMP Fri Mar 8 23:18:20 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
of cause the reason might be the drive never went into standby => i'm testing it.
comment:31 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
ubuntu definitely doesn't have any issue with the drive - following shows the messages that are printed when connecting.
[17481.532042] usb 1-6: new high-speed USB device number 3 using ehci_hcd [17481.681146] usb 1-6: New USB device found, idVendor=0bc2, idProduct=3000 [17481.681152] usb 1-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [17481.681155] usb 1-6: Product: FreeAgentDesktop [17481.681158] usb 1-6: Manufacturer: Seagate [17481.681160] usb 1-6: SerialNumber: 9QG2DCVZ [17481.714478] Initializing USB Mass Storage driver... [17481.714599] scsi8 : usb-storage 1-6:1.0 [17481.714676] usbcore: registered new interface driver usb-storage [17481.714678] USB Mass Storage support registered. [17482.715793] scsi 8:0:0:0: Direct-Access Seagate FreeAgentDesktop 100D PQ: 0 ANSI: 4 [17482.716602] sd 8:0:0:0: Attached scsi generic sg4 type 0 [17482.724279] sd 8:0:0:0: [sdc] Spinning up disk... [17487.884043] .ready [17487.886285] sd 8:0:0:0: [sdc] 976773168 512-byte logical blocks: (500 GB/465 GiB) [17487.887652] sd 8:0:0:0: [sdc] Write Protect is off [17487.887656] sd 8:0:0:0: [sdc] Mode Sense: 1c 00 00 00 [17487.889154] sd 8:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [17487.908043] sdc: sdc1 [17487.919776] sd 8:0:0:0: [sdc] Attached SCSI disk [17488.785092] kjournald starting. Commit interval 5 seconds [17488.785899] EXT3-fs (sdc1): using internal journal [17488.793413] EXT3-fs (sdc1): recovery complete [17488.793416] EXT3-fs (sdc1): mounted filesystem with ordered data mode
after mounting the filesystem and going into standby the drive spins up without any problem - and without printing any message.
comment:32 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
hi matthijs,
i planned to ask you on how to get the above code change into the future release versions, possibly enabling the code only via nvm-switch (nvram) or the like if feasible.
saying this i finally wanted to verify everything is fine with the fonera - but then i had to find the following error messages and sda1 mounted as read-only:
[680483.720000] hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0002 [680483.720000] hub 1-0:1.0: port 1 enable change, status 00000503 [680488.720000] scsi 2:0:0:0: Direct-Access Seagate FreeAgentDesktop 100D PQ: 0 ANSI: 4 [680488.740000] sdb: Checking spinup status... sense_valid: 1, sense_key: 2, asc: 4, ascq: 2 [680488.750000] sdb: Spinning up disk....<5>sdb: Checking spinup status... sense_valid: 1, sense_key: 0, asc: 0, ascq: 0 [680499.050000] ready [680499.060000] SCSI device sdb: 976773168 512-byte hdwr sectors (500108 MB) [680499.070000] sdb: Write Protect is off [680499.080000] sdb: Mode Sense: 1c 00 00 00 [680499.080000] sdb: assuming drive cache: write through [680499.090000] sdb: Checking spinup status... sense_valid: 0, sense_key: 0, asc: 0, ascq: 0 [680499.100000] SCSI device sdb: 976773168 512-byte hdwr sectors (500108 MB) [680499.110000] sdb: Write Protect is off [680499.120000] sdb: Mode Sense: 1c 00 00 00 [680499.120000] sdb: assuming drive cache: write through [680499.130000] sdb: sdb1 [680499.170000] sd 2:0:0:0: Attached scsi disk sdb [680499.180000] usb-storage: device scan complete [680500.200000] kjournald starting. Commit interval 5 seconds [680500.220000] EXT3 FS on sdb1, internal journal [680500.230000] EXT3-fs: mounted filesystem with ordered data mode. [680804.050000] scsi 0:0:0:0: rejecting I/O to dead device [680804.060000] scsi 0:0:0:0: rejecting I/O to dead device [680807.990000] scsi 0:0:0:0: rejecting I/O to dead device [680808.000000] scsi 0:0:0:0: rejecting I/O to dead device [680809.180000] scsi 0:0:0:0: rejecting I/O to dead device [680809.190000] scsi 0:0:0:0: rejecting I/O to dead device [680814.740000] scsi 0:0:0:0: rejecting I/O to dead device [680830.290000] scsi 0:0:0:0: rejecting I/O to dead device [680830.300000] scsi 0:0:0:0: rejecting I/O to dead device [680830.310000] scsi 0:0:0:0: rejecting I/O to dead device [680839.320000] scsi 0:0:0:0: rejecting I/O to dead device [680839.330000] scsi 0:0:0:0: rejecting I/O to dead device [680840.120000] scsi 0:0:0:0: rejecting I/O to dead device [680842.930000] scsi 0:0:0:0: rejecting I/O to dead device [680842.940000] scsi 0:0:0:0: rejecting I/O to dead device [680842.950000] scsi 0:0:0:0: rejecting I/O to dead device [680846.740000] scsi 0:0:0:0: rejecting I/O to dead device [680861.200000] scsi 0:0:0:0: rejecting I/O to dead device [680868.880000] scsi 0:0:0:0: rejecting I/O to dead device [680868.900000] scsi 0:0:0:0: rejecting I/O to dead device [680920.100000] printk: 1 messages suppressed. [680920.100000] Buffer I/O error on device loop1, logical block 90114 [680920.110000] lost page write due to I/O error on loop1 [680920.120000] Buffer I/O error on device loop1, logical block 90115 [680920.130000] lost page write due to I/O error on loop1 [680925.100000] Buffer I/O error on device loop1, logical block 1 [680925.110000] lost page write due to I/O error on loop1 [680925.120000] Buffer I/O error on device loop1, logical block 2 [680925.130000] lost page write due to I/O error on loop1 [680925.140000] Buffer I/O error on device loop1, logical block 260 [680925.150000] lost page write due to I/O error on loop1 [680925.160000] Buffer I/O error on device loop1, logical block 262 [680925.170000] lost page write due to I/O error on loop1 [680942.850000] scsi 0:0:0:0: rejecting I/O to dead device [681233.440000] scsi 0:0:0:0: rejecting I/O to dead device [681280.100000] Buffer I/O error on device loop1, logical block 1 [681280.110000] lost page write due to I/O error on loop1 [681280.120000] Buffer I/O error on device loop1, logical block 2 [681280.130000] lost page write due to I/O error on loop1 [681280.140000] Buffer I/O error on device loop1, logical block 260 [681280.150000] lost page write due to I/O error on loop1 [681280.160000] Buffer I/O error on device loop1, logical block 262 [681280.170000] lost page write due to I/O error on loop1 [682394.930000] scsi 0:0:0:0: rejecting I/O to dead device [697140.060000] scsi 0:0:0:0: rejecting I/O to dead device [699562.470000] scsi 0:0:0:0: rejecting I/O to dead device [700701.560000] scsi 0:0:0:0: rejecting I/O to dead device [702575.460000] scsi 0:0:0:0: rejecting I/O to dead device [702691.750000] scsi 0:0:0:0: rejecting I/O to dead device [702789.070000] scsi 0:0:0:0: rejecting I/O to dead device [702789.080000] scsi 0:0:0:0: rejecting I/O to dead device [702897.910000] scsi 0:0:0:0: rejecting I/O to dead device [702897.920000] scsi 0:0:0:0: rejecting I/O to dead device [702967.370000] scsi 0:0:0:0: rejecting I/O to dead device root@Fonera:~#
/dev/sda1 on /tmp/run/mountd/sda1 type ext3 (ro,noatime,data=ordered) /dev/loop0 on /tmp/images/torrent type ext2 (rw) /dev/loop1 on /tmp/images/torrent/var type ext2 (rw)
any advice on how to debug this?
comment:33 Changed 6 years ago by matthijs
Looking at the output, it might be that this shows a different problem. Before, your device was returning "Device not ready" messages and didn't respond properly. Now it seems that the entire device has disconnected, the output you pasted shows the reconnect. Because there is no earlier output, I can't tell why it disconnected, but from all the I/O errors, we can be sure it happened suddenly. The spinning up messages you see now are to be expected, since they should occur once during the initialisation of the device.
The fact that you disk works properly with Ubuntu suggests that newer kernels have some kind of fix for this problem (but not the fix I now proposed, since that code is still unchanged in the latest kernel version). Looking around the git log, I did find https://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/?id=14216561e164671ce147458653b1fea06a4ada1e which looks related. I don't think it fully applies (it talks about the mpt2sas driver and contains some code triggered on the "ATA" vendor, which your drive does not have), but perhaps this patch fixes your bug as a side-effect.
I'll build another image for testing with this patch applied, to see if that one (also) helps. If so, I'd be happy to include this fix, since it comes from the official kernel (unlike the previous fix, which I just "guessed" together).
Changed 6 years ago by matthijs
Backport of 14216561e164671ce147458653b1fea06a4ada1e, used to build firmware-fonera2n-retry-device-busy-v2.tgz
comment:34 Changed 6 years ago by matthijs
The firmware with the (attached) patch is at: http://www.stderr.nl/static/tmp/firmware-fonera2n-retry-device-busy-v2.tgz
Could you see if this also prevents the Device not ready error from appearing?
comment:35 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
i have just flashed the software and i'll give an update asap!
for the sake of the reflash process i have created a backup and a restore script that might be useful for you as well. of cause this should be used only if the firmware has the same version number as (e.g. config-) files are not merged but overwritten.
root@Fonera:/tmp/run/mountd/sda1/backup# cat thor_create_jffs_backup.sh find /jffs/ -name "META_*" |sed -e "s/^\/jffs\//.\//" >/tmp/exclude.lst tar -cz -X /tmp/exclude.lst -f jffs-2.3.8.0-20130425.tar.gz -C /jffs/ . rm /tmp/exclude.lst
root@Fonera:/tmp/run/mountd/sda1/backup# cat thor_restore_jffs_backup.sh mkdir jffs-2.3.8.0-20130425 cd jffs-2.3.8.0-20130425 tar xzf ../jffs-2.3.8.0-20130425.tar.gz opkg update for f in ./usr/lib/opkg/info/*.control do opkg install `basename $f .control` done cp -pR . / cd .. rm -R jffs-2.3.8.0-20130425
obviously using a parameter or at least a variable for the archive name would be wise ;)
once the fonera is rebooted it will behave pretty much exactly as before the flashing.
comment:36 Changed 6 years ago by Thomas Horner <trac.fonosfera.org@…>
bad news:
EXT3 FS on sda1, internal journal EXT3-fs: recovery complete. EXT3-fs: mounted filesystem with ordered data mode. Adding 129528k swap on /tmp/mounts/FreeAgent//FoneraApps/torrent.2.3.8.0.swp. Priority:-1 extents:34 across:130716k sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 331612615 EXT3-fs error (device sda1): ext3_get_inode_loc: unable to read inode block - inode=10364404, block=41451569 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 63 Buffer I/O error on device sda1, logical block 0 lost page write due to I/O error on sda1 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 61958135 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 61958135 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 61958135 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 63803239 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 63803239 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 63803271 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 331746687 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 331746687 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 10327 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 10327 EXT3-fs error (device sda1): ext3_find_entry: reading directory #2 offset 0 sd 0:0:0:0: Device not ready: <6>: Current: sense key=0x2 ASC=0x4 ASCQ=0x2 end_request: I/O error, dev sda, sector 63 Buffer I/O error on device sda1, logical block 0 lost page write due to I/O error on sda1 root@Fonera:~#
so do I have this problem... I was opening the same ticket, but I have read this first and is the same problem...