Bug 1312459
| Summary: | Rsyslog rsyslog-7.4.7-12.el7.x86_64 not receiving tcp | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | John Walter <jwalter> |
| Component: | rsyslog | Assignee: | Peter Vrabec <pvrabec> |
| Status: | CLOSED ERRATA | QA Contact: | Stefan Dordevic <sdordevi> |
| Severity: | medium | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 7.2 | CC: | jwalter, pvrabec, sdordevi, unixsa |
| Target Milestone: | rc | ||
| Target Release: | --- | ||
| Hardware: | x86_64 | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | Bug Fix | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2016-11-04 05:37:36 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: | |||
Seems to work for me. Have you reproduced this anywhere besides the customer's site? It'd would be helpful to get rsyslog's debug output. Specifically the part when you make a connection with nc and attempt to send a message. Any files in /etc/rsyslog.d/? I've skimmed through the attached rsyslog.conf and the changes there are nontrivial. Are they sure they've only uncommented those four lines? Just to be sure - are there any relevant SELinux AVCs? Yay! I have access. This is Adam, the customer. I have tried this on a pure RH 7.2 build from ISO and company stock image. In this below test case lets use the company stock image because SELinux/IPtables are off. [root@pdxvdumb ~]# sestatus SELinux status: disabled [root@pdxvdumb ~]# iptables --list Chain INPUT (policy ACCEPT) target prot opt source destination Chain FORWARD (policy ACCEPT) target prot opt source destination Chain OUTPUT (policy ACCEPT) target prot opt source destination Version(s), just encase others follow this. [root@pdxvdumb ~]# uname -a Linux pdxvdumb.escocorp.com 3.10.0-327.4.5.el7.x86_64 #1 SMP Thu Jan 21 04:10:29 EST 2016 x86_64 x86_64 x86_64 GNU/Linux [root@pdxvdumb ~]# rpm -qa | grep rsyslog rsyslog-7.4.7-12.el7.x86_64 I have also stripped the rsyslog.conf down as much as I can (Including removing the call to /etc/rsyslog.d/): [root@pdxvdumb ~]# cat /etc/rsyslog.conf $ModLoad imudp $UDPServerRun 514 $ModLoad imtcp $InputTCPServerRun 514 $WorkDirectory /var/lib/rsyslog $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat *.info;mail.none;authpriv.none;cron.none /var/log/messages authpriv.* /var/log/secure mail.* -/var/log/maillog cron.* /var/log/cron *.emerg :omusrmsg:* uucp,news.crit /var/log/spooler local7.* /var/log/boot.log Now restarting and testing: [root@pdxvdumb ~]# systemctl restart rsyslog [root@pdxvdumb ~]# echo -n "foo2 UDP" | nc -u -w1 localhost 514 [root@pdxvdumb ~]# echo -n "foo3 TCP" | nc -w1 localhost 514 [root@pdxvdumb ~]# tail /var/log/messages .... swVersion="7.4.7" x-pid="3451" x-info="http://www.rsyslog.com"] exiting on signal 15. Mar 3 10:26:15 pdxvdumb rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="3513" x-info="http://www.rsyslog.com"] start Mar 3 10:26:44 foo2 UDP No good. Adding debugging and restarting: [root@pdxvdumb ~]# tail -n1 /etc/rsyslog.conf *.debug /var/log/messages-debug [root@pdxvdumb ~]# systemctl restart rsyslog [root@pdxvdumb ~]# echo -n "foo2 UDP" | nc -u -w1 localhost 514 [root@pdxvdumb ~]# echo -n "foo3 TCP" | nc -w1 localhost 514 [root@pdxvdumb ~]# cat /var/log/messages-debug Mar 3 10:29:42 pdxvdumb rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="3641" x-info="http://www.rsyslog.com"] start Mar 3 10:29:46 foo2 UDP ok, lets go full on debugging! [root@pdxvdumb ~]# rsyslogd -n -f /etc/rsyslog.conf -d [root@pdxvdumb ~]# echo -n "foo3 TCP" | nc -w1 localhost 514 0208.227085888:7f3bd6f54700: epoll returned 1 entries 0208.227131282:7f3bd6f54700: epoll push ppusr[0]: 0x7f3bdb29f5c0 0208.227142375:7f3bd6f54700: tcpsrv: ready to process 1 event entries 0208.227149368:7f3bd6f54700: tcpsrv: processing item 0, pUsr 0x7f3bdb29f5c0, bAbortConn 0208.227164122:7f3bd6f54700: New connect on NSD 0x7f3bdb2a6cb0. 0208.227209072:7f3bd6f54700: dnscache: entry (nil) found 0208.227970014:7f3bd6f54700: adding nsdpoll entry 0/0x7f3bc80027a0, sock 9 0208.227988264:7f3bd6f54700: New session created with NSD 0x7f3bc80027a0. 0208.227994847:7f3bd6f54700: doing epoll_wait for max 128 events 0208.228003167:7f3bd6f54700: epoll returned 1 entries 0208.228008514:7f3bd6f54700: epoll push ppusr[0]: 0x7f3bc80027a0 0208.228013811:7f3bd6f54700: tcpsrv: ready to process 1 event entries 0208.228018781:7f3bd6f54700: tcpsrv: processing item 0, pUsr 0x7f3bc80027a0, bAbortConn 0208.228038291:7f3bd6f54700: netstream 0x7f3bc80026d0 with new data 0208.228075844:7f3bd6f54700: doing epoll_wait for max 128 events 0208.228083638:7f3bd6f54700: epoll returned 1 entries 0208.228089194:7f3bd6f54700: epoll push ppusr[0]: 0x7f3bc80027a0 0208.228094171:7f3bd6f54700: tcpsrv: ready to process 1 event entries 0208.228099188:7f3bd6f54700: tcpsrv: processing item 0, pUsr 0x7f3bc80027a0, bAbortConn 0208.228105078:7f3bd6f54700: netstream 0x7f3bc80026d0 with new data 0208.228112308:7f3bd6f54700: removing nsdpoll entry 0/0x7f3bc80027a0, sock 9 0208.228216718:7f3bd6f54700: doing epoll_wait for max 128 events [root@pdxvdumb ~]# echo -n "foo2 UDP" | nc -u -w1 localhost 514 0151.851383219:7f3bd7755700: imudp: epoll_wait() returned with 1 fds 0151.851415519:7f3bd7755700: imudp:recv(3,8),acl:1,msg:foo2 UDP 0151.851432625:7f3bd7755700: msg parser: flags 70, from '~NOTRESOLVED~', msg 'foo2 UDP' 0151.851437785:7f3bd7755700: parse using parser list 0x7f3bdb293250 (the default list). 0151.851442418:7f3bd7755700: Parser 'rsyslog.rfc5424' returned -2160 0151.851460507:7f3bd7755700: Message will now be parsed by the legacy syslog parser (one size fits all... ;)). 0151.851471556:7f3bd7755700: Parser 'rsyslog.rfc3164' returned 0 0151.851481065:7f3bd7755700: main Q: qqueueAdd: entry added, size now log 1, phys 1 entries 0151.851494118:7f3bd7755700: main Q: MultiEnqObj advised worker start 0151.851515782:7f3bd574f700: wti 0x7f3bdb2bd110: worker awoke from idle processing 0151.851526169:7f3bd574f700: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects 0151.851529587:7f3bd574f700: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1 0151.851535427:7f3bd574f700: processBatch: batch of 1 elements must be processed 0151.851539576:7f3bd574f700: scriptExec: batch of 1 elements, active (nil), active[0]:1 0151.851546391:7f3bd574f700: PRIFILT '*.info;mail.none;authpriv.none;cron.none' 0151.851556124:7f3bd574f700: pmask: 7F 7F X 7F 7F 7F 7F 7F 7F X X 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 0151.851594713:7f3bd574f700: batch: item 0 PRIFILT 1 0151.851597978:7f3bd574f700: scriptExec: batch of 1 elements, active 0x7f3bcc0008e0, active[0]:1 0151.851601793:7f3bd574f700: ACTION 0x7f3bdb2a2d20 [builtin:omfile:/var/log/messages] 0151.851608973:7f3bd574f700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f3bcc0008e0 0151.851614066:7f3bd574f700: Called action(NotAllMark), processing batch[0] via 'builtin:omfile' 0151.851617847:7f3bd574f700: Called action(Batch), logging to builtin:omfile 0151.851626217:7f3bd574f700: submitBatch: enter, nElem 1 0151.851630015:7f3bd574f700: tryDoAction 0x7f3bdb2a2d20, pnElem 1, nElem 1 0151.851634037:7f3bd574f700: Action 0x7f3bdb2a2d20 transitioned to state: itx 0151.851637577:7f3bd574f700: entering actionCalldoAction(), state: itx 0151.851641351:7f3bd574f700: file to log to: /var/log/messages 0151.851644582:7f3bd574f700: omfile: start of data: 'Mar 3 10:35:51 foo2 UDP ' 0151.851648369:7f3bd574f700: write to stream, pData->pStrm 0x7f3bcc000a30, lenBuf 26 0151.851652088:7f3bd574f700: action 0x7f3bdb2a2d20 call returned -2121 0151.851656513:7f3bd574f700: strm 0x7f3bcc000a30: file 6(messages) flush, buflen 26 0151.851660620:7f3bd574f700: strmPhysWrite, stream 0x7f3bcc000a30, len 26 0151.851707819:7f3bd574f700: strm 0x7f3bcc000a30: file 6 write wrote 26 bytes 0151.851712704:7f3bd574f700: Action 0x7f3bdb2a2d20 transitioned to state: rdy 0151.851717233:7f3bd574f700: scriptExec: batch of 1 elements, active (nil), active[0]:1 0151.851720355:7f3bd574f700: PRIFILT 'authpriv.*' 0151.851725480:7f3bd574f700: pmask: X X X X X X X X X X FF X X X X X X X X X X X X X X X 0151.851760839:7f3bd574f700: batch: item 0 PRIFILT 0 0151.851763962:7f3bd574f700: scriptExec: batch of 1 elements, active 0x7f3bcc0008e0, active[0]:0 0151.851766508:7f3bd574f700: ACTION 0x7f3bdb2a3510 [builtin:omfile:/var/log/secure] 0151.851772730:7f3bd574f700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f3bcc0008e0 0151.851775712:7f3bd574f700: Called action(Batch), logging to builtin:omfile 0151.851779177:7f3bd574f700: submitBatch: enter, nElem 1 0151.851782215:7f3bd574f700: tryDoAction 0x7f3bdb2a3510, pnElem 1, nElem 1 0151.851785783:7f3bd574f700: scriptExec: batch of 1 elements, active (nil), active[0]:1 0151.851792546:7f3bd574f700: PRIFILT 'mail.*' 0151.851802239:7f3bd574f700: pmask: X X FF X X X X X X X X X X X X X X X X X X X X X X X 0151.851840503:7f3bd574f700: batch: item 0 PRIFILT 0 0151.851843308:7f3bd574f700: scriptExec: batch of 1 elements, active 0x7f3bcc0008e0, active[0]:0 0151.851846235:7f3bd574f700: ACTION 0x7f3bdb2a3d30 [builtin:omfile:-/var/log/maillog] 0151.851852092:7f3bd574f700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f3bcc0008e0 0151.851855648:7f3bd574f700: Called action(Batch), logging to builtin:omfile 0151.851858866:7f3bd574f700: submitBatch: enter, nElem 1 0151.851861676:7f3bd574f700: tryDoAction 0x7f3bdb2a3d30, pnElem 1, nElem 1 0151.851865021:7f3bd574f700: scriptExec: batch of 1 elements, active (nil), active[0]:1 0151.851867930:7f3bd574f700: PRIFILT 'cron.*' 0151.851872594:7f3bd574f700: pmask: X X X X X X X X X FF X X X X X X X X X X X X X X X X 0151.851907219:7f3bd574f700: batch: item 0 PRIFILT 0 0151.851910003:7f3bd574f700: scriptExec: batch of 1 elements, active 0x7f3bcc0008e0, active[0]:0 0151.851912661:7f3bd574f700: ACTION 0x7f3bdb2a4550 [builtin:omfile:/var/log/cron] 0151.851918743:7f3bd574f700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f3bcc0008e0 0151.851921914:7f3bd574f700: Called action(Batch), logging to builtin:omfile 0151.851925148:7f3bd574f700: submitBatch: enter, nElem 1 0151.851928116:7f3bd574f700: tryDoAction 0x7f3bdb2a4550, pnElem 1, nElem 1 0151.851931305:7f3bd574f700: scriptExec: batch of 1 elements, active (nil), active[0]:1 0151.851953699:7f3bd574f700: PRIFILT '*.emerg' 0151.851960378:7f3bd574f700: pmask: 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 0151.851999578:7f3bd574f700: batch: item 0 PRIFILT 0 0151.852002458:7f3bd574f700: scriptExec: batch of 1 elements, active 0x7f3bcc0008e0, active[0]:0 0151.852005214:7f3bd574f700: ACTION 0x7f3bdb2a4cd0 [builtin:omusrmsg::omusrmsg:*] 0151.852011031:7f3bd574f700: RRRR: execAct [builtin:omusrmsg]: batch of 1 elements, active 0x7f3bcc0008e0 0151.852014387:7f3bd574f700: Called action(Batch), logging to builtin:omusrmsg 0151.852017318:7f3bd574f700: submitBatch: enter, nElem 1 0151.852020031:7f3bd574f700: tryDoAction 0x7f3bdb2a4cd0, pnElem 1, nElem 1 0151.852023438:7f3bd574f700: scriptExec: batch of 1 elements, active (nil), active[0]:1 0151.852026423:7f3bd574f700: PRIFILT 'uucp,news.crit' 0151.852031423:7f3bd574f700: pmask: X X X X X X X 7 7 X X X X X X X X X X X X X X X X X 0151.852067484:7f3bd574f700: batch: item 0 PRIFILT 0 0151.852070145:7f3bd574f700: scriptExec: batch of 1 elements, active 0x7f3bcc0008e0, active[0]:0 0151.852073064:7f3bd574f700: ACTION 0x7f3bdb2a54d0 [builtin:omfile:/var/log/spooler] 0151.852079651:7f3bd574f700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f3bcc0008e0 0151.852082822:7f3bd574f700: Called action(Batch), logging to builtin:omfile 0151.852086082:7f3bd574f700: submitBatch: enter, nElem 1 0151.852089013:7f3bd574f700: tryDoAction 0x7f3bdb2a54d0, pnElem 1, nElem 1 0151.852092165:7f3bd574f700: scriptExec: batch of 1 elements, active (nil), active[0]:1 0151.852100560:7f3bd574f700: PRIFILT 'local7.*' 0151.852106115:7f3bd574f700: pmask: X X X X X X X X X X X X X X X X X X X X X X X FF X X 0151.852140846:7f3bd574f700: batch: item 0 PRIFILT 0 0151.852143604:7f3bd574f700: scriptExec: batch of 1 elements, active 0x7f3bcc0008e0, active[0]:0 0151.852181475:7f3bd574f700: ACTION 0x7f3bdb2a5cf0 [builtin:omfile:/var/log/boot.log] 0151.852188166:7f3bd574f700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f3bcc0008e0 0151.852191588:7f3bd574f700: Called action(Batch), logging to builtin:omfile 0151.852197095:7f3bd574f700: submitBatch: enter, nElem 1 0151.852199922:7f3bd574f700: tryDoAction 0x7f3bdb2a5cf0, pnElem 1, nElem 1 0151.852220464:7f3bd574f700: scriptExec: batch of 1 elements, active (nil), active[0]:1 0151.852224146:7f3bd574f700: ACTION 0x7f3bdb2a6510 [builtin:omfile:/var/log/messages-debug] 0151.852230331:7f3bd574f700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active (nil) 0151.852233966:7f3bd574f700: Called action(NotAllMark), processing batch[0] via 'builtin:omfile' 0151.852236795:7f3bd574f700: Called action(Batch), logging to builtin:omfile 0151.852240877:7f3bd574f700: submitBatch: enter, nElem 1 0151.852243657:7f3bd574f700: tryDoAction 0x7f3bdb2a6510, pnElem 1, nElem 1 0151.852246524:7f3bd574f700: Action 0x7f3bdb2a6510 transitioned to state: itx 0151.852249228:7f3bd574f700: entering actionCalldoAction(), state: itx 0151.852254842:7f3bd574f700: file to log to: /var/log/messages-debug 0151.852257537:7f3bd574f700: omfile: start of data: 'Mar 3 10:35:51 foo2 UDP ' 0151.852260975:7f3bd574f700: write to stream, pData->pStrm 0x7f3bcc001d30, lenBuf 26 0151.852264037:7f3bd574f700: action 0x7f3bdb2a6510 call returned -2121 0151.852267442:7f3bd574f700: strm 0x7f3bcc001d30: file 8(messages-debug) flush, buflen 26 0151.852275668:7f3bd574f700: strmPhysWrite, stream 0x7f3bcc001d30, len 26 0151.852296219:7f3bd574f700: strm 0x7f3bcc001d30: file 8 write wrote 26 bytes 0151.852300386:7f3bd574f700: Action 0x7f3bdb2a6510 transitioned to state: rdy 0151.852303652:7f3bd574f700: ruleset.ProcessMsg() returns 0 0151.852307030:7f3bd574f700: regular consumer finished, iret=0, szlog 0 sz phys 1 0151.852315557:7f3bd574f700: DeleteProcessedBatch: we deleted 1 objects and enqueued 0 objects 0151.852319426:7f3bd574f700: doDeleteBatch: delete batch from store, new sizes: log 0, phys 0 0151.852322881:7f3bd574f700: regular consumer finished, iret=4, szlog 0 sz phys 0 0151.852325699:7f3bd574f700: main Q:Reg/w0: worker IDLE, waiting for work. That is the best I can do with out cracking open the source code. You said it work for you?! What version of rsyslog, and can I grab a copy of your rsyslog.conf? (In reply to Adam/Scott from comment #4) > Yay! I have access. This is Adam, the customer. Hi Adam, just a short preliminary answer for now, maybe it'll suffice. > I have tried this on a pure RH 7.2 build from ISO and company stock image. > [root@pdxvdumb ~]# echo -n "foo2 UDP" | nc -u -w1 localhost 514 > [root@pdxvdumb ~]# echo -n "foo3 TCP" | nc -w1 localhost 514 The problem is in this ^^^, specifically the message format. The imtcp module expects the messages to be ended by a newline (\n). You're explicitly telling echo not to write one. If you try it without '-n', the messages should be logged as expected. I'm not sure whether this change is feasible for you but hopefully it'll help. I'm looking into whether this can be altered in the configuration or whether it's a bug. Will let you know what I find out. Confirmed. [root@pdxvdumb ~]# echo -n "No-Newline foo2 UDP" | nc -u -w1 localhost 514 [root@pdxvdumb ~]# echo "Newline foo2 UDP" | nc -u -w1 localhost 514 [root@pdxvdumb ~]# echo -n "No-Newline TCP" | nc -w1 localhost 514 [root@pdxvdumb ~]# echo "Newline TCP" | nc -w1 localhost 514 [root@pdxvdumb ~]# tail -f /var/log/messages Mar 4 08:59:42 No-Newline foo2 UDP Mar 4 08:59:53 Newline foo2 UDP Mar 4 09:00:12 Newline TCP Strange that UDP does not seem to care and TCP does. So the behavior is mostly likely a bug. Filed here: https://github.com/rsyslog/rsyslog/pull/851 (In reply to Adam/Scott from comment #6) > Strange that UDP does not seem to care and TCP does. UPD data seem to be processed per datagram but TCP streams are handled in a slightly more complicated way; a single message can span multiple TCP packets. This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune with any questions *** Bug 1344222 has been marked as a duplicate of this bug. *** 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. https://rhn.redhat.com/errata/RHEA-2016-2401.html |
Description of problem: When sending rsyslog via TCP, destination never receives Version-Release number of selected component (if applicable): RHEL 7.2 How reproducible: Reproduced by customer after multiple clean installs. Steps to Reproduce: Installed RH 7.2 clean from rhel-server-7.2-x86_64-dvd.iso. Infrastructure Server Static IP Set root password Everything else is left stock. ssh root@fiddler (DNS name for static IP set above) [root@fiddler ~]# systemctl enable sshd [root@fiddler ~]# systemctl start sshd [root@fiddler ~]# vi /etc/rsyslog.conf uncomment lines 15,16,19,20, see below # Provides UDP syslog reception $ModLoad imudp $UDPServerRun 514 # Provides TCP syslog reception $ModLoad imtcp $InputTCPServerRun 514 [root@fiddler ~]# systemctl enable rsyslog [root@fiddler ~]# systemctl restart rsyslog #NetCat (nc) is required for testing below. [root@fiddler ~]# rpm -ivh /tmp/nmap-ncat-6.40-7.el7.x86_64.rpm [root@fiddler ~]# echo -n "foo2 UDP" | nc -u -w1 fiddler 514 [root@fiddler ~]# echo -n "foo2 TCP" | nc -w1 fiddler 514 (FAILED, see below messages output) [root@fiddler log]# tail messages | grep foo2 Feb 24 00:17:32 foo2 UDP Trying a different tool to send syslog data: [root@fiddler ~]# echo foo3 | logger -n fiddler -d -p 514 [root@fiddler ~]# echo foo4 | logger -n fiddler -T -p 514 (FAILED, see below messages output, had to tweak services to get this to use 514. Seems to ignore the -p option) [root@fiddler log]# cat messages | grep foo Feb 24 00:34:22 fiddler.escocorp.com root: foo3 Checking to make sure everything is working as expected... Yes, both TCP and UDP are listining: [root@fiddler ~]# netstat -anp | grep 514 tcp 0 0 0.0.0.0:514 0.0.0.0:* LISTEN 11425/rsyslogd tcp6 0 0 :::514 :::* LISTEN 11425/rsyslogd udp 0 0 0.0.0.0:514 0.0.0.0:* 11425/rsyslogd udp6 0 0 :::514 :::* 11425/rsyslogd External test, just making sure there is nothing in the way. [root@tst-atalbot-vl ~]# nmap fiddler -p 514 Starting Nmap 6.40 ( http://nmap.org ) at 2016-02-24 08:22 PST Nmap scan report for fiddler (10.10.9.111) Host is up (0.00032s latency). rDNS record for 10.10.9.111: fiddler.escocorp.com PORT STATE SERVICE 514/tcp open shell MAC Address: 54:9F:35:E0:54:65 (Unknown) Nmap done: 1 IP address (1 host up) scanned in 0.16 seconds [root@tst-atalbot-vl ~]# telnet fiddler 514 Trying 10.10.9.111... Connected to fiddler. Escape character is '^]'. Actual results: Destination does not receive log via TCP Expected results: Destination should receive log via TCP Additional info: