[Pkg-utopia-maintainers] Bug#779931: "sk_disk_check_sleep_mode: Operation not supported" for USB3 HDD docking based on JMicron 152d:0551

Gianluca Oglietti gianogli at tiscali.it
Fri Mar 6 14:30:18 UTC 2015 

Package: libatasmart4
Version: 0.19-3
Severity: grave
Justification: causes non-serious data loss

Dear Maintainer,

I bought a new HDD docking station (for 2 HDDs) based on JMicron JMB551 chipset
but I discover an issue that could cause data loss.

If I mount some partitions of 2 HDDs connected to my laptop via USB 3.0 using
this docking station all works fine until the JMBB551 go in "sleep mode". This
kind of docking station, in fact, have an "intelligent sleep function" that put
the HDDs in sleep mode when there aren't R/W data operations for at least 5
minutes.

Every 10 minutes udisksd control the state of SMART attributes of the attached
HDDs but when the docking is in "sleep mode" we notice the error
"sk_disk_check_sleep_mode: Operation not supported" and the USB connection to
the docking is resetted as you can see in the next udisksd log:

****************************
14:37:52.873:[3496]:[NOTICE]: udisks daemon version 2.1.3 starting [main.c:146,
main()]
14:37:52.874:[3496]:[DEBUG]: Entering main event loop [main.c:171, main()]
14:37:52.885:[3496]:[INFO]: Initialization (device probing)
[udiskslinuxprovider.c:445, udisks_linux_provider_start()]
14:37:52.900:[3496]:[INFO]: Initialization (coldplug 1/2)
[udiskslinuxprovider.c:457, udisks_linux_provider_start()]
14:37:52.900:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.902:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.902:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop2
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.903:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop3
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.903:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop4
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.904:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop5
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.904:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop6
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.905:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop7
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.905:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.907:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.908:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda2
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.909:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda3
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.910:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata2/host1/target1:0:0/1:0:0:0/block/sr0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.911:[3496]:[INFO]: Initialization (coldplug 2/2)
[udiskslinuxprovider.c:457, udisks_linux_provider_start()]
14:37:52.911:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.911:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.912:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop2
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.912:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop3
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.912:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop4
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.913:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop5
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.913:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop6
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.913:[3496]:[DEBUG]: uevent add /sys/devices/virtual/block/loop7
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.914:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.914:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.915:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda2
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.915:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda3
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.916:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:1f.2/ata2/host1/target1:0:0/1:0:0:0/block/sr0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:37:52.916:[3496]:[INFO]: Initialization complete [udiskslinuxprovider.c:466,
udisks_linux_provider_start()]
14:37:52.916:[3498]:[INFO]: Housekeeping initiated (0 seconds since last
housekeeping) [udiskslinuxprovider.c:969, housekeeping_thread_func()]
14:37:52.916:[3498]:[INFO]: Refreshing SMART data on
/org/freedesktop/UDisks2/drives/TS512GSSD370_B807930363 (nowakeup=0)
[udiskslinuxdriveobject.c:925, udisks_linux_drive_object_housekeeping()]
14:37:52.917:[3496]:[DEBUG]: Connected to the system bus [main.c:53,
on_bus_acquired()]
14:37:52.917:[3501]:[INFO]: Entering cleanup thread [udisksstate.c:306,
udisks_state_thread_func()]
14:37:52.917:[3501]:[INFO]: Cleanup check start [udisksstate.c:419,
udisks_state_check_in_thread()]
14:37:52.917:[3501]:[INFO]: Cleanup check end [udisksstate.c:457,
udisks_state_check_in_thread()]
14:37:52.918:[3496]:[NOTICE]: Acquired the name org.freedesktop.UDisks2 on the
system message bus [main.c:77, on_name_acquired()]
14:37:53.033:[3498]:[INFO]: Housekeeping complete [udiskslinuxprovider.c:973,
housekeeping_thread_func()]


14:38:23.816:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:38:25.103:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:38:25.104:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:38:25.105:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:38:25.824:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:0/block/sdb
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:38:25.826:[3701]:[INFO]: Refreshing SMART data on
/org/freedesktop/UDisks2/drives/WDC_WD30EZRX_00MMMB0_WD_WCAWZ1777494
(nowakeup=0) [udiskslinuxdriveobject.c:925,
udisks_linux_drive_object_housekeeping()]
14:38:25.836:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:1/block/sdc
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:38:25.990:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:0/block/sdb/sdb1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:38:26.000:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:1/block/sdc/sdc1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]


14:39:03.577:[3758]:[DEBUG]: Device /dev/sg1 (for entry /dev/sg1) is not a
block device [udiskslinuxfilesystem.c:1076, is_in_fstab()]
14:39:04.187:[3758]:[NOTICE]: Mounted /dev/sdc1 at /media/gianogli/023aabac-
611d-489f-9c48-705f8504c6a9 on behalf of uid 1000
[udiskslinuxfilesystem.c:1507, handle_mount()]
14:39:05.132:[3758]:[DEBUG]: Device /dev/sg1 (for entry /dev/sg1) is not a
block device [udiskslinuxfilesystem.c:1076, is_in_fstab()]
14:39:05.765:[3758]:[NOTICE]: Mounted /dev/sdb1 at
/media/gianogli/2a16c440-4b33-4ffb-aa83-07f4306c42ad on behalf of uid 1000
[udiskslinuxfilesystem.c:1507, handle_mount()]


