Pro Pioneer - Spin Down working or not ?

I've just submitted an online case to them. They want to consult with higher powers. Let's see. Case # 13502474.

Some news - at least now I have a second Pro Pioneer with different drives - let's see what this one does.

PS I hadn't thought about time syncro - I'll disable that and see.

Have you checked in your logs for anything with a timestamp around when your disks spin up (that might give a clue as to what's going on).

Yes, I've checked many times for ANY logs with any indication of what is going on: nada. It's been suggested - multiple times - that the device is spinning up out of sleep mode simply to write to logs. Despite my asking, no one has ever suggested what a sleeping device could possibly want to write to a log file, and this answer is unacceptable to me. I just did a port translation on my router this evening to try to stop SSH attacks on the default port 22, but that still does not account for all the wake cycles.

Time synchro does account for some wakes, but not most of them. I've submitted an enhancement request suggesting a configurable synchronization period since 4 hours is completely unnecessary.

The second Pro Pioneer now has 2x Samsung 1.5TB drives in it and seems to be behaving properly wrt spindown !
Here's an extract from the logs and you can see that it's doing a whole lot of stuff between spindown (top) and spinup (bottom).
(Including mounting a SCSI drive - which I don't have enabled !)
I caused the spinup by adding a 3rd 1.5TB drive.

Maybe spindown doesn't like the Seagate 2TB 5900rpm drives.


Oct 26 19:25:38 nas-EA-75-45 noflushd[1663]: Spinning down disks.
Oct 26 22:03:47 nas-EA-75-45 kernel: ata4: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xe frozen
Oct 26 22:03:47 nas-EA-75-45 kernel: ata4: irq_stat 0x00400040, connection status changed
Oct 26 22:03:47 nas-EA-75-45 kernel: ata4: SError: { PHYRdyChg CommWake DevExch }
Oct 26 22:03:47 nas-EA-75-45 kernel: ata4: hard resetting link
Oct 26 22:03:53 nas-EA-75-45 kernel: ata4: link is slow to respond, please be patient (ready=0)
Oct 26 22:03:57 nas-EA-75-45 kernel: ata4: COMRESET failed (errno=-16)
Oct 26 22:03:57 nas-EA-75-45 kernel: ata4: hard resetting link
Oct 26 22:03:59 nas-EA-75-45 kernel: ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Oct 26 22:03:59 nas-EA-75-45 kernel: ata4.00: ATA-8: ST31500341AS, CC1H, max UDMA/133
Oct 26 22:03:59 nas-EA-75-45 kernel: ata4.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 31/32)
Oct 26 22:03:59 nas-EA-75-45 kernel: ata4.00: configured for UDMA/133
Oct 26 22:03:59 nas-EA-75-45 kernel: ata4: EH complete
Oct 26 22:03:59 nas-EA-75-45 kernel: scsi 3:0:0:0: Direct-Access ATA ST31500341AS CC1H PQ: 0 ANSI: 5
Oct 26 22:03:59 nas-EA-75-45 kernel: sd 3:0:0:0: [sdc] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB)
Oct 26 22:03:59 nas-EA-75-45 kernel: sd 3:0:0:0: [sdc] Write Protect is off
Oct 26 22:03:59 nas-EA-75-45 kernel: sd 3:0:0:0: [sdc] Mode Sense: 00 3a 00 00
Oct 26 22:03:59 nas-EA-75-45 kernel: sd 3:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Oct 26 22:03:59 nas-EA-75-45 kernel: sdc:
Oct 26 22:03:59 nas-EA-75-45 kernel: sd 3:0:0:0: Attached scsi generic sg2 type 0
Oct 26 22:03:59 nas-EA-75-45 kernel: sdc1
Oct 26 22:03:59 nas-EA-75-45 kernel: sd 3:0:0:0: [sdc] Attached SCSI disk
Oct 26 22:04:08 nas-EA-75-45 noflushd[1663]: Disks spinning up after 158 minutes.

