On Thu, Aug 2, 2012 at 3:06 PM, David C. Rankin <drankinatty@xxxxxxxxxxxxxxxxxx> wrote: > On 08/01/2012 06:31 PM, Leonid Isaev wrote: >> >> On Wed, 01 Aug 2012 17:50:45 -0500 >> "David C. Rankin" <drankinatty@xxxxxxxxxxxxxxxxxx> 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!
