Bug 859226 - iptables and other tools unable to log to rsyslog
Summary: iptables and other tools unable to log to rsyslog
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: realtime-kernel
Version: 2.2
Hardware: x86_64
OS: Linux
unspecified
urgent
Target Milestone: 2.2.2
: ---
Assignee: Luis Claudio R. Goncalves
QA Contact: David Sommerseth
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-09-20 20:30 UTC by evcz
Modified: 2016-05-22 23:35 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Cause: A subtlety in the relation between preemption depth (preempt_count) and the raw spinlocks in the PREEMPT_RT based kernels led to a context where printk buffers were never flushed to the console. Consequence: Some time after boot, after a certain condition was triggered, kernel generated log would stop reaching the console and system log (rsyslog). Fix: That specific verification of the preempt_count variable was adapted to the reality of the Realtime kernel. Result: Logs generated by the kernel are successfully sent to both the console and the system log, according to the system configuration.
Clone Of:
Environment:
Last Closed: 2012-12-04 19:59:14 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
fix printk flush of messages (1.95 KB, patch)
2012-09-26 16:05 UTC, Luis Claudio R. Goncalves
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 786083 0 unspecified CLOSED iptables unable to log to rsyslog 2021-02-22 00:41:40 UTC
Red Hat Product Errata RHSA-2012:1491 0 normal SHIPPED_LIVE Important: kernel-rt security and bug fix update 2012-12-05 00:50:25 UTC

Description evcz 2012-09-20 20:30:07 UTC
Description of problem:
Upgraded to 3.2.23-rt37.56.el6rt.x86_64 

but I'm still seeing the issue that was described here:
https://bugzilla.redhat.com/show_bug.cgi?id=786083
that was said to have been fixed in errata RHSA-2012-1282

Version-Release number of selected component (if applicable):
3.2.23-rt37.56.el6rt.x86_64

How reproducible:
everytime

Steps to Reproduce:
1. Make a clean OS install
2. install kernel-rt
3. reboot into kernel-rt
4. issue this command:
tcpdump
let it run for a few seconds then CTRL^C

5. run 
tail /var/log/messages
  
Actual results:
nothing got logged

Expected results:
device eth0 entered promiscuous mode
device eth0 left promiscuous mode

Additional info:
Same thing happens with iptables loggin as described into bz786083

sample iptables test lines:
iptables -I INPUT 1 -m limit --limit 100/m  --limit-burst 100 -j LOG --log-level 4 --log-ip-options --log-prefix "Test iptables logging: "

issuing
echo 5 > /proc/sysrq-trigger

forces the kernel to get everything from dmesg and log it, but it stops right there, nothing new get logged after that...
In the previous kernel version instead that work around was generally working for a few hours

I'll try to wipe the machine, reinstall it from scratch and skip the 3.0.x upgrades as this test was done on an already up-to-data machine with minor changes to the minimal install

Comment 1 evcz 2012-09-21 10:23:15 UTC
don't know if this might be useful...

noticed that when pushing the system resulting in:

"kernel: sched: RT throttling activated"

logged also previous log lines get written to messages

Comment 2 Luis Claudio R. Goncalves 2012-09-21 13:50:56 UTC
The "kernel: sched: RT throttling activated" message means RT tasks have been running uninterruptedly, leaving no time for the non-RT tasks to run. As that may lead the system to an unconsistent state, there is a tunable failsafe that will preempt the RT tasks and let the non-RT tasks run for a giver period of time.

The bandwidth limiting of RT tasks is controlled by:

   /proc/sys/kernel/sched_rt_period_us
   /proc/sys/kernel/sched_rt_runtime_us

The default is a 950000us runtime with a period of 1000000us. So, if RT tasks have been running for more than 950ms in the last 1s, they are throttled so that non-RT tasks have a minimal CPU share.

Writing "-1" to /proc/sys/kernel/sched_rt_runtime_us disables the bandwidth limitting.

The other interesting datapoint is that if you are seeing this message you either have a CPU hog task running on your system (that could be startving other kernel threads -- leading to delays in logging and other tasks) or you have a very old version of _rtctl_ that is unaware of the kernel threads naming change in MRG-2.2.

I suggest updating rtctl first and running the tests again, to confirm.

Comment 3 evcz 2012-09-21 13:59:57 UTC
Hi,

that "error" got written into the log while I was trying to stress test a machine (xeon e1230 (4xcore + 4xHT)) with 8 tasks running in realtime using "100% CPU" each one

The issue I'm reporting here is that logging to syslog does not work (either from iptables and nor from other tools like network when using tcpdump in promiscuos mode)... the only time I saw logging working was during that specific "stress test".

rtctl should be already up-to-date:

rpm -qa rtctl
rtctl-1.9-5.el6rt.noarch

Comment 4 evcz 2012-09-24 10:01:28 UTC
tried on another server with a new install.

and can confirm that issuing:

iptables -I INPUT 1 -m limit --limit 100/m  --limit-burst 100 -j LOG --log-level 4 --log-ip-options --log-prefix "Test iptables logging: "

results in nothing being logged to /var/log/messages

Comment 5 Luis Claudio R. Goncalves 2012-09-24 22:31:58 UTC
Could you please run a test?

When ran the iptables command line you suggested, I saw the data on dmesg but noticed it was not reproduced on the console. When I ran the command line below, during the time it took to complete the command, there was output from iptables at the console. The command line was:

    cat /proc/consoles

Comment 6 evcz 2012-09-24 22:36:34 UTC
yes, can confirm that issuing:

cat /proc/consoles

resulted in data being logged while the task was running.

That's similar to what happens when pushing the system till the "RT throttling activated" kicks in.

Comment 7 Luis Claudio R. Goncalves 2012-09-26 16:05:00 UTC
Created attachment 617625 [details]
fix printk flush of messages

Thanks Steven Rostedt for pointing me out to this patch sent by Frank Rowand. This patch indeed solves the issue.

We are just verifying whether we will be able to release a hotfix kernel containing this change or it will be part of the next Errata kernel.

---

Comment 8 Luis Claudio R. Goncalves 2012-09-26 16:11:00 UTC
It will be released soon as a hotfix kernel.

Comment 9 evcz 2012-09-27 11:52:25 UTC
sounds great

let me know if I've to do some betatesting, got a few spare machines I can experiment on.

thank you,
best regards

Comment 16 errata-xmlrpc 2012-12-04 19:59:14 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2012-1491.html


Note You need to log in before you can comment on or make changes to this bug.