USB Disk mounting is unstable

[rughis]

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.

[ddomee@…]

so do I have this problem... I was opening the same ticket, but I have read this first and is the same problem...

[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.

[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

[ddomee@…]

I haven't a disk larger then 1 Tb. My disk is only 80 Gb...

[calvinturbo@…]

Oh, that is strange. Please fix this Matthijs!

[mihaly.reg@…]

logread

[anonymous]

same problem here.

[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.

[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).

[andrepinto@…]

This instability also happens with my 1tb hd from iomega. Firmware 2.3.7.0 Beta 2

[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

[matthijs]

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?

[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?

[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

[matthijs]

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?

[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:~# 

[matthijs]

Indeed, thanks!

[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).

[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:~#

[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

[matthijs]

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...

[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?

[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!

[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!

[matthijs]

Attempt to fix spindown error observed by Thomas Horner

[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).

[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!

[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.

[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 :)

[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!

[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?

[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.

[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.

[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?

[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).

[matthijs]

Backport of 14216561e164671ce147458653b1fea06a4ada1e, used to build firmware-fonera2n-retry-device-busy-v2.tgz

[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?

[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.

[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:~#