Bug 859226

Summary: iptables and other tools unable to log to rsyslog
Product: Red Hat Enterprise MRG Reporter: evcz
Component: realtime-kernelAssignee: Luis Claudio R. Goncalves <lgoncalv>
Status: CLOSED ERRATA QA Contact: David Sommerseth <davids>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 2.2CC: bhu, jkastner, lgoncalv, ovasik, williams
Target Milestone: 2.2.2   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
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.
 Story Points: ---
Clone Of: Environment:
Last Closed: 2012-12-04 19:59:14 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
fix printk flush of messages none

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