[arch-general] Bizarre Clock Reset 8/1 -> 9/1 after apcupsd shutdown??

[David C. Rankin]

On 08/01/2012 06:31 PM, Leonid Isaev wrote:
> On Wed, 01 Aug 2012 17:50:45 -0500
> "David C. Rankin" <drankinatty at suddenlinkmail.com> wrote:
>>
>> The only config change I can see in the apcupsd.conf.pacnew is:
>>
>> LOCKFILE /var/lock  ->  LOCKFILE /etc/apcupsd
>>
>> I can't see that causing a segfault, could it?
>
> I don't think so, no. But since something does, I would look at what has been
> updated lately (apcupsd for example).
>
> On a side note... I don't use this application (although I do have an APC UPS
> unit) but this entry looks very wrong -- is it a lockfile in /etc? Also, I
> quickly skimmed through the initscript in /etc/rc.d/apcupsd, at it also does
> few writes to /etc. Unless this is absolutely necessary, such behavior
> represents a bug and is in violation of FHS.
>

Something is FUBAR with apcupsd. I am running the package from the community 
repo, so it might need looking at.

>>
>>
>>>> Aug  1 13:20:15 providence ntpd[3454]: Listen normally on 6 eth0
>>>> 192.168.7.124 UDP 123
>>>> Aug  1 13:20:15 providence ntpd[3454]: peers refreshed
>>>> Aug  1 13:20:15 providence ntpd[3454]: new interface(s) found: waking up
>>>> resolver Aug  1 13:20:15 providence postfix/postfix-script[13735]:
>>>> stopping the Postfix mail system
>>>> Aug  1 13:20:15 providence postfix/master[3868]: terminating on signal 15
>>>> Aug  1 13:20:15 providence postfix/postfix-script[13738]: waiting for the
>>>> Postfix mail system to terminate
>>>> Aug  1 13:20:16 providence dhcpcd[424]: eth0: sending IPv6 Router
>>>> Solicitation Aug  1 13:20:19 providence ntpd[3454]: ntpd exiting on
>>>> signal 15
>>>
>>> Your NTP behaves strangely... why would it refresh timeservers and then
>>> shutdown at the same timestamp? It looks like your ntp did something funny
>>> and incorrectly adjusted the HW clock.
>>
>> Now that you mention it, I don't know why it would refresh at shutdown. I
>> think this is just a normal log event that occurred between the time the
>> apcupsd shutdown was commanded at 13:20:15 and the ntpd refresh at 13:20:15.
>> I just don't think ntpd had time to get the message yet...
>
> Well, unless you have hwclock daemon, ntpd is the only thing which affects HW
> clock.
>

   No, it's ntpd and it WAS the problem. This issue started a couple of weeks 
ago. This box usually just sits idle. Going though the various log files, you 
can see it happening and then switching back -- really strange. The history is 
laid out below, but it appears that the hdwclock got zapped by ntpd on a Jul 
11 reboot. Then the system would correct itself and run until the next reboot 
and read the hdwclock again and go though the same cycle. I've never seen 
anything like it and I can't explain it. hdwclock tracks sysclock fine, but we 
have seen some weird things in the past, but never by a whole month.

   It did screw up the cronstamps:

[14:59 providence:/var/spool] # l cronstamps/
total 28
drwxr-xr-x 2 root root 4096 May  4  2011 .
drwxr-xr-x 9 root root 4096 Jul 27 19:28 ..
-rw-r--r-- 1 root root   16 Aug 30  2012 root.prune-cronstamps
-rw-r--r-- 1 root root   16 Jul 23 14:22 root.sys-daily
-rw-r--r-- 1 root root   16 Sep  1  2012 root.sys-hourly
-rw-r--r-- 1 root root   16 Aug 12  2012 root.sys-monthly
-rw-r--r-- 1 root root   16 Aug 30  2012 root.sys-weekly


   For the curios, here is the log history:


   In the everything.log.4 I think I found the fist event:

Jul 11 13:53:12 providence shutdown[1939]: shutting down for system reboot
Jul 11 13:53:13 providence init: Switching to runlevel: 6
Jul 11 13:53:14 providence ntfs-3g[290]: Unmounting /dev/sdb2 ()
Jul 11 18:53:14 providence rtkit-daemon[1536]: Exiting cleanly.
Jul 11 18:53:14 providence rtkit-daemon[1536]: Demoting known real-time threads.
Jul 11 18:53:14 providence rtkit-daemon[1536]: Successfully demoted thread 
1534 of process 1534 (/usr/bin/pulseaudio).
Jul 11 18:53:14 providence rtkit-daemon[1536]: Demoted 1 threads.
Jul 11 18:53:14 providence rtkit-daemon[1536]: Exiting watchdog thread.
Jul 11 18:53:14 providence rtkit-daemon[1536]: Exiting canary thread.
Jul 11 13:53:14 providence apcupsd[1082]: apcupsd exiting, signal 15
Jul 11 13:53:14 providence apcupsd[1082]: apcupsd shutdown succeeded
Jul 11 13:53:15 providence postfix/postfix-script[2116]: stopping the Postfix 
mail system
Jul 11 13:53:15 providence postfix/master[1247]: terminating on signal 15
Jul 11 13:53:16 providence ntpd[870]: ntpd exiting on signal 15
Jul 11 13:53:16 providence dhcpcd[2234]: sending signal 1 to pid 413
Jul 11 13:53:16 providence dhcpcd[413]: received SIGHUP, releasing
Jul 11 13:53:16 providence dhcpcd[413]: eth0: releasing lease of 192.168.7.124
Jul 11 13:53:16 providence dhcpcd[2234]: waiting for pid 413 to exit
Jul 11 13:53:16 providence dhcpcd[413]: eth0: removing interface
Jul 11 13:53:16 providence kernel: [  977.567012] pcieport 0000:00:1c.0: 
wake-up capability enabled by ACPI
Jul 11 13:53:16 providence syslog-ng[352]: syslog-ng shutting down; 
version='3.3.5'
Aug 12 02:00:38 providence kernel: [    0.000000] Initializing cgroup subsys 
cpuset
Aug 12 02:00:38 providence kernel: [    0.000000] Initializing cgroup subsys cpu
Aug 12 02:00:38 providence kernel: [    0.000000] Linux version 3.4.4-2-ARCH 
(tobias at T-POWA-LX) (gcc version 4.7.1 (GCC) ) #1 SMP PREEMPT Sun Jun 24 
17:28:37 UTC 2012

   Then in everything.log.3 you have:

Aug 12 02:01:01 providence syslog-ng[347]: Configuration reload request 
received, reloading configuration;
Aug 12 02:01:02 providence kernel: [   43.154701] NVRM: Your system is not 
currently configured to drive a VGA console
Aug 12 02:01:02 providence kernel: [   43.154712] NVRM: on the primary VGA 
device. The NVIDIA Linux graphics driver
Aug 12 02:01:02 providence kernel: [   43.154719] NVRM: requires the use of a 
text-mode VGA console. Use of other console
Aug 12 02:01:02 providence kernel: [   43.154726] NVRM: drivers including, but 
not limited to, vesafb, may result in
Aug 12 02:01:02 providence kernel: [   43.154732] NVRM: corruption and 
stability problems, and is not supported.
Jul 12 07:04:14 providence crond[860]: time disparity of -44339 minutes detected
Jul 12 07:11:39 providence crond[16097]: mailing cron output for user root job 
sys-daily
Jul 12 07:11:40 providence postfix/pickup[1271]: 5079277CBD: uid=0 from=<root>
Jul 12 07:11:40 providence postfix/cleanup[16099]: 5079277CBD:

   Continuing through everything.log.3 it flip-flops:

Jul 12 13:49:24 providence shutdown[16268]: shutting down for system reboot
Jul 12 13:49:24 providence init: Switching to runlevel: 6
Jul 12 13:49:26 providence ntfs-3g[285]: Unmounting /dev/sdb2 ()
Jul 12 13:49:26 providence apcupsd[874]: apcupsd exiting, signal 15
Jul 12 13:49:26 providence apcupsd[874]: apcupsd shutdown succeeded
Jul 12 13:49:26 providence nmbd[1196]: [2012/07/12 13:49:26.819823,  0] 
nmbd/nmbd.c:66(terminate)
Jul 12 13:49:26 providence nmbd[1196]:   Got SIGTERM: going down...
Jul 12 13:49:27 providence postfix/postfix-script[16441]: stopping the Postfix 
mail system
Jul 12 13:49:27 providence postfix/master[1258]: terminating on signal 15
Jul 12 13:49:28 providence ntpd[881]: ntpd exiting on signal 15
Jul 12 13:49:28 providence dhcpcd[16559]: sending signal 1 to pid 409
Jul 12 13:49:28 providence dhcpcd[409]: received SIGHUP, releasing
Jul 12 13:49:28 providence dhcpcd[409]: eth0: releasing lease of 192.168.7.124
Jul 12 13:49:28 providence dhcpcd[16559]: waiting for pid 409 to exit
Jul 12 13:49:28 providence dhcpcd[409]: eth0: removing interface
Jul 12 13:49:28 providence kernel: [24546.547985] pcieport 0000:00:1c.0: 
wake-up capability enabled by ACPI
Jul 12 13:49:28 providence syslog-ng[347]: syslog-ng shutting down; 
version='3.3.5'
Aug 12 15:25:57 providence kernel: [    0.000000] Initializing cgroup subsys 
cpuset
Aug 12 15:25:57 providence kernel: [    0.000000] Initializing cgroup subsys cpu
Aug 12 15:25:57 providence kernel: [    0.000000] Linux version 3.4.4-2-ARCH 
(tobias at T-POWA-LX) (gcc version 4.7.1 (GCC) ) #1 SMP PREEMPT Sun Jun 24 
17:28:37 UTC 2012

<snip>

Aug 12 15:26:13 providence postfix/postfix-script[1251]: starting the Postfix 
mail system
Aug 12 15:26:13 providence postfix/master[1252]: daemon started -- version 
2.9.3, configuration /etc/postfix
Aug 12 15:26:19 providence kernel: [   40.002496] NVRM: Your system is not 
currently configured to drive a VGA console
Aug 12 15:26:19 providence kernel: [   40.002506] NVRM: on the primary VGA 
device. The NVIDIA Linux graphics driver
Aug 12 15:26:19 providence kernel: [   40.002513] NVRM: requires the use of a 
text-mode VGA console. Use of other console
Aug 12 15:26:19 providence kernel: [   40.002519] NVRM: drivers including, but 
not limited to, vesafb, may result in
Aug 12 15:26:19 providence kernel: [   40.002525] NVRM: corruption and 
stability problems, and is not supported.
Aug 12 15:27:01 providence crond[862]: FILE /var/spool/cron/root USER root PID 
1310 job sys-hourly
Jul 12 20:30:01 providence crond[862]: time disparity of -44339 minutes detected
Jul 12 20:50:01 providence -- MARK --
Jul 12 21:10:01 providence -- MARK --

<snip>