14:47:53.632:[4012]:[INFO]: Housekeeping initiated (601 seconds since last
housekeeping) [udiskslinuxprovider.c:969, housekeeping_thread_func()]
14:47:53.632:[4012]:[INFO]: Refreshing SMART data on
/org/freedesktop/UDisks2/drives/TS512GSSD370_B807930363 (nowakeup=1)
[udiskslinuxdriveobject.c:925, udisks_linux_drive_object_housekeeping()]
14:47:53.765:[4012]:[INFO]: Refreshing SMART data on
/org/freedesktop/UDisks2/drives/WDC_WD30EZRX_00MMMB0_WD_WCAWZ1777494
(nowakeup=1) [udiskslinuxdriveobject.c:925,
udisks_linux_drive_object_housekeeping()]
14:48:01.832:[4012]:[WARNING]: Error performing housekeeping for drive
/org/freedesktop/UDisks2/drives/WDC_WD30EZRX_00MMMB0_WD_WCAWZ1777494: Error
updating SMART data: sk_disk_check_sleep_mode: Operation not supported (udisks-
error-quark, 0) [udiskslinuxprovider.c:941, housekeeping_all_drives()]
14:48:01.832:[4012]:[INFO]: Housekeeping complete [udiskslinuxprovider.c:973,
housekeeping_thread_func()]
14:48:01.836:[3496]:[DEBUG]: uevent remove
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:0/block/sdb/sdb1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:01.837:[3501]:[INFO]: Cleanup check start [udisksstate.c:419,
udisks_state_check_in_thread()]
14:48:01.837:[3501]:[NOTICE]: Cleaning up mount point /media/gianogli/023aabac-
611d-489f-9c48-705f8504c6a9 (device 8:33 no longer exist) [udisksstate.c:683,
udisks_state_check_mounted_fs_entry()]
14:48:01.844:[3496]:[DEBUG]: uevent remove
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:0/block/sdb
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:01.849:[3496]:[DEBUG]: uevent remove
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:01.853:[3496]:[DEBUG]: uevent remove
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:1/block/sdc/sdc1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:01.853:[3496]:[DEBUG]: uevent remove
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:1/block/sdc
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:01.854:[3496]:[DEBUG]: uevent remove
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0/7:0:0:1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:01.854:[3496]:[DEBUG]: uevent remove
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7/target7:0:0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:01.854:[3496]:[DEBUG]: uevent remove
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host7
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:01.872:[3501]:[NOTICE]: Cleaning up mount point
/media/gianogli/2a16c440-4b33-4ffb-aa83-07f4306c42ad (device 8:17 no longer
exist) [udisksstate.c:683, udisks_state_check_mounted_fs_entry()]
14:48:01.911:[3501]:[INFO]: Cleanup check end [udisksstate.c:457,
udisks_state_check_in_thread()]
14:48:01.911:[3501]:[INFO]: Cleanup check start [udisksstate.c:419,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check end [udisksstate.c:457,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check start [udisksstate.c:419,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check end [udisksstate.c:457,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check start [udisksstate.c:419,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check end [udisksstate.c:457,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check start [udisksstate.c:419,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check end [udisksstate.c:457,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check start [udisksstate.c:419,
udisks_state_check_in_thread()]
14:48:01.912:[3501]:[INFO]: Cleanup check end [udisksstate.c:457,
udisks_state_check_in_thread()]
14:48:04.607:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host8
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:05.888:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host8/target8:0:0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:05.894:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host8/target8:0:0/8:0:0:0
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:05.895:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host8/target8:0:0/8:0:0:1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:06.221:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host8/target8:0:0/8:0:0:0/block/sdb
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:06.222:[4012]:[INFO]: Refreshing SMART data on
/org/freedesktop/UDisks2/drives/WDC_WD30EZRX_00MMMB0_WD_WCAWZ1777494
(nowakeup=0) [udiskslinuxdriveobject.c:925,
udisks_linux_drive_object_housekeeping()]
14:48:06.232:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host8/target8:0:0/8:0:0:1/block/sdc
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:06.369:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host8/target8:0:0/8:0:0:0/block/sdb/sdb1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
14:48:06.402:[3496]:[DEBUG]: uevent add
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1:1.0/host8/target8:0:0/8:0:0:1/block/sdc/sdc1
[udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
****************************

The reset of the USB connection, when some portitions are mounted, is a serious
issue: it could lead to data loss!

Do you need other information/logs to discover the cause of this issue?

Thanks,

   GiAn



-- System Information:
Debian Release: 8.0
  APT prefers testing
  APT policy: (990, 'testing')
Architecture: i386 (i686)

Kernel: Linux 3.16.0-4-686-pae (SMP w/4 CPU cores)
Locale: LANG=it_IT at euro, LC_CTYPE=it_IT at euro (charmap=ISO-8859-15)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages libatasmart4 depends on:
ii  libc6              2.19-15
ii  libudev1           215-12
ii  multiarch-support  2.19-15

libatasmart4 recommends no packages.

libatasmart4 suggests no packages.

-- no debconf information

More information about the Pkg-utopia-maintainers mailing list