USB disk spins up again during shutdown in FreeNAS 9.3

[Jan-Philip Gehrcke]

Hello,

I have set up a shutdown script via the web interface (in the init/shutdown scripts section) that spins down an external hard drive. The actual command I am using within that shutdown script for spinning down the disk is

usbconfig -d 0.3 suspend​

I am using this command since FreeNAS 9.1 and it actually spins down the disk if it isn't already in sleep mode. This also worked reliably in FreeNAS 9.2. The goal was that whenever the NAS is shut down, the externally attached (and externally powered) USB disk shoult never spin, but "sleep" instead.

This does not work anymore with FreeNAS-9.3-STABLE-201504100216.

The suspend commant itself still works, it puts the disk to sleep. However, one essential thing changed with FreeNAS 9.3. *After* my spin-down script has run during shutdown (it works, it spins down the disk), the disk spins up again a few seconds later, at a later state during shutdown. The result is: the system is shut down and the external disk spins infinitely long (I'd have to manually switch it off).

I anticipate that this is not something you can consider a bug in FreeNAS. Still, I think it is an important part of disk-related behavior that changed when switching from 9.2 to 9.3, and so it should be discussed seriously.

First of all, I'd love to understand which part during shutdown makes the disk spin up again. So far, I was not really able to debug this myself. Here is relevant output from /var/log/messages, the last part during shutdown.

Jun 4 03:25:41 freenas kernel: <118>INFO >>> USB disk suspend script invocation @ 20150604-032540
Jun 4 03:25:41 freenas kernel: <118>Stopping sshd.
Jun 4 03:25:41 freenas kernel: <118>Waiting for PIDS: 2764.
Jun 4 03:25:41 freenas kernel: <118>Stopping django.
Jun 4 03:25:41 freenas smbd[2259]: dnssd_clientstub DNSServiceProcessResult called with DNSServiceRef with no ProcessReply function
Jun 4 03:25:42 freenas syslog-ng[13312]: syslog-ng starting up; version='3.5.6'
Jun 4 03:25:42 freenas kernel: .
Jun 4 03:25:42 freenas kernel: <118>Stopping mdnsd.
Jun 4 03:25:42 freenas kernel: <118>Waiting for PIDS: 2488.
Jun 4 03:25:42 freenas kernel: <118>Stopping nginx.
Jun 4 03:25:42 freenas kernel: <118>Waiting for PIDS: 2481.
Jun 4 03:25:42 freenas kernel: <118>Stopping pbid...
Jun 4 03:25:42 freenas kernel: <118>Stopping smartd.
Jun 4 03:25:42 freenas kernel: <118>Stopping winbindd.
Jun 4 03:25:42 freenas kernel: <118>Waiting for PIDS: 2262
Jun 4 03:25:42 freenas kernel: <6>pid 1643 (syslog-ng), uid 0: exited on signal 6 (core dumped)
Jun 4 03:25:42 freenas kernel: <118>, 2262.
Jun 4 03:25:42 freenas kernel: <118>Stopping smbd.
Jun 4 03:25:42 freenas kernel: <118>Stopping nmbd.
Jun 4 03:25:42 freenas kernel: <118>Stopping powerd.
Jun 4 03:25:42 freenas kernel: <118>Stopping ntpd.
Jun 4 03:25:42 freenas ntpd[1987]: ntpd exiting on signal 15
Jun 4 03:25:43 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 1
Jun 4 03:25:43 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 1
Jun 4 03:25:43 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 1
Jun 4 03:25:44 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 2
Jun 4 03:25:44 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 2
Jun 4 03:25:44 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 2
Jun 4 03:25:45 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 3
Jun 4 03:25:45 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 3
Jun 4 03:25:45 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 3
Jun 4 03:25:46 freenas python: dnssd_clientstub ConnectToServer: connect() failed Socket:7 Err:-1 Errno:61 Connection refused
Jun 4 03:25:46 freenas python: dnssd_clientstub ConnectToServer: connect() failed Socket:4 Err:-1 Errno:61 Connection refused
Jun 4 03:25:46 freenas python: dnssd_clientstub ConnectToServer: connect() failed Socket:8 Err:-1 Errno:61 Connection refused
Jun 4 03:25:49 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 1
Jun 4 03:25:49 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 1
Jun 4 03:25:49 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 1
Jun 4 03:25:50 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 2
Jun 4 03:25:50 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 2
Jun 4 03:25:50 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 2
Jun 4 03:25:50 freenas kernel: <118>Shutting down local daemons:.
Jun 4 03:25:50 freenas kernel: <118>Stopping watchdogd.
Jun 4 03:25:50 freenas kernel: <118>Waiting for PIDS: 1646.
Jun 4 03:25:50 freenas kernel: <118>Stopping devd.
Jun 4 03:25:50 freenas kernel: <118>Waiting for PIDS: 1279.
Jun 4 03:25:50 freenas kernel: <118>Writing entropy file:.
Jun 4 03:25:51 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 3
Jun 4 03:25:51 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 3
Jun 4 03:25:51 freenas python: dnssd_clientstub ConnectToServer: connect()-> No of tries: 3
Jun 4 03:25:52 freenas syslog-ng[13312]: syslog-ng shutting down; version='3.5.6'
Jun 4 03:25:52 freenas kernel: <118>Terminated
Jun 4 03:25:52 freenas kernel: <118>.​

The output starts with my spin-down script ("USB disk suspend script invocation") and ends with syslog shutting down. The point is: something inbetween 03:25:41 and 03:25:52 triggers the disk to spin up again. What could that be? Is that desired behavior or should it be considered a bug? What can I/we do about it?

Big thanks in advance for any insights.

 

[cyberjock]

I can tell you exactly what spins up the disks.. stopping services causes log entries to be made. 9.3 relies on the .system dataset more than 9.2 did (it didn't exist in 9.2).

The short answer is that spindown is basically impossible for disks that are part of a zpool with your .system dataset. So if you want spindown, you'll have to make another pool with a disk that won't be able to go to sleep.

 

[Jan-Philip Gehrcke]

Thanks for your response! Unfortunately it is not that simple. I should have added to the opening post that the disk has its own zpool, and this zpool is exported as part of my "suspend script". There is, for sure, no system-related data on that disk. I use it for rsync-based backups only. In fact, when the machine boots up, the usual process is that this backup is executed and then the zpool is exported right after that, followed by a USB suspend command. From here on, the disk sleeps for hours or days just fine. So, just running the system never wakes the disk up. It only wakes up again during shutdown.

I should also add what happens when I execute my "suspend script" while the disk already sleeps. Nothing, that is just fine. So, execution of the suspend script during shutdown is not the reason for it to wake up again. The responsible thing really must happen in the time frame I indicated in the opening post.