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.3468078...@providence.rlfpllc.com> -~> Oct 18 09:24:24 providence postfix/qmgr[1338]: 3468078891: -~> from=<r...@rlfpllc.com>, size=1525, nrcpt=1 (queue active) -~> Oct 18 09:24:24 providence postfix/smtp[11990]: 3468078891: -~> to=<r...@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@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
pgpEE87p6RZ9J.pgp
Description: PGP signature
