#779931 "sk_disk_check_sleep_mode: Operation not supported" for USB3 HDD docking based on JMicron 152d:0551

Package:
libatasmart4
Source:
libatasmart
Description:
ATA S.M.A.R.T. reading and parsing library
Submitter:
Gianluca Oglietti
Date:
2015-06-05 17:39:07 UTC
Severity:
important
#779931#5
Date:
2015-03-06 14:30:18 UTC
From:
To:
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
#779931#10
Date:
2015-03-06 15:06:24 UTC
From:
To:
Am 06.03.2015 um 15:30 schrieb Gianluca Oglietti:

If checking the SMART state of the sleeping disk resets the USB
connection, then this sounds like a kernel bug.
#779931#15
Date:
2015-03-09 14:07:01 UTC
From:
To:
I've always seen the reset of the USB connection while the HDs were
mounted.

I've also tried to install the new versions of udisks2 (2.1.4-1 and
2.1.5-1) because I've seen a workaround to this issue (IS: #1281588) but
using these versions I noticed other serious issues (for ex. I can't
mount a partition when the HDs are gone to sleep mode).

If the problem is the kernel, can you suggest me a way to debug this
issue?

Thanks...

    Gianluca



Connetti gratis il mondo con la nuova indoona:  hai la chat, le
chiamate, le video chiamate e persino le chiamate di gruppo.
E chiami gratis anche i numeri fissi e mobili nel mondo!
Scarica subito l’app Vai su https://www.indoona.com/
#779931#20
Date:
2015-03-29 03:31:02 UTC
From:
To:
control: severity -1 important

Try starting a discussion on the linux kernel mailing list (lkml.org)
or bugzilla (bugzilla.kernel.org).

Best wishes,
Mike
#779931#25
Date:
2015-03-29 03:31:02 UTC
From:
To:
control: severity -1 important

Try starting a discussion on the linux kernel mailing list (lkml.org)
or bugzilla (bugzilla.kernel.org).

Best wishes,
Mike
#779931#30
Date:
2015-03-29 03:40:47 UTC
From:
To:
Am 29.03.2015 um 05:31 schrieb Michael Gilbert:

Another alternative might be a buggy USB controller in the docking
station. It's hard to tell.
#779931#33
Date:
2015-03-29 03:40:47 UTC
From:
To:
Am 29.03.2015 um 05:31 schrieb Michael Gilbert:

Another alternative might be a buggy USB controller in the docking
station. It's hard to tell.
#779931#38
Date:
2015-06-05 17:27:08 UTC
From:
To:
this issue?

JMicron USB controllers are in fact notoriously buggy.

I have the same problem with id 152d:0539, and i had to blacklist it in
libatasmart/atasmart.c disk_find_type().

 / C