rsyslog ignores iptables LOG targets

[Brownout]

Binary package hint: rsyslog

Ubuntu Karmic 9.10 Beta, rsyslog 4.2.0-2ubuntu4

First rule of the INPUT chain in iptables:
LOG tcp -- 0.0.0.0/0 0.0.0.0/0 tcp dpt:80 LOG flags 0 level 4 prefix `FW_TEST: '

Connection attempts matching that rule don't get logged anywhere; I added a a couple of rules to the default config (attached file) for debugging, still nothing.

Grepping /var/log/* for FW_TEST doesn't find anything; grepping dmesg shows what's expected, e.g.:
[ 7218.452367] FW_TEST: IN=lo OUT= MAC=00:00:00:00:00:00:00:00:00:00:00:00:08:00 SRC=127.0.0.1 DST=127.0.0.1 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=36999 DF PROTO=TCP SPT=34540 DPT=80 WINDOW=32792 RES=0x00 SYN URGP=0

[Michael Terry (mterry)]

I did some simple testing. I could make 'contains' work, but not 'startswith'. If you change your config to use 'contains' FW_TEST instead and then do a 'sudo restart rsyslog', do things work? If so, we can change this bug into one about just startswith.

[Brownout (brownout)]

:msg, contains, "FW_TEST" /var/log/firewall
It catches the sudo command line used to add the test rule:
Oct 13 18:59:54 grid sudo: brownout : TTY=pts/1 ; PWD=/home/brownout ; USER=root ; COMMAND=/sbin/iptables -I INPUT -p tcp --dport 80 -j LOG --log-prefix FW_TEST:

but it doesn't log the connection attempt, which is correctly reported in dmesg:
[65180.603408] FW_TEST: IN=lo OUT= MAC=00:00:00:00:00:00:00:00:00:00:00:00:08:00 SRC=127.0.0.1 DST=127.0.0.1 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=19095 DF PROTO=TCP SPT=60757 DPT=80 WINDOW=32792 RES=0x00 SYN URGP=0

[Michael Terry (mterry)]

You may be having a more generic problem with rsyslog not grabbing your kernel messages. If you plug/unplug a USB thumbdrive, do you see messages in both dmesg and /var/log/syslog?

If you don't, you *may* be experiencing a regression from bug 430220 not yet being applied (rsyslog is currently incorrectly buffering messages from the kernel, so there's a delay before handling them) or something new.

[Brownout (brownout)]

You're right, sometimes the plug/unplug gets recorded in syslog, sometimes doesn't.

USB thumbdrive plugged, dmesg:
[74543.280021] usb 1-3: new high speed USB device using ehci_hcd and address 8
[74543.434198] usb 1-3: configuration #1 chosen from 1 choice
[74543.437453] scsi8 : SCSI emulation for USB Mass Storage devices
[74543.438016] usb-storage: device found at 8
[74543.438020] usb-storage: waiting for device to settle before scanning
[74548.430169] usb-storage: device scan complete
[74548.432272] scsi 8:0:0:0: Direct-Access PEAK III Flash Drive 0.00 PQ: 0 ANSI: 2
[74548.432801] sd 8:0:0:0: Attached scsi generic sg4 type 0
[74548.436480] sd 8:0:0:0: [sdc] 8060927 512-byte logical blocks: (4.12 GB/3.84 GiB)
[74548.438129] sd 8:0:0:0: [sdc] Write Protect is off
[74548.438133] sd 8:0:0:0: [sdc] Mode Sense: 00 00 00 00
[74548.438136] sd 8:0:0:0: [sdc] Assuming drive cache: write through
[74548.441129] sd 8:0:0:0: [sdc] Assuming drive cache: write through
[74548.441136] sdc: sdc1
[74548.552148] sd 8:0:0:0: [sdc] Assuming drive cache: write through
[74548.552154] sd 8:0:0:0: [sdc] Attached SCSI removable disk

USB thumbdrive plugged, syslog:
Oct 13 21:36:16 grid kernel: [74543.280021] usb 1-3: new high speed USB device using ehci_hcd and address 8
Oct 13 21:36:16 grid kernel: [74543.434198] usb 1-3: configuration #1 chosen from 1 choice
Oct 13 21:36:16 grid kernel: [74543.437453] scsi8 : SCSI emulation for USB Mass Storage devices
Oct 13 21:36:16 grid kernel: [74543.438016] usb-storage: device found at 8
Oct 13 21:36:16 grid kernel: [74543.438020] usb-storage: waiting for device to settle before scanning
Oct 13 21:36:16 grid kernel: [74548.430169] usb-storage: device scan complete
Oct 13 21:36:16 grid kernel: [74548.432272] scsi 8:0:0:0: Direct-Access PEAK III Flash Drive 0.00 PQ: 0 ANSI: 2
Oct 13 21:36:16 grid kernel: [74548.432801] sd 8:0:0:0: Attached scsi generic sg4 type 0
Oct 13 21:36:16 grid kernel: [74548.436480] sd 8:0:0:0: [sdc] 8060927 512-byte logical blocks: (4.12 GB/3.84 GiB)
Oct 13 21:36:16 grid kernel: [74548.438129] sd 8:0:0:0: [sdc] Write Protect is off
Oct 13 21:36:16 grid kernel: [74548.438133] sd 8:0:0:0: [sdc] Mode Sense: 00 00 00 00
Oct 13 21:36:16 grid kernel: [74548.438136] sd 8:0:0:0: [sdc] Assuming drive cache: write through
Oct 13 21:36:16 grid kernel: [74548.441129] sd 8:0:0:0: [sdc] Assuming drive cache: write through
Oct 13 21:36:16 grid kernel: [74548.441136] sdc: sdc1
Oct 13 21:36:16 grid kernel: [74548.552148] sd 8:0:0:0: [sdc] Assuming drive cache: write through
<-the line at [74548.552154] wasn't recorded

USB thumbdrive unplugged, dmesg:
[74569.766475] usb 1-3: USB disconnect, address 8

USB, thumbdrive unplugged, syslog (launched "logger -- --MARK--" a couple of seconds after):
nothing
Oct 13 21:37:22 grid brownout: --MARK--

[Michael Terry (mterry)]

That is consistent with bug 430220 (buffering of kernel messages). If you keep unplugging/replugging (i.e. filling up the kernel message buffer and forcing a flush), do those lost messages finally appear?

[Brownout (brownout)]

Yes. Additionally if I hit the logging rule of iptables and then I plug/unplug an usb key the connection attempt gets finally logged.

[Michael Terry (mterry)]

OK, cool. Thanks Brownout for helping me figure this out. I'm going to mark this bug as a duplicate of bug 430220. The fix *should* be pushed in today.