Spin down keeps waking up (per logs)

[index]

i just enabled spin down for the first time last night, but this morning the system log showed the following.
The only other PC on the network was shut down. Any ideas why it won't stay asleep?

Code: Select all

...
Aug 31 23:54:44 readynas noflushd[721]: Spinning down /dev/hdi.
Aug 31 23:54:45 readynas noflushd[721]: Spinning down /dev/hdg.
Aug 31 23:54:45 readynas noflushd[721]: Spinning down /dev/hde.
Aug 31 23:54:45 readynas noflushd[721]: Spinning down /dev/hdc.
Aug 31 23:54:55 readynas noflushd[721]: Spinning up /dev/hdi after 0 minutes.
Aug 31 23:54:55 readynas noflushd[721]: Spinning up /dev/hdg after 0 minutes.
Aug 31 23:54:55 readynas noflushd[721]: Spinning up /dev/hde after 0 minutes.
Aug 31 23:54:55 readynas noflushd[721]: Spinning up /dev/hdc after 0 minutes.
Sep  1 00:04:55 readynas noflushd[721]: Spinning down /dev/hdi.
Sep  1 00:04:56 readynas noflushd[721]: Spinning down /dev/hdg.
Sep  1 00:04:56 readynas noflushd[721]: Spinning down /dev/hde.
Sep  1 00:04:56 readynas noflushd[721]: Spinning down /dev/hdc.
Sep  1 00:07:31 readynas noflushd[721]: Spinning up /dev/hdi after 2 minutes.
Sep  1 00:07:31 readynas noflushd[721]: Spinning up /dev/hdg after 2 minutes.
Sep  1 00:07:31 readynas noflushd[721]: Spinning up /dev/hde after 2 minutes.
Sep  1 00:07:31 readynas noflushd[721]: Spinning up /dev/hdc after 2 minutes.
Sep  1 00:20:32 readynas noflushd[721]: Spinning down /dev/hdi.
Sep  1 00:20:33 readynas noflushd[721]: Spinning down /dev/hdg.
Sep  1 00:20:33 readynas noflushd[721]: Spinning down /dev/hde.
Sep  1 00:20:33 readynas noflushd[721]: Spinning down /dev/hdc.
Sep  1 00:23:13 readynas noflushd[721]: Spinning up /dev/hdi after 2 minutes.
Sep  1 00:23:13 readynas noflushd[721]: Spinning up /dev/hdg after 2 minutes.
Sep  1 00:23:13 readynas noflushd[721]: Spinning up /dev/hde after 2 minutes.
Sep  1 00:23:13 readynas noflushd[721]: Spinning up /dev/hdc after 2 minutes.
Sep  1 00:33:13 readynas noflushd[721]: Spinning down /dev/hdi.
Sep  1 00:33:14 readynas noflushd[721]: Spinning down /dev/hdg.
Sep  1 00:33:14 readynas noflushd[721]: Spinning down /dev/hde.
Sep  1 00:33:14 readynas noflushd[721]: Spinning down /dev/hdc.
Sep  1 02:05:13 readynas noflushd[721]: Spinning up /dev/hdi after 91 minutes.
Sep  1 02:05:13 readynas noflushd[721]: Spinning up /dev/hdg after 91 minutes.
Sep  1 02:05:13 readynas noflushd[721]: Spinning up /dev/hde after 91 minutes.
Sep  1 02:05:13 readynas noflushd[721]: Spinning up /dev/hdc after 91 minutes.
Sep  1 02:15:14 readynas noflushd[721]: Spinning down /dev/hdi.
Sep  1 02:15:14 readynas noflushd[721]: Spinning down /dev/hdg.
Sep  1 02:15:14 readynas noflushd[721]: Spinning down /dev/hde.
Sep  1 02:15:14 readynas noflushd[721]: Spinning down /dev/hdc.
Sep  1 04:00:12 readynas noflushd[721]: Spinning up /dev/hdi after 104 minutes.
Sep  1 04:00:12 readynas noflushd[721]: Spinning up /dev/hdg after 104 minutes.
Sep  1 04:00:12 readynas noflushd[721]: Spinning up /dev/hde after 104 minutes.
Sep  1 04:00:12 readynas noflushd[721]: Spinning up /dev/hdc after 104 minutes.
Sep  1 04:10:09 readynas ntpdate[3352]: step time server 12.151.34.177 offset 0.031741 sec
Sep  1 04:10:13 readynas noflushd[721]: Spinning down /dev/hdi.
Sep  1 04:10:14 readynas noflushd[721]: Spinning down /dev/hdg.
Sep  1 04:10:14 readynas noflushd[721]: Spinning down /dev/hde.
Sep  1 04:10:14 readynas noflushd[721]: Spinning up /dev/hdi after 0 minutes.
Sep  1 04:10:14 readynas noflushd[721]: Spinning up /dev/hdg after 0 minutes.
Sep  1 04:10:14 readynas noflushd[721]: Spinning up /dev/hde after 0 minutes.
Sep  1 04:20:14 readynas noflushd[721]: Spinning down /dev/hdi.
Sep  1 04:20:15 readynas noflushd[721]: Spinning down /dev/hdg.
Sep  1 04:20:15 readynas noflushd[721]: Spinning down /dev/hde.
Sep  1 04:20:15 readynas noflushd[721]: Spinning down /dev/hdc.
Sep  1 06:25:10 readynas noflushd[721]: Spinning up /dev/hdi after 124 minutes.
Sep  1 06:25:17 readynas noflushd[721]: Spinning up /dev/hdg after 125 minutes.
Sep  1 06:25:17 readynas noflushd[721]: Spinning up /dev/hde after 125 minutes.
Sep  1 06:25:17 readynas noflushd[721]: Spinning up /dev/hdc after 125 minutes.
Sep  1 06:25:29 readynas syslogd 1.4.1#10: restart.
Sep  1 06:25:29 readynas ntpdate[4018]: step time server 12.151.34.177 offset 0.013252 sec
Sep  1 06:36:10 readynas noflushd[721]: Spinning down /dev/hdi.
Sep  1 06:36:10 readynas noflushd[721]: Spinning down /dev/hdg.
Sep  1 06:36:10 readynas noflushd[721]: Spinning down /dev/hde.
Sep  1 06:36:10 readynas noflushd[721]: Spinning down /dev/hdc.
Sep  1 06:52:12 readynas noflushd[721]: Spinning up /dev/hdi after 16 minutes.
Sep  1 06:52:12 readynas noflushd[721]: Spinning up /dev/hdg after 16 minutes.
Sep  1 06:52:12 readynas noflushd[721]: Spinning up /dev/hde after 16 minutes.
Sep  1 06:52:12 readynas noflushd[721]: Spinning up /dev/hdc after 16 minutes.
Sep  1 07:02:13 readynas noflushd[721]: Spinning down /dev/hdi.
Sep  1 07:02:14 readynas noflushd[721]: Spinning down /dev/hdg.
Sep  1 07:02:14 readynas noflushd[721]: Spinning down /dev/hde.
Sep  1 07:02:14 readynas noflushd[721]: Spinning down /dev/hdc.
Sep  1 07:34:48 readynas noflushd[721]: Spinning up /dev/hdi after 32 minutes.
Sep  1 07:34:48 readynas noflushd[721]: Spinning up /dev/hdg after 32 minutes.
Sep  1 07:34:48 readynas noflushd[721]: Spinning up /dev/hde after 32 minutes.
Sep  1 07:34:48 readynas noflushd[721]: Spinning up /dev/hdc after 32 minutes.
Sep  1 04:20:15 readynas noflushd[721]: Spinning down /dev/hdg.
...

