ReadyNAS OS Vi.j.k - Discs don't spindown - still

[Michael_Oz]

I decided to use generics for the version in the title, so I can resuse this for the next release...

Right now it applies to 6.10.1 which I upgraded to yesterday.

tl;dr disk spindown is still broken.

The last time (6.9.5), I said:

>This is turning into a ritual, as for the last few releases I again check whether disc spindown is fixed.

>Last was for 6.9.3 here.

>My last post there was "So has this been recognised as a bug?" which remains unanswered by Netgear, I think it is obvious.

>As per the flow of the previous post, I cut to the chase.

This time I just did the minimal test, enabled spindown to 10 minutes, unplugged the network for a while, downloaded logs.

Same preconditions as before (except no htop).

Jun 03 10:02:46 ME-NAS-316A noflushd[26631]: Spinning down disk 2 (/dev/sdb).
Jun 03 10:02:53 ME-NAS-316A noflushd[26631]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Jun 03 10:09:30 ME-NAS-316A noflushd[26631]: Spinning down disk 1 (/dev/sda).
Jun 03 10:09:37 ME-NAS-316A noflushd[26631]: Spinning up disk 1 (/dev/sda) after 0:00:05.
Jun 03 10:11:44 ME-NAS-316A noflushd[26631]: Spinning down disk 3 (/dev/sdc).
Jun 03 10:11:47 ME-NAS-316A noflushd[26631]: Spinning down disk 4 (/dev/sdd).
Jun 03 10:11:49 ME-NAS-316A noflushd[26631]: Spinning down disk 5 (/dev/sde).
Jun 03 10:11:51 ME-NAS-316A noflushd[26631]: Spinning down disk 6 (/dev/sdf).
Jun 03 10:11:59 ME-NAS-316A noflushd[26631]: Spinning up disk 3 (/dev/sdc) after 0:00:12.
Jun 03 10:11:59 ME-NAS-316A noflushd[26631]: Spinning up disk 4 (/dev/sdd) after 0:00:10.
Jun 03 10:11:59 ME-NAS-316A noflushd[26631]: Spinning up disk 5 (/dev/sde) after 0:00:08.
Jun 03 10:11:59 ME-NAS-316A noflushd[26631]: Spinning up disk 6 (/dev/sdf) after 0:00:05.
Jun 03 10:12:58 ME-NAS-316A noflushd[26631]: Spinning down disk 2 (/dev/sdb).
Jun 03 10:13:06 ME-NAS-316A noflushd[26631]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Jun 03 10:19:42 ME-NAS-316A noflushd[26631]: Spinning down disk 1 (/dev/sda).
Jun 03 10:19:50 ME-NAS-316A noflushd[26631]: Spinning up disk 1 (/dev/sda) after 0:00:05.
Jun 03 10:22:11 ME-NAS-316A noflushd[26631]: Spinning down disk 3 (/dev/sdc).
Jun 03 10:22:14 ME-NAS-316A noflushd[26631]: Spinning down disk 4 (/dev/sdd).
Jun 03 10:22:16 ME-NAS-316A noflushd[26631]: Spinning down disk 5 (/dev/sde).
Jun 03 10:22:19 ME-NAS-316A noflushd[26631]: Spinning down disk 6 (/dev/sdf).
Jun 03 10:22:26 ME-NAS-316A noflushd[26631]: Spinning up disk 3 (/dev/sdc) after 0:00:12.
Jun 03 10:22:26 ME-NAS-316A noflushd[26631]: Spinning up disk 4 (/dev/sdd) after 0:00:10.
Jun 03 10:22:26 ME-NAS-316A noflushd[26631]: Spinning up disk 5 (/dev/sde) after 0:00:07.
Jun 03 10:22:26 ME-NAS-316A noflushd[26631]: Spinning up disk 6 (/dev/sdf) after 0:00:05.
Jun 03 10:23:10 ME-NAS-316A noflushd[26631]: Spinning down disk 2 (/dev/sdb).
Jun 03 10:23:18 ME-NAS-316A noflushd[26631]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Jun 03 10:29:54 ME-NAS-316A noflushd[26631]: Spinning down disk 1 (/dev/sda).
Jun 03 10:30:02 ME-NAS-316A noflushd[26631]: Spinning up disk 1 (/dev/sda) after 0:00:05.
Jun 03 10:32:38 ME-NAS-316A noflushd[26631]: Spinning down disk 3 (/dev/sdc).
Jun 03 10:32:41 ME-NAS-316A noflushd[26631]: Spinning down disk 4 (/dev/sdd).
Jun 03 10:32:43 ME-NAS-316A noflushd[26631]: Spinning down disk 5 (/dev/sde).
Jun 03 10:32:46 ME-NAS-316A noflushd[26631]: Spinning down disk 6 (/dev/sdf).
Jun 03 10:32:53 ME-NAS-316A noflushd[26631]: Spinning up disk 3 (/dev/sdc) after 0:00:12.
Jun 03 10:32:53 ME-NAS-316A noflushd[26631]: Spinning up disk 4 (/dev/sdd) after 0:00:10.
Jun 03 10:32:53 ME-NAS-316A noflushd[26631]: Spinning up disk 5 (/dev/sde) after 0:00:07.
Jun 03 10:32:53 ME-NAS-316A noflushd[26631]: Spinning up disk 6 (/dev/sdf) after 0:00:05.
Jun 03 10:33:22 ME-NAS-316A noflushd[26631]: Spinning down disk 2 (/dev/sdb).
Jun 03 10:33:30 ME-NAS-316A noflushd[26631]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Jun 03 10:40:06 ME-NAS-316A noflushd[26631]: Spinning down disk 1 (/dev/sda).
Jun 03 10:40:14 ME-NAS-316A noflushd[26631]: Spinning up disk 1 (/dev/sda) after 0:00:05.
Jun 03 10:43:05 ME-NAS-316A noflushd[26631]: Spinning down disk 3 (/dev/sdc).
Jun 03 10:43:08 ME-NAS-316A noflushd[26631]: Spinning down disk 4 (/dev/sdd).
Jun 03 10:43:10 ME-NAS-316A noflushd[26631]: Spinning down disk 5 (/dev/sde).
Jun 03 10:43:13 ME-NAS-316A noflushd[26631]: Spinning down disk 6 (/dev/sdf).
Jun 03 10:43:23 ME-NAS-316A noflushd[26631]: Spinning up disk 3 (/dev/sdc) after 0:00:15.
Jun 03 10:43:23 ME-NAS-316A noflushd[26631]: Spinning up disk 4 (/dev/sdd) after 0:00:13.
Jun 03 10:43:23 ME-NAS-316A noflushd[26631]: Spinning up disk 5 (/dev/sde) after 0:00:10.
Jun 03 10:43:23 ME-NAS-316A noflushd[26631]: Spinning up disk 6 (/dev/sdf) after 0:00:08.