For anyone that is having trouble with disks either not spinning down or spinning up prematurely, check your auth.log and post if you see any activity in it. Apparently, a CRON job (at least that is what the log says) is opening and closing a root session every 10-15 minutes, all the time, on my box:
Oct 27 16:53:01 JitterBug CRON[2514]: (pam_unix) session opened for user root by (uid=0)
Oct 27 16:53:02 JitterBug CRON[2514]: (pam_unix) session closed for user root
Oct 27 17:08:01 JitterBug CRON[2744]: (pam_unix) session opened for user root by (uid=0)
Oct 27 17:08:22 JitterBug CRON[2744]: (pam_unix) session closed for user root
Oct 27 17:17:01 JitterBug CRON[2909]: (pam_unix) session opened for user root by (uid=0)
Oct 27 17:17:01 JitterBug CRON[2909]: (pam_unix) session closed for user root
Oct 27 17:23:01 JitterBug CRON[3010]: (pam_unix) session opened for user root by (uid=0)
Oct 27 17:23:02 JitterBug CRON[3010]: (pam_unix) session closed for user root
Oct 27 17:38:01 JitterBug CRON[3229]: (pam_unix) session opened for user root by (uid=0)
Oct 27 17:53:01 JitterBug CRON[3457]: (pam_unix) session opened for user root by (uid=0)
Oct 27 17:53:01 JitterBug CRON[3457]: (pam_unix) session closed for user root
Oct 27 18:08:01 JitterBug CRON[3686]: (pam_unix) session opened for user root by (uid=0)
Oct 27 18:08:01 JitterBug CRON[3686]: (pam_unix) session closed for user root
Oct 27 18:08:02 JitterBug CRON[3229]: (pam_unix) session closed for user root
Oct 27 18:17:01 JitterBug CRON[3820]: (pam_unix) session opened for user root by (uid=0)
Oct 27 18:17:01 JitterBug CRON[3820]: (pam_unix) session closed for user root
Oct 27 18:23:01 JitterBug CRON[3907]: (pam_unix) session opened for user root by (uid=0)
Oct 27 18:23:03 JitterBug CRON[3907]: (pam_unix) session closed for user root
Oct 27 18:38:01 JitterBug CRON[4128]: (pam_unix) session opened for user root by (uid=0)
Oct 27 18:38:45 JitterBug CRON[4128]: (pam_unix) session closed for user root
Oct 27 18:53:01 JitterBug CRON[4328]: (pam_unix) session opened for user root by (uid=0)
Oct 27 18:53:02 JitterBug CRON[4328]: (pam_unix) session closed for user root
Oct 27 19:08:01 JitterBug CRON[4542]: (pam_unix) session opened for user root by (uid=0)
Oct 27 19:08:03 JitterBug CRON[4542]: (pam_unix) session closed for user root
Oct 27 19:17:01 JitterBug CRON[4670]: (pam_unix) session opened for user root by (uid=0)
Oct 27 19:17:01 JitterBug CRON[4670]: (pam_unix) session closed for user root
Oct 27 19:23:01 JitterBug CRON[4751]: (pam_unix) session opened for user root by (uid=0)
Oct 27 19:23:23 JitterBug CRON[4751]: (pam_unix) session closed for user root
Oct 27 19:38:01 JitterBug CRON[4963]: (pam_unix) session opened for user root by (uid=0)
Oct 27 19:38:03 JitterBug CRON[4963]: (pam_unix) session closed for user root
Oct 27 19:53:01 JitterBug CRON[5177]: (pam_unix) session opened for user root by (uid=0)
Oct 27 19:53:02 JitterBug CRON[5177]: (pam_unix) session closed for user root
Oct 27 20:00:01 JitterBug CRON[5279]: (pam_unix) session opened for user root by (uid=0)
Oct 27 20:00:01 JitterBug CRON[5279]: (pam_unix) session closed for user root
Oct 27 20:08:01 JitterBug CRON[5388]: (pam_unix) session opened for user root by (uid=0)
Oct 27 20:08:03 JitterBug CRON[5388]: (pam_unix) session closed for user root
Oct 27 20:17:01 JitterBug CRON[5514]: (pam_unix) session opened for user root by (uid=0)
Oct 27 20:17:01 JitterBug CRON[5514]: (pam_unix) session closed for user root
Oct 27 20:23:01 JitterBug CRON[5595]: (pam_unix) session opened for user root by (uid=0)
Oct 27 20:23:02 JitterBug CRON[5595]: (pam_unix) session closed for user root
Oct 27 20:38:01 JitterBug CRON[5823]: (pam_unix) session opened for user root by (uid=0)
Oct 27 20:38:03 JitterBug CRON[5823]: (pam_unix) session closed for user root

-Robert

Damn right !

Millions of CRON related entries in auth.log

I'm pouring 4TB of stuff back in Pro #2 at the moment so I can't test Pro #1.
When that's finished and all is quiet, I'll test again.

CRON is a timer related activity as I remember from Ubuntu Linux.
What is it supposed to be doing as I have set no timers except : SpinDown and ShutDown/WakeUp

However I have entries for SpinDown that overlap with these CRON entries, so they might not be the cause :

viz :

Oct 30 01:12:39 Pippin noflushd[1877]: Spinning down disks.
Oct 30 02:05:14 Pippin noflushd[1877]: Disks spinning up after 52 minutes.
Oct 30 03:07:15 Pippin noflushd[1877]: Spinning down disks.
Oct 30 05:04:30 Pippin noflushd[1877]: Disks spinning up after 117 minutes.

