Bug 756500

Summary:	usb /dev/sdb renamed /dev/sdc after suspend
Product:	[Fedora] Fedora	Reporter:	jepege
Component:	kernel	Assignee:	Kernel Maintainer List <kernel-maint>
Status:	CLOSED WORKSFORME	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	16	CC:	dennis, gansalmon, itamar, jonathan, kernel-maint, madhu.chinakonda
Target Milestone:	---
Target Release:	---
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2012-03-01 13:44:05 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description jepege 2011-11-23 19:20:10 UTC

Description of problem:
I have Fedora 16 (Vortexbox 2.0) installed and use an external USB disk attached permanently. The drive (/dev/sdb) is mounted on /storagen(by using UUID in fstab). I noticed that after suspend the drive no longer mounted on /dev/sdb but on /dev/sdc. However the mount /dev/sdb on /storage stills exists but is not accessable. I now have to reboot the server to get access to my data on /storage. 


Version-Release number of selected component (if applicable):
Fedora 16

How reproducible:
It is hard to reproduce. I think it happens once in 3-4 days. In that time the server suspends about 20 times.

attach usb device (/dev/sdb) 
mount usb device using UUID to /storage

Steps to Reproduce:
1. echo 0 > /sys/class/rtc/rtc0/wakealarm
2. echo `date '+%s' -d '+ 5 minutes'` > /sys/class/rtc/rtc0/wakealarm
3. /usr/sbin/pm-suspend
  
Actual results:
device sdb no longer available (/dev/sdb does not exist)
/dev/sdb still mounted on /storage 

Expected results:
if device sdb no longer exists (replaced by /dev/sdc) then the mount /dev/sdb should be deleted and a remount of the UUID should take place.
That leads to /dev/sdc being mounted on /storage

Additional info:
Here are some listings:
#/etc/fstab

UUID=27a71999-3d79-4a94-8c69-5ab22423db74 /storage ext4 noatime,barrier=0,rw 0 0

#output from mount
/dev/sdb on /storage type ext4 (rw,noatime,user_xattr,acl,barrier=0,data=ordered)

#udev/rules.d/80-usbmount.rules
ACTION=="add", BUS=="usb", KERNEL=="sd*", RUN+="/opt/vortexbox/usbaction add %k %n"
ACTION=="remove", BUS=="usb", KERNEL=="sd*", RUN+="/opt/vortexbox/usbaction remove %k %n"


# output of /opt/vortexbox/usbaction 
11/22/2011 00:30:13 - USB disk /dev/sdb removed
11/22/2011 00:30:32 - USB disk added [Disk /dev/sdc: 2000.4 GB, 2000398934016 bytes]
11/22/2011 01:56:30 - USB disk /dev/sdc removed
11/22/2011 01:56:31 - USB disk added [Disk /dev/sdc: 2000.4 GB, 2000398934016 bytes]

Comment 1 jepege 2011-11-24 18:40:49 UTC

This morning the problems occurred again. Looks like the hibernate is causing the problem. The server is hibernated every night at 0:30. This morning it was hibernated at 0:50.

Looks like the storage.mount exited with an error. If this process wants to umount /storage then it will fail because squeezeboxserver is still running.
 
Listings:
# ls -d /dev/sd*
/dev/sda  /dev/sda1  /dev/sda2  /dev/sda3  /dev/sdc

# mount | grep storage
/dev/sdb on /storage type ext4 (rw,noatime,user_xattr,acl,barrier=0,data=ordered)

# tail /var/log/usbbackup.log
11/24/2011 00:50:20 - USB disk /dev/sdb removed
11/24/2011 00:50:39 - USB disk added [Disk /dev/sdc: 2000.4 GB, 2000398934016 bytes]

