Bug 136859

Summary: acpid logs too much
Product: [openSUSE] SUSE Linux 10.1 Reporter: Bart Whiteley <bwhiteley>
Component: BasesystemAssignee: Forgotten User ZhJd0F0L3x <forgotten_ZhJd0F0L3x>
Status: VERIFIED FIXED QA Contact: E-mail List <qa-bugs>
Severity: Major    
Priority: P5 - None CC: aj, suse-beta
Version: RC 1   
Target Milestone: Beta 1   
Hardware: Other   
OS: Other   
Whiteboard:
Found By: Other Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---
Attachments: /etc/syslog-ng/syslog-ng.conf
/etc/syslog-ng/syslog-ng.conf.in

Description Bart Whiteley 2005-12-05 03:54:18 UTC
My /var/log/messages is filled with this: 
Dec  4 20:52:06 linux [acpid]: received event "battery BAT1 00000080 00000001"
Dec  4 20:52:06 linux [acpid]: notifying client 2771[0:0]
Dec  4 20:52:06 linux [acpid]: notifying client 3284[0:0]
Dec  4 20:52:06 linux [acpid]: notifying client 3250[0:0]
Dec  4 20:52:06 linux [acpid]: notifying client 3433[0:0]
Dec  4 20:52:06 linux [acpid]: notifying client 3573[1000:100]
Dec  4 20:52:06 linux [acpid]: completed event "battery BAT1 00000080 00000001"
Dec  4 20:52:06 linux [acpid]: received event "battery BAT2 00000080 00000001"
Dec  4 20:52:06 linux [acpid]: notifying client 2771[0:0]
Dec  4 20:52:06 linux [acpid]: notifying client 3284[0:0]
Dec  4 20:52:06 linux [acpid]: notifying client 3250[0:0]
Dec  4 20:52:06 linux [acpid]: notifying client 3433[0:0]
Dec  4 20:52:06 linux [acpid]: notifying client 3573[1000:100]
Dec  4 20:52:06 linux [acpid]: completed event "battery BAT2 00000080 00000001"
Dec  4 20:52:11 linux [acpid]: received event "battery BAT1 00000080 00000001"
Dec  4 20:52:11 linux [acpid]: notifying client 2771[0:0]
Dec  4 20:52:11 linux [acpid]: notifying client 3284[0:0]
Dec  4 20:52:11 linux [acpid]: notifying client 3250[0:0]
Dec  4 20:52:11 linux [acpid]: notifying client 3433[0:0]
Dec  4 20:52:11 linux [acpid]: notifying client 3573[1000:100]
Dec  4 20:52:11 linux [acpid]: completed event "battery BAT1 00000080 00000001"
Dec  4 20:52:22 linux [acpid]: received event "battery BAT1 00000080 00000001"
Dec  4 20:52:22 linux [acpid]: notifying client 2771[0:0]
Dec  4 20:52:22 linux [acpid]: notifying client 3284[0:0]
Dec  4 20:52:22 linux [acpid]: notifying client 3250[0:0]
Dec  4 20:52:22 linux [acpid]: notifying client 3433[0:0]
Dec  4 20:52:22 linux [acpid]: notifying client 3573[1000:100]
Dec  4 20:52:22 linux [acpid]: completed event "battery BAT1 00000080 00000001"
Dec  4 20:52:23 linux [acpid]: received event "battery BAT2 00000080 00000001"
Dec  4 20:52:23 linux [acpid]: notifying client 2771[0:0]
Dec  4 20:52:23 linux [acpid]: notifying client 3284[0:0]
Dec  4 20:52:23 linux [acpid]: notifying client 3250[0:0]
Dec  4 20:52:23 linux [acpid]: notifying client 3433[0:0]
Dec  4 20:52:23 linux [acpid]: notifying client 3573[1000:100]
Dec  4 20:52:23 linux [acpid]: completed event "battery BAT2 00000080 00000001"
Dec  4 20:52:39 linux [acpid]: received event "battery BAT1 00000080 00000001"
Dec  4 20:52:39 linux [acpid]: notifying client 2771[0:0]
Dec  4 20:52:39 linux [acpid]: notifying client 3284[0:0]
Dec  4 20:52:39 linux [acpid]: notifying client 3250[0:0]
Dec  4 20:52:39 linux [acpid]: notifying client 3433[0:0]
Dec  4 20:52:39 linux [acpid]: notifying client 3573[1000:100]
Dec  4 20:52:39 linux [acpid]: completed event "battery BAT1 00000080 00000001"
Dec  4 20:52:39 linux [acpid]: received event "battery BAT2 00000080 00000001"
Dec  4 20:52:39 linux [acpid]: notifying client 2771[0:0]
Dec  4 20:52:39 linux [acpid]: notifying client 3284[0:0]
Dec  4 20:52:39 linux [acpid]: notifying client 3250[0:0]
Dec  4 20:52:39 linux [acpid]: notifying client 3433[0:0]
Dec  4 20:52:39 linux [acpid]: notifying client 3573[1000:100]
Dec  4 20:52:39 linux [acpid]: completed event "battery BAT2 00000080 00000001"