Jul 13 09:35:51 providence shutdown[6698]: shutting down for system reboot
Jul 13 09:35:52 providence init: Switching to runlevel: 6
Jul 13 09:35:53 providence ntfs-3g[288]: Unmounting /dev/sdb2 ()
Jul 13 09:35:53 providence apcupsd[867]: apcupsd exiting, signal 15
Jul 13 09:35:53 providence apcupsd[867]: apcupsd shutdown succeeded
Jul 13 09:35:54 providence postfix/postfix-script[6871]: stopping the Postfix 
mail system
Jul 13 09:35:54 providence postfix/master[1252]: terminating on signal 15
Jul 13 09:35:55 providence ntpd[870]: ntpd exiting on signal 15
Jul 13 09:35:55 providence dhcpcd[6989]: sending signal 1 to pid 411
Jul 13 09:35:55 providence dhcpcd[6989]: waiting for pid 411 to exit
Jul 13 09:35:55 providence dhcpcd[411]: received SIGHUP, releasing
Jul 13 09:35:55 providence dhcpcd[411]: eth0: releasing lease of 192.168.7.124
Jul 13 09:35:55 providence dhcpcd[411]: eth0: removing interface
Jul 13 09:35:55 providence kernel: [47416.619033] pcieport 0000:00:1c.0: 
wake-up capability enabled by ACPI
Jul 13 09:35:55 providence syslog-ng[350]: syslog-ng shutting down; 
version='3.3.5'
Aug 13 09:37:16 providence kernel: [    0.000000] Initializing cgroup subsys 
cpuset
Aug 13 09:37:16 providence kernel: [    0.000000] Initializing cgroup subsys cpu
Aug 13 09:37:16 providence kernel: [    0.000000] Linux version 3.4.4-2-ARCH 
(tobias at T-POWA-LX) (gcc version 4.7.1 (GCC) ) #1 SMP PREEMPT Sun Jun 24 
17:28:37 UTC 2012

<snip>

Aug 13 09:38:19 providence pulseaudio[1668]: [pulseaudio] bluetooth-util.c: 
org.bluez.Manager.ListAdapters() failed: 
org.freedesktop.DBus.Error.Spawn.ChildExited: Launch helper exited with 
unknown return code 1
Aug 13 09:38:26 providence pulseaudio[1794]: [pulseaudio] pid.c: Daemon 
already running.
Aug 13 09:38:26 providence pulseaudio[1798]: [pulseaudio] pid.c: Daemon 
already running.
Aug 13 09:38:33 providence kernel: [   95.078975] EXT4-fs (sdc5): re-mounted. 
Opts: commit=0
Aug 13 09:38:33 providence kernel: [   95.848878] EXT4-fs (sdc7): re-mounted. 
Opts: commit=0
Jul 13 09:40:51 providence crond[865]: time disparity of -44639 minutes detected

   It happens a couple more times in everything.log.3, then we get to 
everything.log.2:

Aug 20 11:24:02 providence syslog-ng[353]: Configuration reload request 
received, reloading configuration;
Aug 20 11:25:02 providence kernel: [  251.345882] EXT4-fs (sdc5): re-mounted. 
Opts: commit=0
Aug 20 11:25:03 providence kernel: [  252.552472] EXT4-fs (sdc7): re-mounted. 
Opts: commit=0
Jul 20 11:26:31 providence crond[3051]: time disparity of -44639 minutes detected

<snip>