# grep "Nov 24 00:50" /var/log/messages
Nov 24 00:50:19 vortexbox kernel: [92329.036380] scsi: killing requests for dead queue
Nov 24 00:50:20 vortexbox kernel: [92329.139121] usb 3-2: new full speed USB device number 2 using uhci_hcd
Nov 24 00:50:20 vortexbox kernel: [92329.267053] usb 3-2: not running at top speed; connect to a high speed hub
Nov 24 00:50:20 vortexbox kernel: [92329.295055] usb 3-2: New USB device found, idVendor=1058, idProduct=1003
Nov 24 00:50:20 vortexbox kernel: [92329.295059] usb 3-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Nov 24 00:50:20 vortexbox kernel: [92329.295062] usb 3-2: Product: External HDD
Nov 24 00:50:20 vortexbox kernel: [92329.295064] usb 3-2: Manufacturer: Western Digital
Nov 24 00:50:20 vortexbox kernel: [92329.295067] usb 3-2: SerialNumber: 57442D574341565932343033323336
Nov 24 00:50:20 vortexbox dbus[806]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Nov 24 00:50:20 vortexbox dbus-daemon[806]: dbus[806]: [system] Activating service name='org.freedesktop.PackageKit' (using s
ervicehelper)
Nov 24 00:50:20 vortexbox kernel: [92329.298187] scsi7 : usb-storage 3-2:1.0
Nov 24 00:50:20 vortexbox systemd[1]: storage.mount mount process exited, code=exited status=1
Nov 24 00:50:20 vortexbox dbus[806]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Nov 24 00:50:20 vortexbox dbus-daemon[806]: dbus[806]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Nov 24 00:50:21 vortexbox kernel: [92330.302093] scsi 7:0:0:0: Direct-Access     WD       20EADS External  1.75 PQ: 0 ANSI: 4
Nov 24 00:50:21 vortexbox kernel: [92330.302149] scsi: killing requests for dead queue
Nov 24 00:50:21 vortexbox kernel: [92330.302217] scsi: killing requests for dead queue
Nov 24 00:50:21 vortexbox kernel: [92330.302277] scsi: killing requests for dead queue
Nov 24 00:50:21 vortexbox kernel: [92330.302337] scsi: killing requests for dead queue
Nov 24 00:50:21 vortexbox kernel: [92330.302396] scsi: killing requests for dead queue
Nov 24 00:50:21 vortexbox kernel: [92330.302455] scsi: killing requests for dead queue
Nov 24 00:50:21 vortexbox kernel: [92330.302515] scsi: killing requests for dead queue
Nov 24 00:50:21 vortexbox kernel: [92330.302573] scsi: killing requests for dead queue
Nov 24 00:50:21 vortexbox kernel: [92330.302802] sd 7:0:0:0: Attached scsi generic sg2 type 0
Nov 24 00:50:21 vortexbox kernel: [92330.308077] sd 7:0:0:0: [sdc] 3907029168 512-byte logical blocks: (2.00 TB/1.81 TiB)
Nov 24 00:50:21 vortexbox kernel: [92330.311075] sd 7:0:0:0: [sdc] Write Protect is off
Nov 24 00:50:21 vortexbox kernel: [92330.314075] sd 7:0:0:0: [sdc] No Caching mode page present
Nov 24 00:50:21 vortexbox kernel: [92330.314127] sd 7:0:0:0: [sdc] Assuming drive cache: write through
Nov 24 00:50:21 vortexbox kernel: [92330.325075] sd 7:0:0:0: [sdc] No Caching mode page present
Nov 24 00:50:21 vortexbox kernel: [92330.325121] sd 7:0:0:0: [sdc] Assuming drive cache: write through
Nov 24 00:50:21 vortexbox kernel: [92330.469889] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
Nov 24 00:50:21 vortexbox NetworkManager[782]: <info> (eth0): carrier now ON (device state 100)
Nov 24 00:50:21 vortexbox NetworkManager[782]: NetworkManager[782]: <info> (eth0): carrier now ON (device state 100)
Nov 24 00:50:31 vortexbox kernel: [92340.565204]  sdc: unknown partition table
Nov 24 00:50:31 vortexbox kernel: [92340.578194] sd 7:0:0:0: [sdc] No Caching mode page present
Nov 24 00:50:31 vortexbox kernel: [92340.578247] sd 7:0:0:0: [sdc] Assuming drive cache: write through
Nov 24 00:50:31 vortexbox kernel: [92340.578289] sd 7:0:0:0: [sdc] Attached SCSI disk
Nov 24 00:50:39 vortexbox kernel: [92348.119027] usb 3-2: reset full speed USB device number 2 using uhci_hcd

Comment 2 jepege 2011-12-05 19:10:25 UTC

Looking closer to the messages log file I noticed 

Nov 24 00:50:19 vortexbox kernel: [92328.913492] PM: Not enough free swap

Adding enough space to the swap solved the problem.

Steps to Reproduce the error:
1. swap partition smaller then amount of memory used
2. attach usb device (/dev/sdb) 
3. mount usb device using UUID to /storage

4. echo 0 > /sys/class/rtc/rtc0/wakealarm
5. echo `date '+%s' -d '+ 5 minutes'` > /sys/class/rtc/rtc0/wakealarm
6. /usr/sbin/pm-hibernate

Comment 3 Josh Boyer 2012-03-01 13:44:05 UTC

This seems like it was due to not enough swap space for hibernation, which was causing the bus probe again after a failure.

Thanks for letting us know you solved it.