It causes far too much disk I/O.  It would be nice if someone could tell me a workaround by tomorrow AM. before I take this laptop on a plane.  :)  I think my battery would last a bit longer if this were not happening.
Comment 1 Forgotten User ZhJd0F0L3x 2005-12-06 13:56:38 UTC
add something like this to /etc/syslog-ng.conf.in and call SuSEconfig afterwards:

seife@susi:/etc/syslog-ng> diff -u syslog-ng.conf.in.orig syslog-ng.conf.in
--- syslog-ng.conf.in.orig      2005-09-26 11:37:33.000000000 +0200
+++ syslog-ng.conf.in   2005-11-17 18:32:36.000000000 +0100
@@ -67,4 +67,6 @@

+filter f_acpid      { match('^\[acpid\]:'); };
 filter f_messages   { not facility(news, mail) and not
filter(f_iptables) and not filter(f_acpi_semaphore); };
 filter f_warn       { level(warn, err, crit) and not filter(f_iptables); };
 filter f_alert      { level(alert); };
@@ -124,6 +125,11 @@
 destination mail { file("/var/log/mail"); };
 log { source(src); filter(f_mail); destination(mail); };

+#
+# acpid messages in one file:
+#
+destination acpid { file("/var/log/acpid"); };
+log { source(src); filter(f_acpid); destination(acpid); flags(final); };

 #
 # Cron-messages in one file:

This will be in one of the next syslog-ng package versions.
Comment 2 Bart Whiteley 2005-12-07 00:42:23 UTC
that change to syslog-ng.conf.in worked.  I then tried to make /var/log/acpid a symlink to /dev/null.  This didn't work too well, because syslog then chmod'd /dev/null to 0640, which broke a lot of things (can't log into desktop anymore).  :)
Comment 3 Forgotten User ZhJd0F0L3x 2005-12-07 08:42:28 UTC
well, /var/log/acpid is the same file acpid always logged to, so syslog now does the same (although with a very slightly different format)
You can probably just drop the messages in sylog, but they are not that much that this would really bring any benefit, or am i overlooking something?
Comment 4 Forgotten User ZhJd0F0L3x 2005-12-07 08:54:03 UTC
ah, ok. i see, the battery argument.
Well, let me assure you that harddisk spinup/down is practically irrelevant for battery lifetime (an idle laptop disk draws ~0.65W, a spun down drive draws ~0.25W. Your machine draws ~15, so the 0.4W amount for ~8:13 minutes (on my panasonich, which has a 75Wh battery. Do not forget, that the disk will never be spun down for the whole runtime, at least not if you actually want to do something on this machine and that you will need additional power to spin up the disk).
Comment 5 Marius Tomaschewski 2006-02-08 02:39:46 UTC
I think, this is yours Stefan. Perhaps you can add a filter
to leave out some of the messages.
Comment 6 Forgotten User ZhJd0F0L3x 2006-02-08 08:17:29 UTC
i already checked in the acpid rule to syslog-ng. /var/log/acpid is not written with fsync(yes) and my harddisk is spinning down happily ever after.

Bart, since beta3 the powersaved stuff should actually work, so if you set the harddisk mode to "aggressive_powersave" in your scheme file, it should spin down. Note: this is not the "advanced powersave" scheme, which might crash the machine. Only the setting for the disk...
Comment 7 Christian Boltz 2006-04-15 00:09:48 UTC
In RC1, /var/log/messages is still flooded by acpid messages :-(
(>2/3 of the lines are caused by acpid!)

/var/log/acpid does not even exist.

/etc/syslog-ng/syslog-ng.conf.in is unmodified (according to rpm --verify), the generated syslog-ng.conf only has some additional unix-dgram entries. Both contain your change from comment #1 - but it seems it is not working :-(
Comment 8 Forgotten User ZhJd0F0L3x 2006-04-15 07:19:04 UTC
since it seems to work for everybody else, we need more information.
Please provide:
- rpm -V syslog-ng
- /etc/syslog-ng.conf{.in,}
- some acpid lines from /var/log/messages
Comment 9 Christian Boltz 2006-04-15 10:34:47 UTC
cb@cboltz:~> rpm -V syslog-ng
S.5....T  c /etc/syslog-ng/syslog-ng.conf
cb@cboltz:~>



the newest lines from /var/log/messages:
Apr 15 12:32:38 cboltz [acpid]: received event "battery BAT1 00000080 00000001"
Apr 15 12:32:38 cboltz [acpid]: notifying client 3608[0:0]
Apr 15 12:32:38 cboltz [acpid]: notifying client 3838[0:0]
Apr 15 12:32:38 cboltz [acpid]: notifying client 4291[0:0]
Apr 15 12:32:38 cboltz [acpid]: completed event "battery BAT1 00000080 00000001"
Apr 15 12:32:38 cboltz [acpid]: received event "battery BAT2 00000080 00000000"
Apr 15 12:32:38 cboltz [acpid]: notifying client 3608[0:0]
Apr 15 12:32:38 cboltz [acpid]: notifying client 3838[0:0]
Apr 15 12:32:38 cboltz [acpid]: notifying client 4291[0:0]
Apr 15 12:32:38 cboltz [acpid]: completed event "battery BAT2 00000080 00000000"
Apr 15 12:33:39 cboltz [acpid]: received event "battery BAT1 00000080 00000001"
Apr 15 12:33:39 cboltz [acpid]: notifying client 3608[0:0]
Apr 15 12:33:39 cboltz [acpid]: notifying client 3838[0:0]
Apr 15 12:33:39 cboltz [acpid]: notifying client 4291[0:0]
Apr 15 12:33:39 cboltz [acpid]: completed event "battery BAT1 00000080 00000001"
Apr 15 12:33:39 cboltz [acpid]: received event "battery BAT2 00000080 00000000"
Apr 15 12:33:39 cboltz [acpid]: notifying client 3608[0:0]
Apr 15 12:33:39 cboltz [acpid]: notifying client 3838[0:0]
Apr 15 12:33:39 cboltz [acpid]: notifying client 4291[0:0]
Apr 15 12:33:39 cboltz [acpid]: completed event "battery BAT2 00000080 00000000"
Apr 15 12:34:40 cboltz [acpid]: received event "battery BAT1 00000080 00000001"
Apr 15 12:34:40 cboltz [acpid]: notifying client 3608[0:0]
Apr 15 12:34:40 cboltz [acpid]: notifying client 3838[0:0]
Apr 15 12:34:40 cboltz [acpid]: notifying client 4291[0:0]
Apr 15 12:34:40 cboltz [acpid]: completed event "battery BAT1 00000080 00000001"
Apr 15 12:34:40 cboltz [acpid]: received event "battery BAT2 00000080 00000000"
Apr 15 12:34:40 cboltz [acpid]: notifying client 3608[0:0]
Apr 15 12:34:40 cboltz [acpid]: notifying client 3838[0:0]
Apr 15 12:34:40 cboltz [acpid]: notifying client 4291[0:0]
Apr 15 12:34:40 cboltz [acpid]: completed event "battery BAT2 00000080 00000000"
Comment 10 Christian Boltz 2006-04-15 10:36:25 UTC
Created attachment 78599 [details]
/etc/syslog-ng/syslog-ng.conf
Comment 11 Christian Boltz 2006-04-15 10:36:51 UTC
Created attachment 78600 [details]
/etc/syslog-ng/syslog-ng.conf.in
Comment 12 Forgotten User ZhJd0F0L3x 2006-04-15 11:23:00 UTC
are you using syslog-ng at all?
"chkconfig syslogd"
"chkconfig syslog-ng"
Comment 13 Forgotten User ZhJd0F0L3x 2006-04-15 11:25:51 UTC
ok, that's wrong :-)
"grep SYSLOG_DAEMON /etc/sysconfig/syslog"
determines if syslogd or syslog-ng is used.
Comment 14 Christian Boltz 2006-04-15 11:54:41 UTC
# grep SYSLOG_DAEMON /etc/sysconfig/syslog
SYSLOG_DAEMON="syslogd"

Good guess...
OK, then the syslog-ng configfile might be correct ;-)

# rpm -q syslogd
syslogd-1.4.1-555

# rpm -V syslogd
does not give any output.

Can you change /etc/syslogd.conf as well?
Comment 15 Forgotten User ZhJd0F0L3x 2006-04-15 12:06:46 UTC
no, syslogd does not provide the needed functionality. This is why syslog-ng is default now ;-)
Closing as fixed, if you disagree file a bug under "update problems".

Maybe we should mention in the release notes that after an update manual selection of syslog-ng is recommended.
Comment 16 Christian Boltz 2006-04-15 17:49:34 UTC
(In reply to comment #15)
> no, syslogd does not provide the needed functionality. This is why syslog-ng 
> is default now ;-)

OK, I just switched to syslog-ng ;-)

> Maybe we should mention in the release notes that after an update manual
> selection of syslog-ng is recommended.

Good idea - bug 166932 (hello AJ ;-)

I also noticed that syslogd was not stopped after switching to syslog-ng and "rcsyslog restart" :-( - bug 166933

Finally: I can verify that /var/log/messages is no longer flooded with acpid messages :-)

Thanks for your help!