Jul 23 14:05:53 providence shutdown[30324]: shutting down for system reboot
Jul 23 14:05:54 providence init: Switching to runlevel: 6
Jul 23 14:05:56 providence ntfs-3g[291]: Unmounting /dev/sdb2 ()
Jul 23 19:05:56 providence rtkit-daemon[3729]: Exiting cleanly.
Jul 23 19:05:56 providence rtkit-daemon[3729]: Demoting known real-time threads.
Jul 23 19:05:56 providence rtkit-daemon[3729]: Successfully demoted thread 
3727 of process 3727 (/usr/bin/pulseaudio).
Jul 23 19:05:56 providence rtkit-daemon[3729]: Demoted 1 threads.
Jul 23 19:05:56 providence rtkit-daemon[3729]: Exiting watchdog thread.
Jul 23 19:05:56 providence rtkit-daemon[3729]: Exiting canary thread.
Jul 23 14:05:56 providence apcupsd[3082]: apcupsd exiting, signal 15
Jul 23 14:05:56 providence apcupsd[3082]: apcupsd shutdown succeeded
Jul 23 14:05:56 providence nmbd[3396]: [2012/07/23 14:05:56.875158,  0] 
nmbd/nmbd.c:66(terminate)
Jul 23 14:05:56 providence nmbd[3396]:   Got SIGTERM: going down...
Jul 23 14:05:58 providence postfix/postfix-script[30496]: stopping the Postfix 
mail system
Jul 23 14:05:58 providence postfix/postfix-script[30499]: waiting for the 
Postfix mail system to terminate
Jul 23 14:05:58 providence postfix/master[3464]: terminating on signal 15
Jul 23 14:06:01 providence ntpd[3058]: ntpd exiting on signal 15
Jul 23 14:06:01 providence dhcpcd[30644]: sending signal 1 to pid 414
Jul 23 14:06:01 providence dhcpcd[30644]: waiting for pid 414 to exit
Jul 23 14:06:01 providence dhcpcd[414]: received SIGHUP, releasing
Jul 23 14:06:01 providence dhcpcd[414]: eth0: releasing lease of 192.168.7.124
Jul 23 14:06:01 providence dhcpcd[414]: eth0: removing interface
Jul 23 14:06:01 providence kernel: [269110.573529] pcieport 0000:00:1c.0: 
wake-up capability enabled by ACPI
Jul 23 14:06:01 providence syslog-ng[353]: syslog-ng shutting down; 
version='3.3.5'
Aug 23 14:08:34 providence kernel: [    0.000000] Initializing cgroup subsys 
cpuset
Aug 23 14:08:34 providence kernel: [    0.000000] Initializing cgroup subsys cpu
Aug 23 14:08:34 providence kernel: [    0.000000] Linux version 3.4.6-1-ARCH 
(tobias at T-POWA-LX) (gcc version 4.7.1 (GCC) ) #1 SMP PREEMPT Fri Jul 20 
07:24:45 UTC 2012

<snip>

Aug 23 14:11:38 providence kernel: [  322.982157] EXT4-fs (sdc5): re-mounted. 
Opts: commit=0
Aug 23 14:11:38 providence kernel: [  323.759352] EXT4-fs (sdc7): re-mounted. 
Opts: commit=0
Aug 23 14:13:05 providence kernel: [  409.951135] FS-Cache: Loaded
Aug 23 14:13:05 providence kernel: [  409.961788] FS-Cache: Netfs 'cifs' 
registered for caching
Aug 23 14:13:05 providence kernel: [  409.984001] CIFS VFS: default security 
mechanism requested.  The default security mechanism will be upgraded from 
ntlm to ntlmv2 in kernel release 3.3
Jul 23 14:13:52 providence crond[3182]: time disparity of -44639 minutes detected
Jul 23 14:22:55 providence crond[18915]: mailing cron output for user root job 
sys-daily

<snip> continues correct time until July 30 in everything.log:

Jul 30 13:48:20 providence shutdown[32078]: shutting down for system reboot
Jul 30 13:48:21 providence init: Switching to runlevel: 6
Jul 30 13:48:22 providence ntfs-3g[287]: Unmounting /dev/sdb2 ()
Jul 30 13:48:23 providence nmbd[3527]: [2012/07/30 13:48:23.397472,  0] 
nmbd/nmbd.c:66(terminate)
Jul 30 13:48:23 providence nmbd[3527]:   Got SIGTERM: going down...
Jul 30 18:48:23 providence rtkit-daemon[4562]: Exiting cleanly.
Jul 30 18:48:23 providence rtkit-daemon[4562]: Demoting known real-time threads.
Jul 30 18:48:23 providence rtkit-daemon[4562]: Successfully demoted thread 
4560 of process 4560 (/usr/bin/pulseaudio).
Jul 30 18:48:23 providence rtkit-daemon[4562]: Demoted 1 threads.
Jul 30 18:48:23 providence rtkit-daemon[4562]: Exiting watchdog thread.
Jul 30 18:48:23 providence rtkit-daemon[4562]: Exiting canary thread.
Jul 30 13:48:23 providence apcupsd[3190]: apcupsd exiting, signal 15
Jul 30 13:48:24 providence apcupsd[3190]: apcupsd shutdown succeeded
Jul 30 13:48:24 providence kernel: [603728.758431] apcupsd[3190]: segfault at 
0 ip 0805e0fc sp bfe397c0 error 4 in apcupsd (deleted)[8048000+39000]
Jul 30 13:48:24 providence postfix/postfix-script[32294]: stopping the Postfix 
mail system
Jul 30 13:48:24 providence postfix/postfix-script[32297]: waiting for the 
Postfix mail system to terminate
Jul 30 13:48:24 providence postfix/master[3582]: terminating on signal 15
Jul 30 13:48:27 providence ntpd[3192]: ntpd exiting on signal 15
Jul 30 13:48:27 providence dhcpcd[32443]: sending signal 1 to pid 410
Jul 30 13:48:27 providence dhcpcd[410]: received SIGHUP, releasing
Jul 30 13:48:27 providence dhcpcd[410]: eth0: releasing lease of 192.168.7.124
Jul 30 13:48:27 providence dhcpcd[32443]: waiting for pid 410 to exit
Jul 30 13:48:27 providence dhcpcd[410]: eth0: removing interface
Jul 30 13:48:27 providence kernel: [603732.640067] pcieport 0000:00:1c.0: 
wake-up capability enabled by ACPI
Jul 30 13:48:28 providence syslog-ng[349]: syslog-ng shutting down; 
version='3.3.5'
Aug 30 13:49:01 providence kernel: [    0.000000] Initializing cgroup subsys 
cpuset
Aug 30 13:49:01 providence kernel: [    0.000000] Initializing cgroup subsys cpu
Aug 30 13:49:01 providence kernel: [    0.000000] Linux version 3.4.7-1-ARCH 
(tobias at T-POWA-LX) (gcc version 4.7.1 20120721 (prerelease) (GCC) ) #1 SMP 
PREEMPT Sun Jul 29 20:05:01 UTC 2012


   In the boot log, you can clearly see it happened:

Wed Jul 11 13:37:27 2012: :: Starting netfs    [BKGD]
Wed Jul 11 13:37:27 2012: :: Starting ntpd    [BKGD]
Wed Jul 11 13:37:27 2012: :: Starting sshd    [BKGD]
Wed Jul 11 13:37:27 2012: :: Starting crond    [BKGD]
Wed Jul 11 13:37:27 2012: :: Starting mysqld    [BKGD]
Wed Jul 11 13:37:27 2012: :: Starting postfix    [BKGD]
Wed Jul 11 13:37:27 2012: :: Starting cups    [BKGD]
Wed Jul 11 13:37:27 2012: :: Starting samba    [BKGD]
Wed Jul 11 13:37:27 2012: :: Starting apcupsd    [BKGD]
Sun Aug 12 02:00:34 2012: :: Adjusting system time and setting kernel timezone 
    [BUSY]    [DONE]
Sun Aug 12 02:00:34 2012: :: Starting UDev Daemon    [BUSY]    [DONE]
Sun Aug 12 02:00:34 2012: :: Triggering UDev uevents    [BUSY]    [DONE]
Sun Aug 12 02:00:34 2012: :: Loading User-specified Modules    [BUSY]    [DONE]
Sun Aug 12 02:00:34 2012: :: Waiting for UDev uevents to be processed 
[BUSY]    [DONE]
Sun Aug 12 02:00:34 2012: :: Configuring Virtual Consoles    [BUSY] %G   [DONE]
Sun Aug 12 02:00:34 2012: :: Bringing up loopback interface    [BUSY]    [DONE]

   I hope I don't see this again :)

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