[chirpa]

Any port forwards to the NAS that outside connections may trigger it? UPnP or other services running?

[index]

Any port forwards to the NAS that outside connections may trigger it? UPnP or other services running?

No outside connections...a firewall is up.
I also checked the http/https access logs.

upnp is off, however itunes server is up.

[chirpa]

Can you send me your system logs (link in my sig).

[index]

i just reset and turned off the UPNP service and discovery. i will wait till tomorrow and send you the logs then (so the nas has some time to spin up, spin down, spin up,...)

[Skywalker]

There should be a new 4.1.3 release coming out very soon, which has some major spindown time improvements.

[index]

logs sent.

@Skywalker
is there a projected release date for 4.1.3 ?

[chirpa]

You can give the beta release a try if you like:

Release Notes for RAIDiator 4.1.3-T136

Enhanced disk spin-down times.

[essd]

I'm using 4.1.4, and I'm seeing similar problems to what the first poster noted: the system will not spin down for more than 5 seconds before waking up. I'm using two Samsung HD103UJ's in a Duo.

Spindown was never great with the 4.01 release, but at least it would sleep for a couple of minutes. Any ideas? The only special service running on the NAS is Firefly; the only other computer connected to the network would have been doing a Time Machine backup every hour, but it otherwise does not attempt to use the NAS at all.

