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

[Leonid Isaev]

On (10/18/11 11:55), David C. Rankin wrote:
-~> 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.

Well, a simple search shows that rtkit has an open bug report,
https://bugzilla.redhat.com/show_bug.cgi?id=698040, which explains why you have
its logs in UTC. Regarding the rest, are you saying the system spontaneously
rebooted after a successfull recovery from power outage? Also, what does grep
"system clock" /var/log/messages.log say?

-- 
Leonid Isaev
GnuPG key ID: 164B5A6D
Key fingerprint: C0DF 20D0 C075 C3F1 E1BE  775A A7AE F6CB 164B 5A6D
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 490 bytes
Desc: not available
URL: <http://mailman.archlinux.org/pipermail/arch-general/attachments/20111018/be0a1b1d/attachment.asc>