This is beyond a joke.

Spindown is broken, or rather it has premature spinup.

It has been broken for a very long time.

You are falsely advertising a feature.

Let me know if anyone wants noflushd -b or block_dump info.

@Retired_Member

[schumaku]

And what processes are wetting the inodes on e.g. the md device(s)?

This example is not intended to be a "does not spin-down" example, just to illustrate what you might have done and collected as part of your test, and what I would like to see (taken here from the Kernel log rung buffer):

root@RN628X:~# /bin/echo 1 > /proc/sys/vm/block_dump

root@RN628X:~# dmesg | grep dirt | grep md
[382243.814302] kworker/u16:1(28029): dirtied inode 1 (?) on md127
[382267.797468] systemd-journal(2550): dirtied inode 492340 (system.journal) on md0
[382392.192136] aurndb-write-db(4298): dirtied inode 7428 (audit_log.sq3) on md127
[382392.222247] sshd(28139): dirtied inode 11380 (wtmp) on md0
[382392.222272] sshd(28139): dirtied inode 11377 (lastlog) on md0
[382453.937746] btrfs-transacti(2646): dirtied inode 1 (?) on md127
[382568.295864] systemd-journal(2550): dirtied inode 492340 (system.journal) on md0
[382608.754085] loadavg(5756): dirtied inode 11834 (loadavg.dat) on md0

root@RN628X:~# /bin/echo 0 > /proc/sys/vm/block_dump

Please note that a system disconnected from the network can and will develop activities becaue of the disconnected interfaces, because of the lack of Internet connectivity, ... so I would consider your ritual *****.

[Michael_Oz]

---

@schumaku wrote:

And what processes are wetting the inodes on e.g. the md device(s)?

This example is not intended to be a "does not spin-down" example, just to illustrate what you might have done and collected as part of your test, and what I would like to see (taken here from the Kernel log rung buffer):

root@RN628X:~# /bin/echo 1 > /proc/sys/vm/block_dump

root@RN628X:~# dmesg | grep dirt | grep md
[382243.814302] kworker/u16:1(28029): dirtied inode 1 (?) on md127
[382267.797468] systemd-journal(2550): dirtied inode 492340 (system.journal) on md0
[382392.192136] aurndb-write-db(4298): dirtied inode 7428 (audit_log.sq3) on md127
[382392.222247] sshd(28139): dirtied inode 11380 (wtmp) on md0
[382392.222272] sshd(28139): dirtied inode 11377 (lastlog) on md0
[382453.937746] btrfs-transacti(2646): dirtied inode 1 (?) on md127
[382568.295864] systemd-journal(2550): dirtied inode 492340 (system.journal) on md0
[382608.754085] loadavg(5756): dirtied inode 11834 (loadavg.dat) on md0

root@RN628X:~# /bin/echo 0 > /proc/sys/vm/block_dump

Please note that a system disconnected from the network can and will develop activities becaue of the disconnected interfaces, because of the lack of Internet connectivity, ... so I would consider your ritual *****.

---

I've been dealing with this bug for years. Thank you for the complement ***** to you too.

[schumaku]

While you might be perfectly right withb the problem, your test is potentially wrong. Other NAS vendors start writing error information into logs, try to send error status information, and much more - and this often wetting the storage buffer and makes the HDD spinning again.

Instead of nagging - answer the question.

[Michael_Oz]

My 'ritual' is to try again after each OS release.

Steps involved in the past were based on requests from Netgear.

My system is as vanilla as you can get. Apart from Frontview checking for updates (which is from my PC) it does not talk to the internet.

It does not have scheduled anything that is not vanilla.

Prior to disconnecting the cable, I checked, spinup was premature.

Previously I was challenged that spurious network activity was the cause of the spinups.

I did offer that "Let me know if anyone wants noflushd -b or block_dump info."

However seeing you asked with such a polite post...

Standby...

[Michael_Oz]

spindown = 5 minutes