For example:

Code: Select all

Sep 26 22:18:00 nas noflushd[790]: Spinning down /dev/hde.
Sep 26 22:18:00 nas noflushd[790]: Spinning up /dev/hde after 0 minutes.
Sep 26 23:09:06 nas noflushd[790]: Spinning down /dev/hde.
Sep 26 23:09:07 nas noflushd[790]: Spinning up /dev/hde after 0 minutes.
Sep 26 23:35:09 nas noflushd[790]: Spinning down /dev/hde.
Sep 26 23:35:11 nas noflushd[790]: Spinning down /dev/hdc.
Sep 26 23:35:11 nas noflushd[790]: Spindown of /dev/hdc cancelled.
Sep 26 23:35:11 nas noflushd[790]: Spinning up /dev/hde after 0 minutes.
Sep 26 23:50:13 nas noflushd[790]: Spinning down /dev/hde.
Sep 26 23:50:15 nas noflushd[790]: Spinning down /dev/hdc.
Sep 26 23:50:25 nas noflushd[790]: Spinning up /dev/hde after 0 minutes.
Sep 26 23:50:25 nas noflushd[790]: Spinning up /dev/hdc after 0 minutes.
Sep 27 09:08:19 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 09:08:20 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 10:08:07 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 10:08:08 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 11:11:35 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 11:11:36 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 12:00:00 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 12:00:01 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 12:15:23 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 12:15:25 nas noflushd[791]: Spinning down /dev/hdc.
Sep 27 12:15:28 nas noflushd[791]: Spindown of /dev/hdc cancelled.
Sep 27 12:15:28 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 12:55:33 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 12:55:34 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 13:10:36 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 13:10:38 nas noflushd[791]: Spinning down /dev/hdc.
Sep 27 13:10:48 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 13:10:48 nas noflushd[791]: Spinning up /dev/hdc after 0 minutes.
Sep 27 13:55:32 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 13:55:33 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 14:10:35 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 14:10:37 nas noflushd[791]: Spinning down /dev/hdc.
Sep 27 14:10:47 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 14:10:47 nas noflushd[791]: Spinning up /dev/hdc after 0 minutes.
Sep 27 15:04:13 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 15:04:14 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 15:19:16 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 15:19:18 nas noflushd[791]: Spinning down /dev/hdc.
Sep 27 15:19:21 nas noflushd[791]: Spindown of /dev/hdc cancelled.
Sep 27 15:19:21 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 15:57:05 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 15:57:06 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 16:15:08 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 16:15:10 nas noflushd[791]: Spinning down /dev/hdc.
Sep 27 16:15:10 nas noflushd[791]: Spindown of /dev/hdc cancelled.
Sep 27 16:15:10 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.
Sep 27 19:04:09 nas noflushd[791]: Spinning down /dev/hde.
Sep 27 19:04:10 nas noflushd[791]: Spinning up /dev/hde after 0 minutes.

[Skywalker]

Can you try the addon I posted at viewtopic.php?f=24&t=20763&p=119521#p119521 ?

[Jeroen1000]

Oh surprise surprise. eesd, do you have SSH enabled? I tried Netgear support for this one but they blew me off after having me reset my NAS 4(!) times (and a sync takes quite some time) and switching disks etc etc,... . Eventually, they spotted that my SSH was enabled in my first set of logs (what obviously was not the case anymore after 4 resets and then sending new logs) and they canned the issue altogether stating I should send new logs with SSH off (perhaps I should have done 50 resets:p)

Sorry, now I feel better. Well then, I fixed it by turning write cache OFF on the second drive. Works perfectly now. Until you reboot, then you will need to turn it off again.

I do not know what the performance impact will be, if any. You need SSH access to change it, but will lose official support until you turn SSH access off.

[Skywalker]

Did you ever try Flex-RAID mode instead of X-RAID?

[essd]

I think I've identified the cause of this issue, at least for me!

