[6.8.3] HDDs are spinning, but WebGUI status shows spindown

Added more info about my second server which now shows the same problem.

Ok, monitored even longer and now a check for sde appeared:

16:34:02 openat(AT_FDCWD, "/dev/sde", O_RDONLY|O_NONBLOCK) = 3
16:34:02 write(1, "Device is in STANDBY mode, exit("..., 35) = 35

 

sdc is still missing, but sdl appeared multiple times with a pipe error:

strace: Process 27020 attached
strace: [ Process PID=27020 runs in x32 mode. ]
strace: [ Process PID=27020 runs in 64 bit mode. ]
17:15:01 read(3, "\"\", \"\"\n  },\n  { \"Seagate Barracu"..., 4096) = 4096
17:15:01 read(3, "T3000DM001\",\n    \"\", \"\",\n    \"-v"..., 4096) = 4096
17:15:01 read(3, "Constellation ES (SATA 6Gb/s)\", "..., 4096) = 4096
17:15:01 read(3, "  \"\", \"\", \"\"\n  },\n  { \"Seagate M"..., 4096) = 4096
17:15:01 read(3, "\"-v 187,raw48,Uncorrectable_ECC_"..., 4096) = 4096
17:15:01 read(3, "bly explained by the WD firmware"..., 4096) = 4096
17:15:01 read(3, "viar Green\", // tested with WDC "..., 4096) = 4096
17:15:01 read(3, "/82.00A82,\n      // WDC WD80EFAX"..., 4096) = 4096
17:15:01 read(3, "SB ID entries\n  ////////////////"..., 4096) = 4096
17:15:01 read(3, " \"USB: Samsung; \",\n    \"0x04e8:0"..., 4096) = 4096
17:15:01 read(3, "at\"\n  },\n  // Micron\n  { \"USB: M"..., 4096) = 4096
17:15:01 read(3, "  { \"USB: Maxtor OneTouch 4; \",\n"..., 4096) = 4096
17:15:01 read(3, "    \"\", // 0x0114\n    \"\", // 0x0"..., 4096) = 4096
17:15:01 read(3, " usbjmicron\"\n  },\n  { \"USB: Verb"..., 4096) = 3817
17:15:01 read(3, "", 4096)              = 0
17:15:01 close(3)                       = 0
17:15:01 lstat("/dev/sdl", {st_mode=S_IFBLK|0660, st_rdev=makedev(8, 176), ...}) = 0
17:15:01 stat("/sys/devices", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 stat("/sys/block/sdl/device/..", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 access("/sys/block/sdl/device/../idVendor", F_OK) = -1 ENOENT (No such file or directory)
17:15:01 stat("/sys/block/sdl/device/../..", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 access("/sys/block/sdl/device/../../idVendor", F_OK) = -1 ENOENT (No such file or directory)
17:15:01 stat("/sys/block/sdl/device/../../..", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 access("/sys/block/sdl/device/../../../idVendor", F_OK) = -1 ENOENT (No such file or directory)
17:15:01 stat("/sys/block/sdl/device/../../../..", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 access("/sys/block/sdl/device/../../../../idVendor", F_OK) = -1 ENOENT (No such file or directory)
17:15:01 stat("/sys/block/sdl/device/../../../../..", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 access("/sys/block/sdl/device/../../../../../idVendor", F_OK) = -1 ENOENT (No such file or directory)
17:15:01 stat("/sys/block/sdl/device/../../../../../..", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 access("/sys/block/sdl/device/../../../../../../idVendor", F_OK) = -1 ENOENT (No such file or directory)
17:15:01 stat("/sys/block/sdl/device/../../../../../../..", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
17:15:01 lstat("/sys/block", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/block/sdl", {st_mode=S_IFLNK|0777, st_size=0, ...}) = 0
17:15:01 readlink("/sys/block/sdl", "../devices/pci0000:00/0000:00:1d"..., 4095) = 92
17:15:01 lstat("/sys/devices", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13/host13", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13/host13/target13:0:0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13/host13/target13:0:0/13:0:0:0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13/host13/target13:0:0/13:0:0:0/block", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13/host13/target13:0:0/13:0:0:0/block/sdl", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13/host13/target13:0:0/13:0:0:0/block/sdl/device", {st_mode=S_IFLNK|0777, st_size=0, ...}) = 0
17:15:01 readlink("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13/host13/target13:0:0/13:0:0:0/block/sdl/device", "../../../13:0:0:0", 4095) = 17
17:15:01 lstat("/sys/devices/pci0000:00/0000:00:1d.0/0000:05:00.0/ata13/host13/target13:0:0/13:0:0:0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
17:15:01 openat(AT_FDCWD, "/sys/class/scsi_host/host13/proc_name", O_RDONLY) = 3
17:15:01 read(3, "ahci\n", 31)          = 5
17:15:01 close(3)                       = 0
17:15:01 openat(AT_FDCWD, "/dev/sdl", O_RDONLY|O_NONBLOCK) = 3
17:15:01 fcntl(3, F_SETFD, FD_CLOEXEC)  = 0
17:15:01 ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[6]=[12, 00, 00, 00, 24, 00], mx_sb_len=32, iovec_count=0, dxfer_len=36, timeout=60000, flags=0, data[36]=[00, 00, 05, 02, 5b, 00, 00, 02, 41, 54, 41, 20, 20, 20, 20, 20, 48, 47, 53, 54, 20, 48, 55, 48, 37, 32, 31, 32, 31, 32, 41, 4c, ...], status=00, masked_status=00, sb[0]=[], host_status=0, driver_status=0, resid=0, duration=0, info=0}) = 0
17:15:01 ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[16]=[85, 08, 0e, 00, 00, 00, 01, 00, 00, 00, 00, 00, 00, 00, ec, 00], mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=60000, flags=0, data[512]=[5a, 04, ff, 3f, 37, c8, 10, 00, 00, 00, 00, 00, 3f, 00, 00, 00, 00, 00, 00, 00, 43, 38, 55, 48, 48, 44, 45, 45, 20, 20, 20, 20, ...], status=00, masked_status=00, sb[0]=[], host_status=0, driver_status=0, resid=0, duration=0, info=0}) = 0
17:15:01 ioctl(3, SG_IO, {'S', SG_DXFER_NONE, cmd[16]=[85, 06, 2c, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, e5, 00], mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=60000, flags=0, status=02, masked_status=01, sb[22]=[72, 01, 00, 1d, 00, 00, 00, 0e, 09, 0c, 00, 00, 00, 81, 00, 00, 00, 00, 00, 00, 00, 50], host_status=0, driver_status=0x8, resid=0, duration=0, info=0x1}) = 0
17:15:01 ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[16]=[85, 08, 0e, 00, 00, 00, 01, 00, 00, 00, 00, 00, 00, 00, ec, 00], mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=60000, flags=0, data[512]=[5a, 04, ff, 3f, 37, c8, 10, 00, 00, 00, 00, 00, 3f, 00, 00, 00, 00, 00, 00, 00, 43, 38, 55, 48, 48, 44, 45, 45, 20, 20, 20, 20, ...], status=00, masked_status=00, sb[0]=[], host_status=0, driver_status=0, resid=0, duration=0, info=0}) = 0
17:15:01 brk(0x584000)                  = 0x584000
17:15:01 brk(0x5a6000)                  = 0x5a6000
17:15:01 brk(0x5c7000)                  = 0x5c7000
17:15:01 ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[16]=[85, 08, 0e, 00, d0, 00, 01, 00, 00, 00, 4f, 00, c2, 00, b0, 00], mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=60000, flags=0, data[512]=[10, 00, 01, 0b, 00, 64, 64, 00, 00, 00, 00, 00, 00, 00, 02, 05, 00, 84, 84, 60, 00, 00, 00, 00, 00, 00, 03, 07, 00, 9f, 9f, 9c, ...], status=00, masked_status=00, sb[0]=[], host_status=0, driver_status=0, resid=0, duration=5, info=0}) = 0
17:15:01 ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[16]=[85, 08, 0e, 00, d1, 00, 01, 00, 01, 00, 4f, 00, c2, 00, b0, 00], mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=60000, flags=0, data[512]=[10, 00, 01, 10, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 02, 36, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 03, 18, 00, 00, 00, 00, ...], status=00, masked_status=00, sb[0]=[], host_status=0, driver_status=0, resid=0, duration=3, info=0}) = 0
17:15:01 write(1, "=== START OF READ SMART DATA SEC"..., 41) = 41
17:15:01 ioctl(3, SG_IO, {'S', SG_DXFER_NONE, cmd[16]=[85, 06, 2c, 00, da, 00, 00, 00, 00, 00, 4f, 00, c2, 00, b0, 00], mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=60000, flags=0, status=02, masked_status=01, sb[22]=[72, 01, 00, 1d, 00, 00, 00, 0e, 09, 0c, 00, 00, 00, 00, 00, 00, 00, 4f, 00, c2, 00, 50], host_status=0, driver_status=0x8, resid=0, duration=1, info=0x1}) = 0
17:15:01 write(1, "SMART overall-health self-assess"..., 57) = 57
17:15:01 write(1, "\n", 1)              = -1 EPIPE (Broken pipe)
17:15:01 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=27020, si_uid=0} ---
17:15:01 close(3)                       = 0
17:15:01 exit_group(0)                  = ?
17:15:01 +++ exited with 0 +++

 