Jun 03 21:10:28 ME-NAS-316A kernel: loadavg(6021): dirtied inode 1326999 (loadavg.dat) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: rnutil(18463): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: kworker/u8:6(18035): dirtied inode 1 (?) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: kworker/u8:6(18035): dirtied inode 1 (?) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:10:43 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:10:50 ME-NAS-316A kernel: rnutil(18466): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:11:02 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:02 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:02 ME-NAS-316A kernel: kworker/u8:1(17467): dirtied inode 1 (?) on md0
Jun 03 21:11:02 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:02 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: rnutil(18485): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: kworker/u8:0(18273): dirtied inode 1 (?) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: kworker/u8:0(18273): dirtied inode 1 (?) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:11:55 ME-NAS-316A kernel: rnutil(18489): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:12:16 ME-NAS-316A kernel: kworker/u8:0(18273): dirtied inode 1 (?) on md0
Jun 03 21:12:16 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:12:16 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: rnutil(18529): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: kworker/u8:3(17037): dirtied inode 1 (?) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: kworker/u8:6(18035): dirtied inode 1 (?) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:36 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:39 ME-NAS-316A kernel: rnutil(18532): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:13:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:58 ME-NAS-316A kernel: kworker/u8:6(18035): dirtied inode 1 (?) on md0
Jun 03 21:13:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:13:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:15:04 ME-NAS-316A kernel: sysadm(6020): dirtied inode 2096290 (readynasd_2019_06_03_204031.db-journal) on md0
Jun 03 21:15:05 ME-NAS-316A kernel: sysadm(6020): dirtied inode 2096289 (readynasd_2019_06_03_204031.db) on md0
Jun 03 21:15:05 ME-NAS-316A kernel: lz4(18555): dirtied inode 2096291 (readynasd_2019_06_03_204031.db.lz4) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: rnutil(18568): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: kworker/u8:3(17037): dirtied inode 1 (?) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: kworker/u8:0(18273): dirtied inode 1 (?) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:15:58 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:16:06 ME-NAS-316A kernel: rnutil(18572): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:16:17 ME-NAS-316A kernel: kworker/u8:0(18273): dirtied inode 1 (?) on md0
Jun 03 21:16:17 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:16:17 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:07 ME-NAS-316A kernel: rnutil(18593): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:17:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:07 ME-NAS-316A kernel: kworker/u8:6(18035): dirtied inode 1 (?) on md0
Jun 03 21:17:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:08 ME-NAS-316A kernel: kworker/u8:0(18273): dirtied inode 1 (?) on md0
Jun 03 21:17:08 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:08 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:10 ME-NAS-316A kernel: rnutil(18597): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:17:31 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:31 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:31 ME-NAS-316A kernel: kworker/u8:2(18569): dirtied inode 1 (?) on md0
Jun 03 21:17:31 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:17:31 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: rnutil(18638): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: kworker/u8:0(18273): dirtied inode 1 (?) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: kworker/u8:1(17467): dirtied inode 1 (?) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:18:52 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:18:54 ME-NAS-316A kernel: rnutil(18641): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:19:13 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:19:13 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:19:13 ME-NAS-316A kernel: kworker/u8:6(18035): dirtied inode 1 (?) on md0
Jun 03 21:19:13 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:19:13 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:13 ME-NAS-316A kernel: rnutil(18681): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:21:14 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:14 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:14 ME-NAS-316A kernel: kworker/u8:1(17467): dirtied inode 1 (?) on md0
Jun 03 21:21:14 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:14 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:14 ME-NAS-316A kernel: kworker/u8:6(18035): dirtied inode 1 (?) on md0
Jun 03 21:21:14 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:14 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:21 ME-NAS-316A kernel: rnutil(18685): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:21:33 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:33 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:33 ME-NAS-316A kernel: kworker/u8:3(17037): dirtied inode 1 (?) on md0
Jun 03 21:21:33 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:21:33 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:23 ME-NAS-316A kernel: rnutil(18703): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:22:23 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:23 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:23 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:23 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:23 ME-NAS-316A kernel: kworker/u8:3(17037): dirtied inode 1 (?) on md0
Jun 03 21:22:23 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:23 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:25 ME-NAS-316A kernel: rnutil(18706): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:22:47 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:47 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:47 ME-NAS-316A kernel: kworker/u8:0(18273): dirtied inode 1 (?) on md0
Jun 03 21:22:47 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:22:47 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: rnutil(18739): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: kworker/u8:1(17467): dirtied inode 1 (?) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096283 (system.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096294 (system.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096294 (system.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2084103 (system@96c8dbaf1efd49efb0f806d41449d8fb-00000000000a97b9-00058a43375001c1.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2084103 (system@96c8dbaf1efd49efb0f806d41449d8fb-00000000000a97b9-00058a43375001c1.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: kworker/u8:1(17467): dirtied inode 1 (?) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096294 (system.journal) on md0
Jun 03 21:24:07 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096294 (system.journal) on md0
Jun 03 21:24:15 ME-NAS-316A kernel: rnutil(18744): dirtied inode 9380 (event.sq3) on md0
Jun 03 21:24:21 ME-NAS-316A kernel: kworker/u8:1(17467): dirtied inode 1 (?) on md0
Jun 03 21:24:21 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096294 (system.journal) on md0
Jun 03 21:24:21 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096294 (system.journal) on md0
Jun 03 21:25:28 ME-NAS-316A kernel: loadavg(6021): dirtied inode 1326999 (loadavg.dat) on md0

[Michael_Oz]

Jun 03 21:08:31 ME-NAS-316A noflushd[17518]: Spinning up disk 5 (/dev/sde) after 0:00:05.
Jun 03 21:10:43 ME-NAS-316A noflushd[17518]: Spinning down disk 4 (/dev/sdd).
Jun 03 21:10:50 ME-NAS-316A noflushd[17518]: Spinning up disk 4 (/dev/sdd) after 0:00:05.
Jun 03 21:11:52 ME-NAS-316A noflushd[17518]: Spinning down disk 1 (/dev/sda).
Jun 03 21:11:55 ME-NAS-316A noflushd[17518]: Spinning down disk 2 (/dev/sdb).
Jun 03 21:11:57 ME-NAS-316A noflushd[17518]: Spinning down disk 6 (/dev/sdf).
Jun 03 21:12:04 ME-NAS-316A noflushd[17518]: Spinning up disk 1 (/dev/sda) after 0:00:09.
Jun 03 21:12:04 ME-NAS-316A noflushd[17518]: Spinning up disk 2 (/dev/sdb) after 0:00:07.
Jun 03 21:12:04 ME-NAS-316A noflushd[17518]: Spinning up disk 6 (/dev/sdf) after 0:00:05.
Jun 03 21:13:36 ME-NAS-316A noflushd[17518]: Spinning down disk 3 (/dev/sdc).
Jun 03 21:13:39 ME-NAS-316A noflushd[17518]: Spinning down disk 5 (/dev/sde).
Jun 03 21:13:46 ME-NAS-316A noflushd[17518]: Spinning up disk 3 (/dev/sdc) after 0:00:07.
Jun 03 21:13:46 ME-NAS-316A noflushd[17518]: Spinning up disk 5 (/dev/sde) after 0:00:05.
Jun 03 21:15:58 ME-NAS-316A noflushd[17518]: Spinning down disk 4 (/dev/sdd).
Jun 03 21:16:06 ME-NAS-316A noflushd[17518]: Spinning up disk 4 (/dev/sdd) after 0:00:05.
Jun 03 21:17:07 ME-NAS-316A noflushd[17518]: Spinning down disk 1 (/dev/sda).
Jun 03 21:17:10 ME-NAS-316A noflushd[17518]: Spinning down disk 2 (/dev/sdb).
Jun 03 21:17:13 ME-NAS-316A noflushd[17518]: Spinning down disk 6 (/dev/sdf).
Jun 03 21:17:20 ME-NAS-316A noflushd[17518]: Spinning up disk 1 (/dev/sda) after 0:00:10.
Jun 03 21:17:20 ME-NAS-316A noflushd[17518]: Spinning up disk 2 (/dev/sdb) after 0:00:07.
Jun 03 21:17:20 ME-NAS-316A noflushd[17518]: Spinning up disk 6 (/dev/sdf) after 0:00:05.
Jun 03 21:18:52 ME-NAS-316A noflushd[17518]: Spinning down disk 3 (/dev/sdc).
Jun 03 21:18:54 ME-NAS-316A noflushd[17518]: Spinning down disk 5 (/dev/sde).
Jun 03 21:19:02 ME-NAS-316A noflushd[17518]: Spinning up disk 3 (/dev/sdc) after 0:00:08.
Jun 03 21:19:02 ME-NAS-316A noflushd[17518]: Spinning up disk 5 (/dev/sde) after 0:00:05.
Jun 03 21:21:13 ME-NAS-316A noflushd[17518]: Spinning down disk 4 (/dev/sdd).
Jun 03 21:21:21 ME-NAS-316A noflushd[17518]: Spinning up disk 4 (/dev/sdd) after 0:00:05.
Jun 03 21:22:23 ME-NAS-316A noflushd[17518]: Spinning down disk 1 (/dev/sda).
Jun 03 21:22:25 ME-NAS-316A noflushd[17518]: Spinning down disk 2 (/dev/sdb).
Jun 03 21:22:28 ME-NAS-316A noflushd[17518]: Spinning down disk 6 (/dev/sdf).
Jun 03 21:22:35 ME-NAS-316A noflushd[17518]: Spinning up disk 1 (/dev/sda) after 0:00:10.
Jun 03 21:22:35 ME-NAS-316A noflushd[17518]: Spinning up disk 2 (/dev/sdb) after 0:00:07.
Jun 03 21:22:35 ME-NAS-316A noflushd[17518]: Spinning up disk 6 (/dev/sdf) after 0:00:05.
Jun 03 21:24:07 ME-NAS-316A noflushd[17518]: Spinning down disk 3 (/dev/sdc).
Jun 03 21:24:15 ME-NAS-316A noflushd[17518]: Spinning up disk 3 (/dev/sdc) after 0:00:05.
Jun 03 21:27:41 ME-NAS-316A noflushd[17518]: Spinning down disk 1 (/dev/sda).

[schumaku]

Well, the obvious HDD spin-down killer would be certainly the silly recording of the loadavg data into /var/readynasd/loadavg.dat located on md0 (typically a RAID1 spanning all internal HDD devices), the system volume, every 15 minutes - this would be prohibitive for having a longer HDD spin-down. That alone does confirm your suspicion: I agree, the spin down feature can't work the way users in the field expect.

In your case, there must be more going on - system.journal - so check what is going into the logs. I would assume there are regular (repeating?) entries in the log file, sometimes every 20 seconds, ....  sometimes about after two minutes. The lz4 that pops up once or so is some compression, I guess done on behalf of sqlite, but again on the events database, housekeeping or on a larger record.

So what is in the NAS system log during this time window?

[Michael_Oz]

---

@schumaku wrote:

So what is in the NAS system log during this time window?

---

system.log

Jun 03 20:55:42 ME-NAS-316A connmand[3424]: ntp: adjust (slew): -0.008095 sec
Jun 03 21:09:01 ME-NAS-316A CRON[18394]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 03 21:09:01 ME-NAS-316A CRON[18395]: (root) CMD (  [ -x /usr/lib/php5/sessionclean ] && /usr/lib/php5/sessionclean)
Jun 03 21:09:02 ME-NAS-316A CRON[18394]: pam_unix(cron:session): session closed for user root
Jun 03 21:12:47 ME-NAS-316A connmand[3424]: ntp: adjust (slew): -0.002741 sec
Jun 03 21:17:01 ME-NAS-316A CRON[18588]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 03 21:17:01 ME-NAS-316A CRON[18589]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jun 03 21:17:01 ME-NAS-316A CRON[18588]: pam_unix(cron:session): session closed for user root
Jun 03 21:29:51 ME-NAS-316A connmand[3424]: ntp: adjust (slew): +0.017888 sec
Jun 03 21:31:11 ME-NAS-316A dbus[3423]: [system] Activating service name='org.opensuse.Snapper' (using servicehelper)
Jun 03 21:31:11 ME-NAS-316A dbus[3423]: [system] Successfully activated service 'org.opensuse.Snapper'

[schumaku]

Sorry, I had expected to see what is in the database, as visible on System -> Logs ... thats what thesefile/block device  access system.journal entries are about, sorry to be unclear.

Ref. the cron sessions: 

-> A "clean" ReadyNAS does not have any cron entries for root

root@RN628X:~# crontab -l
no crontab for root

-> Similar, no such php5 (wahhhhht?) crap:

root@RN628X:~# ls /usr/lib/php5/
ls: cannot access '/usr/lib/php5/': No such file or directory

[Michael_Oz]

---

@schumaku wrote:

Sorry, I had expected to see what is in the database, as visible on System -> Logs

---

Jun 04, 2019 12:00:07 AM Snapshot: Snapshot c_1559570407 was successfully created for share or LUN Backup0.
->>Jun 03, 2019 08:40:31 PM System: Automatic disk spin-down enabled.
Jun 03, 2019 01:07:05 PM System: External storage device disconnected.

Just that one line just before that period.

---

-> A "clean" ReadyNAS does not have any cron entries for root

-> Similar, no such php5 (wahhhhht?) crap:

---

Perhaps detritus from phpSysInfo app, installed years (versions) ago and removed a couple of versions ago?

[Michael_Oz]

I've disabled that job.

#09,39 *     * * *     root   [ -x /usr/lib/php5/sessionclean ] && /usr/lib/php5/sessionclean

[Michael_Oz]

That was /etc/cron.d/php5

[Michael_Oz]

-> A "clean" ReadyNAS does not have any cron entries for root

There is a whole ecosystem, other entries

root@ME-NAS-316A:/etc# ls cron*
crontab

cron.d:
frontview-backup  php5  poweroff  spindown

cron.daily:
logrotate

cron.hourly:

cron.monthly:

cron.weekly:
root@ME-NAS-316A:/etc#

Given the content I have to presume those non-php5 entries are Netgear in origin

While cron.hourly is empty it runs as root

system.log

Jun 04 09:49:01 ME-NAS-316A cron[3433]: (*system*php5) RELOAD (/etc/cron.d/php5)
Jun 04 10:00:48 ME-NAS-316A connmand[3424]: ntp: adjust (slew): -0.022689 sec
Jun 04 10:17:01 ME-NAS-316A CRON[11330]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 04 10:17:01 ME-NAS-316A CRON[11331]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jun 04 10:17:01 ME-NAS-316A CRON[11330]: pam_unix(cron:session): session closed for user root
Jun 04 10:17:52 ME-NAS-316A connmand[3424]: ntp: adjust (slew): -0.009072 sec
Jun 04 10:33:30 ME-NAS-316A sshd[17284]: SSH: Server;Ltype: Kex;Remote: 192.168.1.150-48859;Enc: aes256-ctr;MAC: hmac-sha2-256;Comp: none
Jun 04 10:33:53 ME-NAS-316A apache2[8878]: [:error] [pid 8878] [client 192.168.1.150:58835] mod_csrf(020): request denied, expired id (0 sec), action=deny, id=-, referer: https://192.168.1.6/admin/
Jun 04 10:33:53 ME-NAS-316A apache_access[3973]: Suppressed 1 duplicate messages
Jun 04 10:33:53 ME-NAS-316A apache_access[3973]: 192.168.1.150 "POST /dbbroker HTTP/1.1" 403
Jun 04 10:33:53 ME-NAS-316A apache2[3974]: pam_unix(frontview:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=192.168.1.150  user=admin
Jun 04 10:33:57 ME-NAS-316A apache2[8875]: [auth_basic:error] [pid 8875] [client 192.168.1.150:58836] AH01617: user admin: authentication failure for "/admin/": Password Mismatch, referer: https://192.168.1.6/admin/
Jun 04 10:33:57 ME-NAS-316A apache_access[3973]: 192.168.1.150 "GET /admin/ HTTP/1.1" 401
Jun 04 10:34:56 ME-NAS-316A connmand[3424]: ntp: adjust (slew): +0.006941 sec
Jun 04 10:42:41 ME-NAS-316A dbus[3423]: [system] Activating service name='org.opensuse.Snapper' (using servicehelper)
Jun 04 10:42:41 ME-NAS-316A dbus[3423]: [system] Successfully activated service 'org.opensuse.Snapper'
Jun 04 10:47:24 ME-NAS-316A apache_access[3973]: Suppressed 1 duplicate messages
Jun 04 10:47:24 ME-NAS-316A apache_access[3973]: 192.168.1.150 "POST /dbbroker HTTP/1.1" 401
Jun 04 10:49:08 ME-NAS-316A dbus[3423]: [system] Activating service name='org.opensuse.Snapper' (using servicehelper)
Jun 04 10:49:08 ME-NAS-316A dbus[3423]: [system] Successfully activated service 'org.opensuse.Snapper'

Spindown/up still cycling

Jun 03 10:30:02 ME-NAS-316A noflushd[26631]: Spinning up disk 1 (/dev/sda) after 0:00:05.
Jun 03 10:32:38 ME-NAS-316A noflushd[26631]: Spinning down disk 3 (/dev/sdc).
Jun 03 10:32:41 ME-NAS-316A noflushd[26631]: Spinning down disk 4 (/dev/sdd).
Jun 03 10:32:43 ME-NAS-316A noflushd[26631]: Spinning down disk 5 (/dev/sde).
Jun 03 10:32:46 ME-NAS-316A noflushd[26631]: Spinning down disk 6 (/dev/sdf).
Jun 03 10:32:53 ME-NAS-316A noflushd[26631]: Spinning up disk 3 (/dev/sdc) after 0:00:12.
Jun 03 10:32:53 ME-NAS-316A noflushd[26631]: Spinning up disk 4 (/dev/sdd) after 0:00:10.
Jun 03 10:32:53 ME-NAS-316A noflushd[26631]: Spinning up disk 5 (/dev/sde) after 0:00:07.
Jun 03 10:32:53 ME-NAS-316A noflushd[26631]: Spinning up disk 6 (/dev/sdf) after 0:00:05.
Jun 03 10:33:22 ME-NAS-316A noflushd[26631]: Spinning down disk 2 (/dev/sdb).
Jun 03 10:33:30 ME-NAS-316A noflushd[26631]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Jun 03 10:40:06 ME-NAS-316A noflushd[26631]: Spinning down disk 1 (/dev/sda).
Jun 03 10:40:14 ME-NAS-316A noflushd[26631]: Spinning up disk 1 (/dev/sda) after 0:00:05.

I'll do another block_dump.

[Michael_Oz]

noflushd with -b

systemd-journal.log

I had to kill dups to fit the char limit,

- most dirtied LCD were in groups of three. Not sure what that last flurry is about.

- md0_raid1(1430): WRITE block 8 on sd[a-f]1 - ie was repeated for all six devices

- +n - n more to other addresses.

Jun 04 13:16:15 ME-NAS-316A noflushd[17625]: Quitting on signal...
Jun 04 13:16:15 ME-NAS-316A systemd[1]: Stopped Idle Disk Spindown Daemon.
Jun 04 13:16:15 ME-NAS-316A systemd[1]: Started Idle Disk Spindown Daemon.
Jun 04 13:16:15 ME-NAS-316A noflushd[19271]: Enabling spindown for disk 1 [sda,0:0:TOSHIBA_DT01ACA300:15VAPMZGS:MX6OABB0:7200]
Jun 04 13:16:15 ME-NAS-316A noflushd[19271]: Enabling spindown for disk 2 [sdb,0:1:TOSHIBA_DT01ACA300:353JZERKS:MX6OABB0:7200]
Jun 04 13:16:15 ME-NAS-316A noflushd[19271]: Enabling spindown for disk 3 [sdc,0:2:TOSHIBA_DT01ACA300:15VAR70GS:MX6OABB0:7200]
Jun 04 13:16:15 ME-NAS-316A noflushd[19271]: Enabling spindown for disk 4 [sdd,0:3:ST10000VN0004-1ZD101:ZA2146QE:SC60:7200]
Jun 04 13:16:15 ME-NAS-316A noflushd[19271]: Enabling spindown for disk 5 [sde,0:4:ST10000VN0004-1ZD101:ZA20Z1FE:SC60:7200]
Jun 04 13:16:15 ME-NAS-316A noflushd[19271]: Enabling spindown for disk 6 [sdf,0:5:ST10000VN0004-1ZD101:ZA2157YT:SC60:7200]
Jun 04 13:17:01 ME-NAS-316A CRON[19291]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 04 13:17:01 ME-NAS-316A CRON[19292]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Jun 04 13:17:01 ME-NAS-316A CRON[19291]: pam_unix(cron:session): session closed for user root
Jun 04 13:21:20 ME-NAS-316A noflushd[19271]: Spinning down disk 1 (/dev/sda).
Jun 04 13:21:20 ME-NAS-316A kernel: md0_raid1(1430): WRITE block 8 on sd[a-f]1 (1 sectors)
Jun 04 13:21:20 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096674 (system.journal) on md0
Jun 04 13:21:23 ME-NAS-316A noflushd[19271]: Spinning down disk 2 (/dev/sdb).
Jun 04 13:21:23 ME-NAS-316A kernel: rnutil(19404): dirtied inode 9380 (event.sq3) on md0
Jun 04 13:21:23 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc x3
Jun 04 13:21:25 ME-NAS-316A noflushd[19271]: Spinning down disk 3 (/dev/sdc).
Jun 04 13:21:25 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:21:27 ME-NAS-316A noflushd[19271]: Spinning down disk 4 (/dev/sdd).
Jun 04 13:21:27 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:21:30 ME-NAS-316A noflushd[19271]: Spinning down disk 5 (/dev/sde).
Jun 04 13:21:30 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:21:39 ME-NAS-316A kernel: apache2(3974): dirtied inode 2095252 (tallylog) on md0
Jun 04 13:21:39 ME-NAS-316A kernel: apache2(3974): WRITE block 25264 on md0 (8 sectors)
Jun 04 13:21:39 ME-NAS-316A kernel: md0_raid1(1430): WRITE block 8 on sd[a-f]1 (1 sectors)
Jun 04 13:21:39 ME-NAS-316A noflushd[19271]: Spinning up disk 1 (/dev/sda) after 0:00:16.
Jun 04 13:21:39 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:21:48 ME-NAS-316A noflushd[19271]: Spinning up disk 2 (/dev/sdb) after 0:00:23.
Jun 04 13:21:48 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:21:48 ME-NAS-316A noflushd[19271]: Spinning up disk 3 (/dev/sdc) after 0:00:21.
Jun 04 13:21:48 ME-NAS-316A noflushd[19271]: Spinning up disk 4 (/dev/sdd) after 0:00:18.
Jun 04 13:21:48 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:21:52 ME-NAS-316A kernel: apache2(3974): WRITE block 143456 on md0 (32 sectors)
+3
Jun 04 13:21:52 ME-NAS-316A noflushd[19271]: Spinning up disk 5 (/dev/sde) after 0:00:20.
Jun 04 13:21:52 ME-NAS-316A kernel: apache2(3974): WRITE block 128 on md0 (8 sectors)
Jun 04 13:21:52 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:21:52 ME-NAS-316A kernel: apache2(3974): WRITE block 28472 on md0 (8 sectors)
+4
Jun 04 13:21:52 ME-NAS-316A noflushd[19271]: Spinning up disk 6 (/dev/sdf) after 0:00:18.
Jun 04 13:21:52 ME-NAS-316A kernel: apache2(3974): WRITE block 128 on md0 (8 sectors)
+6
Jun 04 13:21:52 ME-NAS-316A kernel: kworker/u8:4(16869): WRITE block 4263688 on md0 (8 sectors)
+17
Jun 04 13:21:53 ME-NAS-316A kernel: apache2(3974): WRITE block 28912 on md0 (8 sectors)
Jun 04 13:21:53 ME-NAS-316A kernel: kworker/u8:4(16869): WRITE block 4297240 on md0 (16 sectors)
+11
Jun 04 13:21:53 ME-NAS-316A kernel: apache2(3974): WRITE block 143712 on md0 (32 sectors)
Jun 04 13:21:53 ME-NAS-316A kernel: kworker/u8:4(16869): WRITE block 4299264 on md0 (8 sectors)
Jun 04 13:21:53 ME-NAS-316A kernel: apache2(3974): WRITE block 562656 on md0 (32 sectors)
Jun 04 13:21:53 ME-NAS-316A kernel: kworker/u8:4(16869): WRITE block 4299392 on md0 (8 sectors)
+2
Jun 04 13:21:53 ME-NAS-316A kernel: apache2(3974): WRITE block 143744 on md0 (32 sectors)
Jun 04 13:21:53 ME-NAS-316A kernel: apache2(3974): WRITE block 562688 on md0 (32 sectors)
Jun 04 13:21:53 ME-NAS-316A kernel: kworker/u8:4(16869): WRITE block 4299728 on md0 (8 sectors)
+33
Jun 04 13:21:53 ME-NAS-316A kernel: apache2(3974): WRITE block 128 on md0 (8 sectors)
Jun 04 13:21:53 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:21:53 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096674 (system.journal) on md0
Jun 04 13:21:53 ME-NAS-316A kernel: kworker/u8:1(19394): dirtied inode 1 (?) on md0
Jun 04 13:21:53 ME-NAS-316A kernel: kworker/u8:0(17574): WRITE block 143776 on md0 (96 sectors)
+8
Jun 04 13:21:53 ME-NAS-316A kernel: noflushd(19271): WRITE block 128 on md0 (8 sectors)
Jun 04 13:21:53 ME-NAS-316A kernel: noflushd(19271): WRITE block 131072 on md0 (8 sectors)
Jun 04 13:25:36 ME-NAS-316A connmand[3424]: ntp: adjust (slew): -0.040087 sec
Jun 04 13:26:43 ME-NAS-316A noflushd[19271]: Spinning down disk 1 (/dev/sda).
Jun 04 13:26:43 ME-NAS-316A kernel: md0_raid1(1430): WRITE block 8 on sd[a-f]1 (1 sectors)
Jun 04 13:26:43 ME-NAS-316A kernel: systemd-journal(1582): dirtied inode 2096674 (system.journal) on md0
Jun 04 13:26:45 ME-NAS-316A noflushd[19271]: Spinning down disk 2 (/dev/sdb).
Jun 04 13:26:45 ME-NAS-316A kernel: rnutil(19558): dirtied inode 9380 (event.sq3) on md0
Jun 04 13:26:45 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:26:48 ME-NAS-316A noflushd[19271]: Spinning down disk 3 (/dev/sdc).
Jun 04 13:26:48 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:26:50 ME-NAS-316A noflushd[19271]: Spinning down disk 4 (/dev/sdd).
Jun 04 13:26:50 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:26:53 ME-NAS-316A noflushd[19271]: Spinning down disk 5 (/dev/sde).
Jun 04 13:26:53 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:26:55 ME-NAS-316A noflushd[19271]: Spinning down disk 6 (/dev/sdf).
Jun 04 13:26:55 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:26:56 ME-NAS-316A kernel: apache2(3974): dirtied inode 2095252 (tallylog) on md0
Jun 04 13:26:56 ME-NAS-316A kernel: apache2(3974): WRITE block 25264 on md0 (8 sectors)
Jun 04 13:26:56 ME-NAS-316A kernel: md0_raid1(1430): WRITE block 8 on sd[a-f]1 (1 sectors)
Jun 04 13:27:06 ME-NAS-316A kernel: apache2(3974): WRITE block 154304 on md0 (32 sectors)
+3
Jun 04 13:27:11 ME-NAS-316A noflushd[19271]: Spinning up disk 1 (/dev/sda) after 0:00:26.
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A noflushd[19271]: Spinning up disk 2 (/dev/sdb) after 0:00:23.
Jun 04 13:27:11 ME-NAS-316A noflushd[19271]: Spinning up disk 3 (/dev/sdc) after 0:00:21.
Jun 04 13:27:11 ME-NAS-316A noflushd[19271]: Spinning up disk 4 (/dev/sdd) after 0:00:18.
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A noflushd[19271]: Spinning up disk 5 (/dev/sde) after 0:00:16.
Jun 04 13:27:11 ME-NAS-316A noflushd[19271]: Spinning up disk 6 (/dev/sdf) after 0:00:14.
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc
Jun 04 13:27:11 ME-NAS-316A kernel: readynasd(6538): dirtied inode 4026532241 (LCD) on proc

Nothing in Frontview System/Log

[Michael_Oz]

Note: I raised this officialy with My Support, it has been escalated to level 3 support.

[schumaku]

The LCD one you can filter out, it's on the /proc file system residing in the RAM - these are OK.

There is still a conjob lurking around?

Remains the apache2 process sometimes writing to the tallylog ... this is the file where an Apache2 with the pam_tally2.so does write failed login attempts to, this file will be also checked on every login if an account is locked out. FWIW the /sbin/pam_tally2 utility can be used to make the contents readable:

root@RN628X:~# /sbin/pam_tally2
Login Failures Latest failure From
admin 3 06/04/19 10:28:36 192.168.123.45

Unless there are some 3rd party tools in place attempting to get access to the frontview XML data via the admin Web server ... thius is never called.

Now what hurts me more @OOM-9 ?

• The fact that pam_tally2.so is not integrated with the FTP, SSH, AFP, SAMBA, ... services ... that's kind of ridiculous - ways off business class NAS.
• As well, authentication access with known (and unknown) usernames must be logged (user visible, to the frontend system log) - again not buisiness class.

And mentioned before, here for the records of @OOM-9 :

One obvious HDD spin-down killer would be certainly the silly recording of the loadavg data into /var/readynasd/loadavg.dat located on md0 (typically a RAID1 spanning all internal HDD devices), the system volume, every 15 minutes - this would be prohibitive for having a longer HDD spin-down. 

And FWIW here the (very few) cron files on a kinda "clean" ReadyNAS 6.10.1 system:

root@RN628X:/etc# ls cron*
crontab

cron.d:
spindown

cron.daily:

cron.hourly:

cron.monthly:

cron.weekly:

"Given the content I have to presume those non-php5 entries are Netgear in origin" Agree, these names look familiar, however these don't exist on a clean(er), newer system anymore - well possible that's some layzynes ... seen that with my preferred NAS provider, too.

So let's see where this is going to...

[StephenB]

---

@schumaku wrote:

Agree, these names look familiar, however these don't exist on a clean(er), newer system anymore - well possible that's some layzynes ... seen that with my preferred NAS provider, too.

---

FWIW, my system is pretty "vanilla", and was built in late 2016. I also see @Michael_Oz 's entries

root@NAS:/etc# ls cron*
crontab

cron.d:
frontview-backup  frontview-volumeschedule  poweroff  spindown

cron.daily:

cron.hourly:

cron.monthly:

cron.weekly:

And on my system, frontview-volumeschedule and spindown are both populated.  There is no power schedule, and no scheduled backup jobs (and as expected, those two are empty).

I'm running 6.10.0, and have spindown enabled at night.  However, the log from last night doesn't show any spindown events - which seems wrong to me. 

root@NAS:/etc/cron.d# journalctl --no-page | grep -i noflushd
Jun 03 22:00:23 NAS noflushd[317]: Enabling spindown for disk 1 [sda,0:0:WDC_WD100EFAX-68LHPN0]
Jun 03 22:00:23 NAS noflushd[317]: Enabling spindown for disk 2 [sdb,0:1:WDC_WD100EFAX-68LHPN0]
Jun 03 22:00:23 NAS noflushd[317]: Enabling spindown for disk 3 [sdc,0:2:WDC_WD60EFRX-68MYMN1]
Jun 03 22:00:23 NAS noflushd[317]: Enabling spindown for disk 4 [sdd,0:3:WDC_WD60EFRX-68L0BN1]
Jun 04 05:00:02 NAS noflushd[317]: Quitting on signal...
Jun 04 05:00:03 NAS readynasd[5874]: Failed to call method ResetFailedUnit noflushd.service: No such file or directory

[Michael_Oz]

While there may be other longer periodic causes (cron etc), which need to be fixed, there is something happening frequently and regularly, as all spinups are in 5-28 seconds range.