I tried installing the add-on that Skywalker mentioned (viewtopic.php?f=24&t=20763&p=119521#p119521) but it did NOT help.

On a hunch, though, I started doing some investigation. The system has been spinning up after only 0-2 minutes of sleep (assuming that the spindown was not cancelled in the first place).

My first step was to turn off Time Machine on the two computers on my network that were set to do that. I let it run for an hour, and it was still spinning up with little downtime.

After that, I unplugged the ethernet cord for an hour. Interestingly, the system remained in sleep mode without spinning up.

FIguring that this might pave the way to more clues, I plugged the ethernet back in and I then turned off as many services on the box as I could.

It took a couple of hours of testing, but I narrowed the problem down to the iTunes Streaming Server (Firefly). While this service is running, the system will not spin down for more than a few minutes.

Once I turned it off, I started getting much more reasonable spindown durations. The drives have seen no filesystem activity since 17:37 local time (it's 21:40 now), and aside from a brief spin-up and sleep at 20:00 for no apparent reason, the drives were asleep for the whole time.

The bigger question is: why is this happening? I have only two computers connected to the network (both Macs) and iTunes is definitely not running on either of them. The firefly config is set to force scans, but it should only be doing that once every day (86,400 seconds). On the other hand, the fact that it spins down properly without ethernet attached is still a little suspicious.

It's great to get the spindown feature working, but I would also like to be able to stream music off the NAS. Ideas?

[essd]

I think I've identified the cause of this issue, at least for me!

<...>
It took a couple of hours of testing, but I narrowed the problem down to the iTunes Streaming Server (Firefly). While this service is running, the system will not spin down for more than a few minutes.

I take that back. Although Firefly was definitely preventing spindown for me, there is something else preventing it too. Even with Firefly shut off and the latest and greatest Spindown update that was posted earlier this week, I'm still seeing spin-ups for no apparent reason.

There is no file activity happening on the local network, but something is waking up the NAS. My syslog looks like this for an example period:

Oct 9 15:42:40 nas noflushd[835]: Spinning down /dev/hdc.
Oct 9 15:42:42 nas noflushd[835]: Spinning down /dev/hde.
Oct 9 15:42:52 nas noflushd[835]: Spinning up /dev/hdc after 0 minutes.
Oct 9 15:42:52 nas noflushd[835]: Spinning up /dev/hde after 0 minutes.
Oct 9 15:53:04 nas noflushd[835]: Spinning down /dev/hdc.
Oct 9 15:53:06 nas noflushd[835]: Spinning down /dev/hde.
Oct 9 15:54:37 nas noflushd[835]: Spinning up /dev/hdc after 1 minutes.
Oct 9 15:54:46 nas noflushd[835]: Spinning up /dev/hde after 1 minutes.
Oct 9 16:00:02 nas ntpdate[2024]: step time server 12.151.34.177 offset -0.130965 sec
Oct 9 16:10:08 nas noflushd[835]: Spinning down /dev/hdc.
Oct 9 16:10:10 nas noflushd[835]: Spinning down /dev/hde.
Oct 9 16:23:13 nas noflushd[835]: Spinning up /dev/hdc after 13 minutes.
Oct 9 16:23:22 nas noflushd[835]: Spinning up /dev/hde after 13 minutes.
Oct 9 16:33:19 nas noflushd[835]: Spinning down /dev/hdc.
Oct 9 16:33:21 nas noflushd[835]: Spinning down /dev/hde.

I was running tcpdump to capture traffic over this period, and I saw no traffic that *should* be waking up the NAS. Packets were of the random variety that one would expect for a network with no local activity: broadcast NetBIOS nameserver packets; ARP; broadcast IGMP; broadcast Bonjour announcements; and the one NTP request above.

I do see a correlation between ARP request/responses for the NAS and spin-ups. For example, from the above log (with MAC address sanitized for privacy):

15:42:40.871093 arp who-has 10.1.1.2 tell 10.1.1.5
15:42:40.871193 arp reply 10.1.1.2 is-at 00:0d:a2:xx:xx:xx (oui Unknown)

16:23:13.829446 arp who-has 10.1.1.2 tell 10.1.1.5
16:23:13.829547 arp reply 10.1.1.2 is-at 00:0d:a2:xx:xx:xx (oui Unknown)

10.1.1.2 is the NAS and .5 is a workstation on the network. These were the only times that I saw ARP requests for .2, so the timing seems to be more than coincidental.

Is it possible that the NAS is spinning up solely to answer ARP queries? If so, is there anything I can do to stay spun down? I'd be happy to provide the tcpdump data to the Jedis if it would help.

Thanks!
-essd

[Skywalker]

Hmm, I would think ARP requests shouldn't do much. You're not running SlimServer on your NAS by any chance, are you?