and

Oct 30 01:17:01 Pippin CRON[17014]: (pam_unix) session opened for user root by (uid=0)
Oct 30 01:17:01 Pippin CRON[17014]: (pam_unix) session closed for user root
Oct 30 01:23:01 Pippin CRON[17110]: (pam_unix) session opened for user root by (uid=0)
Oct 30 01:38:01 Pippin CRON[17373]: (pam_unix) session opened for user root by (uid=0)
Oct 30 01:38:01 Pippin CRON[17373]: (pam_unix) session closed for user root
Oct 30 01:53:01 Pippin CRON[17628]: (pam_unix) session opened for user root by (uid=0)
Oct 30 01:53:01 Pippin CRON[17628]: (pam_unix) session closed for user root
Oct 30 02:05:01 Pippin CRON[17833]: (pam_unix) session opened for user root by (uid=0)
Oct 30 02:05:30 Pippin sudo: root : TTY=unknown ; PWD=/root ; USER=root ; COMMAND=/sbin/mdconfig -t
Oct 30 02:05:30 Pippin CRON[17833]: (pam_unix) session closed for user root

Oct 30 03:08:01 Pippin CRON[18806]: (pam_unix) session opened for user root by (uid=0)
Oct 30 03:17:01 Pippin CRON[18955]: (pam_unix) session opened for user root by (uid=0)
Oct 30 03:17:01 Pippin CRON[18955]: (pam_unix) session closed for user root
Oct 30 03:23:01 Pippin CRON[19058]: (pam_unix) session opened for user root by (uid=0)
Oct 30 03:23:01 Pippin CRON[19058]: (pam_unix) session closed for user root
Oct 30 03:38:01 Pippin CRON[19311]: (pam_unix) session opened for user root by (uid=0)
Oct 30 03:38:01 Pippin CRON[19311]: (pam_unix) session closed for user root
Oct 30 03:53:01 Pippin CRON[19572]: (pam_unix) session opened for user root by (uid=0)
Oct 30 03:53:01 Pippin CRON[19572]: (pam_unix) session closed for user root
Oct 30 04:00:01 Pippin CRON[19686]: (pam_unix) session opened for user root by (uid=0)
Oct 30 04:00:01 Pippin CRON[19685]: (pam_unix) session opened for user root by (uid=0)
Oct 30 04:08:01 Pippin CRON[19832]: (pam_unix) session opened for user root by (uid=0)
Oct 30 04:08:01 Pippin CRON[19832]: (pam_unix) session closed for user root
Oct 30 04:17:01 Pippin CRON[19991]: (pam_unix) session opened for user root by (uid=0)
Oct 30 04:17:01 Pippin CRON[19991]: (pam_unix) session closed for user root
Oct 30 04:23:01 Pippin CRON[20094]: (pam_unix) session opened for user root by (uid=0)
Oct 30 04:23:01 Pippin CRON[20094]: (pam_unix) session closed for user root
Oct 30 04:38:01 Pippin CRON[20357]: (pam_unix) session opened for user root by (uid=0)
Oct 30 04:38:01 Pippin CRON[20357]: (pam_unix) session closed for user root
Oct 30 04:53:01 Pippin CRON[20610]: (pam_unix) session opened for user root by (uid=0)
Oct 30 04:53:01 Pippin CRON[20610]: (pam_unix) session closed for user root
Oct 30 05:08:01 Pippin CRON[20865]: (pam_unix) session opened for user root by (uid=0)
Oct 30 05:08:01 Pippin CRON[20865]: (pam_unix) session closed for user root

Can anyone shed any light on the cron sessions or the disk spinup problems?

I suggest you start a new thread about this as old threads don't seem to get much attention.

I've had no responses in the last week or so and I still have spindown problems.
My Pro Pioneer does spin down, but not till 19.30 or so.
It's on at about 07.00 and should spin down at 09.00 or so.

eg :

Nov 8 06:42:46 Pippin syslogd 1.4.1#18: restart.

Used for 1 hour or so 07.30 till 08.30

blah blah

Nov 8 19:01:42 Pippin noflushd[1897]: Spinning down disks.
Nov 9 00:00:13 Pippin noflushd[1897]: Disks spinning up after 298 minutes.

blah blah

Nov 9 00:00:27 Pippin exiting on signal 15

I upgraded the 4 drives in Pro Pioneer #1 from CC34 to CC35- had to use the force method.
Happy to report that this cured the problem I had with spin-down not working !
Must have been related to vibration ?
Also - no impact on the RAID integrity !

I'll try on Pro Pioneer #2 (mixed drives) and see whether it cures that also.

I'm happy to be able to report that updating the drive firmware also fixed the spin-down problem on the other Pro Pioneer (the one with mixed drives). Who would have known it.