On Thu, Aug 2, 2012 at 3:06 PM, David C. Rankin <drankinatty@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@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@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@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@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@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@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!