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.