Now I started a movie which is on sdl and the icon became directly active in the WebGUI:

 

 

So its only something related the standby status which fails.

 

One bug location found:

13:57:01 lstat("/dev/", {st_mode=S_IFDIR|0755, st_size=3920, ...}) = 0
13:57:01 write(1, "/dev/: Unable to detect device t"..., 36) = 36
13:57:01 write(1, "Please specify device type with "..., 47) = 47
13:57:01 write(1, "\nUse smartctl -h to get a usage "..., 41) = 41

 

This is caused in /usr/local/emhttp/plugins/dynamix/scripts/monitor in this line:

if (!file_exists($file) || (time()-filemtime($file)>$var['poll_attributes'])) exec("smartctl -n standby -H $type ".escapeshellarg("/dev/$port")."|grep -Pom1 '^SMART.*: \K[A-Z]+'|tr -d '\n' >".escapeshellarg($file));

 

It happens because $port is sometimes empty:

/usr/local/emhttp/plugins/dynamix/scripts/monitor170smartctl -n standby -H  '/dev/sdh'|grep -Pom1 '^SMART.*: \K[A-Z]+'|tr -d '
' >'/var/local/emhttp/smart/disk8.ssa'
/usr/local/emhttp/plugins/dynamix/scripts/monitor170smartctl -n standby -H  '/dev/sdd'|grep -Pom1 '^SMART.*: \K[A-Z]+'|tr -d '
' >'/var/local/emhttp/smart/disk9.ssa'
/usr/local/emhttp/plugins/dynamix/scripts/monitor170smartctl -n standby -H  '/dev/'|grep -Pom1 '^SMART.*: \K[A-Z]+'|tr -d '
' >'/var/local/emhttp/smart/parity2.ssa'
/usr/local/emhttp/plugins/dynamix/scripts/monitor170smartctl -n standby -H  '/dev/sdj'|grep -Pom1 '^SMART.*: \K[A-Z]+'|tr -d '
' >'/var/local/emhttp/smart/cache.ssa'
/usr/local/emhttp/plugins/dynamix/scripts/monitor170smartctl -n standby -H  '/dev/sdg'|grep -Pom1 '^SMART.*: \K[A-Z]+'|tr -d '
' >'/var/local/emhttp/smart/parity.ssa'

 

