[arch-general] Bizarre Clock Reset 8/1 -> 9/1 after apcupsd shutdown??
Myra Nelson
myra.nelson at hughes.net
Thu Aug 2 17:57:27 EDT 2012
On Thu, Aug 2, 2012 at 3:06 PM, David C. Rankin
<drankinatty at suddenlinkmail.com> wrote:
> 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.
David:
I've been experiencing the same problems, just not that much of a skip
at once. I seem to have cured the problem by replacing my cmos
battery. Don't know if that will help, but thought I'd try.
Myra
--
Life's fun when your sick and psychotic!
More information about the arch-general
mailing list