[arch-general] apcupsd or rtkit - Caused time to go haywire on shutdown/reboot??

[David C. Rankin]

Guys,

   Here is one for the brain-trust to consider. Something totally screwed up 
the time on my computer during an apcupsd commanded shutdown and the 
subsequent reboot resulting in a 479 Minute time disparity. I don't think this 
was handled on the first reboot after the power outage because after reboot, I 
worked for 20-30 minutes before the OS imploded rebooted automatically. I 
suspect the time discrepancy somehow carried through the boot and went along 
until some kernel mechanism totally went bonkers and shut the system down. In 
12 years of Linux use, this is the first time I've seen something like this 
happen. (note the time below) The log is:

Oct 18 09:21:07 providence -- MARK --
Oct 18 09:24:18 providence apcupsd[949]: Power failure.
Oct 18 09:24:24 providence apcupsd[949]: Running on UPS batteries.
Oct 18 09:24:24 providence wall[11985]: wall: user root broadcasted 1 lines 
(56 chars)
Oct 18 09:24:24 providence postfix/pickup[11962]: 3468078891: uid=0 from=<root>
Oct 18 09:24:24 providence postfix/cleanup[11988]: 3468078891: 
message-id=<20111018142424.3468078891 at providence.rlfpllc.com>
Oct 18 09:24:24 providence postfix/qmgr[1338]: 3468078891: 
from=<root at rlfpllc.com>, size=1525, nrcpt=1 (queue active)
Oct 18 09:24:24 providence postfix/smtp[11990]: 3468078891: 
to=<root at rlfpllc.com>, orig_to=<root>, 
relay=phoenix.rlfpllc.com[192.168.7.15]:25, delay=0.13, 
delays=0.07/0.01/0.02/0.04, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 
4699114AB47)
Oct 18 09:24:24 providence postfix/qmgr[1338]: 3468078891: removed
Oct 18 09:25:16 providence shutdown[13133]: shutting down for system halt
Oct 18 09:25:17 providence init: Switching to runlevel: 0
Oct 18 14:25:18 providence rtkit-daemon[2768]: Exiting cleanly.
Oct 18 14:25:18 providence rtkit-daemon[2768]: Demoting known real-time threads.
Oct 18 14:25:18 providence rtkit-daemon[2768]: Successfully demoted thread 
2766 of process 2766 (/usr/bin/pulseaudio (deleted)).
Oct 18 14:25:18 providence rtkit-daemon[2768]: Demoted 1 threads.
Oct 18 14:25:18 providence rtkit-daemon[2768]: Exiting watchdog thread.
Oct 18 14:25:18 providence rtkit-daemon[2768]: Exiting canary thread.
Oct 18 09:25:18 providence apcupsd[949]: apcupsd exiting, signal 15
Oct 18 09:25:19 providence apcupsd[949]: apcupsd shutdown succeeded
Oct 18 09:25:19 providence nmbd[1339]: [2011/10/18 09:25:19.139254,  0] 
nmbd/nmbd.c:66(terminate)
Oct 18 09:25:19 providence nmbd[1339]:   Got SIGTERM: going down...
Oct 18 09:25:19 providence postfix/postfix-script[13294]: stopping the Postfix 
mail system
Oct 18 09:25:19 providence postfix/postfix-script[13297]: waiting for the 
Postfix mail system to terminate
Oct 18 09:25:19 providence postfix/master[1330]: terminating on signal 15
Oct 18 09:25:22 providence ntpd[944]: ntpd exiting on signal 15
Oct 18 09:25:22 providence dhcpcd[13471]: sending signal 1 to pid 762
Oct 18 09:25:22 providence dhcpcd[762]: received SIGHUP, releasing
Oct 18 09:25:22 providence dhcpcd[762]: eth0: releasing lease of 192.168.7.124
Oct 18 09:25:22 providence dhcpcd[13471]: waiting for pid 762 to exit
Oct 18 09:25:23 providence dhcpcd[762]: eth0: removing interface
Oct 18 09:25:23 providence kernel: [518721.438558] tg3 0000:02:00.0: PME# enabled
Oct 18 09:25:23 providence kernel: [518721.438578] pcieport 0000:00:1c.0: 
wake-up capability enabled by ACPI
Oct 18 09:25:25 providence ntfs-3g[524]: Unmounting /dev/sdb2 ()
Oct 18 09:25:25 providence syslog-ng[707]: Termination requested via signal, 
terminating;
Oct 18 09:25:25 providence syslog-ng[707]: syslog-ng shutting down; 
version='3.2.4'
Oct 18 17:28:06 providence kernel: [    0.000000] Initializing cgroup subsys 
cpuset
Oct 18 17:28:06 providence kernel: [    0.000000] Initializing cgroup subsys cpu
Oct 18 17:28:06 providence kernel: [    0.000000] Linux version 3.0-ARCH 
(tobias at T-POWA-LX) (gcc version 4.6.1 20110819 (prerelease) (GCC) ) #1 SMP 
PREEMPT Fri Oct 7 10:11:05 UTC 2011
Oct 18 17:28:06 providence kernel: [    0.000000] BIOS-provided physical RAM map:
Oct 18 17:28:06 providence kernel: [    0.000000]  BIOS-e820: 0000000000000000 
- 00000000000a0000 (usable)

   I understand the jump from 09:25:17 to 14:25:18, that just reflects the 
tzoffset for CDT. What I can't explain is the 09:25:25 to 17:28:06 jump. The 
power was only out for 5 minutes and the box booted as soon as power was 
restored. The log entry after reboot that caught my eye was:

Oct 18 11:19:01 providence crond[978]: time disparity of -479 minutes detected

   I don't have a clue what could have caused this time shift unless it was 
some spurious voltage issue. If not, then something is definitely funny with 
the time handling in either apcupsd or rtkit.

   What say the experts, problem or just weird voltage induced time skew?


-- 
David C. Rankin, J.D.,P.E.