I think its because of "parity2". I don't have a second parity. So this check should not happen.

On 1/26/2021 at 11:45 AM, mgutt said:

It happens because $port is sometimes empty:

 

Now found the reason why $port is sometimes empty:

$disks = parse_ini_file("/var/local/emhttp/disks.ini",true);
...
foreach ($disks as $disk) {
...
  check_smart($name,port_name($disk['smDevice'] ?? $disk['device']),$text,$info);

 

Its because "/var/local/emhttp/disks.ini" contains data for parity2 which is not used:

["parity2"]
idx="29"
name="parity2"
device=""
id=""
size="0"
status="DISK_NP_DSBL"
rotational=""
format="-"
temp="*"
numReads="0"
numWrites="0"
numErrors="0"
type="Parity"
color="grey-off"
fsStatus="-"
spindownDelay="-1"
spinupGroup=""
deviceSb=""
idSb=""
sizeSb="0"

As we can see there is no "smDevice" key and "device" is empty, which causes this error.

 

Bug fix

 

search in "/usr/local/emhttp/plugins/dynamix/scripts/monitor" for:

if ($name=='flash' || substr($disk['status'],-3)=='_NP') continue;

 

replace against:

if ($name=='flash' || strpos($disk['status'],'_NP')) continue;

 

This is because parity2 has the status "DISK_NP_DSBL" and all other empty disk slots have "DISK_NP".

 

Now I try to find the other bugs

Quote

Broken Pipe errors (happen often)

 

Ok, I found the reason in "/usr/local/emhttp/plugins/dynamix/scripts/monitor" for this, too. It's not really a bug. It happens because the output of smartctl is piped to grep and grep stops the pipe because "SMART" was found:

if (!file_exists($file) || (time()-filemtime($file)>$var['poll_attributes'])) exec("smartctl -n standby -H $type ".escapeshellarg("/dev/$port")."|grep -Pom1 '^SMART.*: \K[A-Z]+'|tr -d '\n' >".escapeshellarg($file));

 

Two examples, the second causes the broken pipe error:

root@Thoth:~# smartctl -n standby -H  '/dev/sdc'|grep -Pom1 '^SMART.*: \K[A-Z]+'

root@Thoth:~# smartctl -n standby -H  '/dev/sdc'
smartctl 7.1 2019-12-30 r5022 [x86_64-linux-4.19.107-Unraid] (local build)
Copyright (C) 2002-19, Bruce Allen, Christian Franke, www.smartmontools.org

Device is in STANDBY mode, exit(2)

 

root@Thoth:~# smartctl -n standby -H  '/dev/sdb'|grep -Pom1 '^SMART.*: \K[A-Z]+'
PASSED
root@Thoth:~# smartctl -n standby -H  '/dev/sdb'
smartctl 7.1 2019-12-30 r5022 [x86_64-linux-4.19.107-Unraid] (local build)
Copyright (C) 2002-19, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

 

It could be fixed by passing the result to PHP first and let PHP check for "SMART", but it's ok to leave it as it is.

 

Now I need to find the major bug: Why are some disks not monitored at all.

Interesting, I have a similar problem, automatic spindown worked for about two weeks then just stopped. New Install, new Hardware, all sorts of trying things out in the beginning (first build). I was running 6.9.rc2 at the time and thought it might get fixed with the stable release, which it didn't. Also tried all the file activity plugins, running without dockers and vms, nothing. Pretty sure I also tried the 'HardwareProfile' page in Tools at some point.

 

Unneccesarry spin ups were sort of fixed with 'smartcl -n standby /dev/sdX' but still auto spindown doesn't work at all.

I also run only one parity drive and got the irelevant second entry in '/var/local/emhttp/disks.ini'. I also get the pipe errors etc. same as you.

 

I added the fix in '/usr/local/emhttp/plugins/dynamix/scripts/monitor' but I suppose that is primarily to fix your original issue, which I didn't notice.

 

I'm glad someone else with more knowledge got the problem as well, I got the feeling there is more people (some bug reports indicting similiar problems) and believe spin down not working should be treated as a little more than a minor bug. Looking forward to your diagnosis!

 

 

Nevermind, I just uninstalled 'Dynamix Auto Fan Control' and my problems went away, everything is spinning down as set up, now all that remains is to test wether the plugin works with spinning drives excluded.

 

I have a similar problem too, in version 6.9.0 RC2 and above.

I worte things about that in another threat (I think it was in wrong section).

 

Quote

I got the same error. I noticed this error with 6.9.0 RC2. Before that Version everything was working like expected.

In the Array Monitor the disks were shown as spin down, but I can hear the disks running.

 

Edit:

My problem is mayby a bit different as the described one above.

I'm using a small server with an external 4-bay USB 3.0 storage device from Fantec. It is connected by USB 3.0 and I have 4 WD Red in that case.

Additionally 2 WD Red + 1 SSD in the server case connected via S-ATA.

 

Since UNRaid 6.9.0 RC2 the disks in the external case were not detected corretly. If the drives spin-up because of an access, UNRaid doesn't notice that. I got no SMART values. And because of that they won't spin-down correctly, because UNRaid doesn't know that they're up. But if I spin them up manually everything is working fine. They spin down after 30 min and I get the values.

 

Every drive on the screenshot should be green, because they're running.

 

I hope, that someony has an idea what I can do.

 

Quote

I'm back on 6.9.0 RC1, the last working build for me.

 

I found a small difference in the log between 6.9.0 RC1 and 6.9.0. If I access one of these external drives than appears the following message in the log file:

"Mar 3 08:15:29 Media-Server emhttpd: read SMART /dev/sdc"

That doesn't happen in the release version and that's the reason why UNRaid isn't able to spin-down the drives, because UNRaid doesn't notice that the access happens and the drive spun-up.

 

I attached a new diagnostic file from RC1.

 

I've attached the diagnostics from 6.9.0 and 6.9.0 RC1.

6.9.0RC1_media-server-diagnostics-20210303-0816.zip 6.9.0_media-server-diagnostics-20210302-1301.zip

12 minutes ago, Redskyer said:

I have a similar problem too, in version 6.9.0 RC2 and above.

 

Your problem is different and can't be solved as its a hardware limitation:

https://forums.unraid.net/bug-reports/stable-releases/683-usb-hdds-randomly-spin-up-but-status-stays-unchanged-r1091/

 

 

2 minutes ago, mgutt said:

Your problem is different and can't be solved as its a hardware limitation:

https://forums.unraid.net/bug-reports/stable-releases/683-usb-hdds-randomly-spin-up-but-status-stays-unchanged-r1091/

 

 

Hmm okay, but I think its not the same as in your threat, because I had no problems with the beta releases of 6.9.0 and RC1, the problem just appears at RC2. And the disks don't spin up randomly, they spin up, if an access happens, but UNRaid doesn't notice that.

 

Should I open a new threat?