# test run while true; do sleep 2; logger -4 -h 127.0.0.1 testing1 ; done & /usr/local/sbin/rsyslogd -i /var/run/syslog.pid -f /usr/local/etc/rsyslog.conf -dn 2>&1| grep -i udp sockstat -46l |grep 514 root rsyslogd 6737 4 tcp4 127.0.0.1:514 *:* root rsyslogd 6737 6 udp4 127.0.0.1:514 *:* # expected results rsyslog is clearly listening on the right port, so we should see rsyslog receiving messages on udp transport, along the lines of this (done directly via /dev/log socket with logger) # 0689.354882820:main Q:Reg/w0 : processBATCH: next msg 0: <13>Nov 11 18:58:09 dch: testing3 0689.837419435:main Q:Reg/w0 : frame to send: '2 syslog 58 <13>2016-11-11T18:58:09.354059+00:00 bridget dch: testing3 # actual results nothing. we can see via tcpdump that the packets are indeed sent, and every 2 seconds this occurs: 8412.256941479:imudp.c : imudp: recvmmsg returned 1 8412.257276361:imudp.c : imudp: recvmmsg returned -1 8411.958888001:main thread : module config name is 'imudp' 8411.958892543:main thread : module imudp supports rsyslog v6 config interface 8411.958902654:main thread : module (global) param blk for imudp: 8411.975968672:main thread : name: 'type', value 'imudp' 8411.975984127:main thread : type: 'imudp' 8411.975994027:main thread : newInpInst (imudp) 8411.976021430:main thread : input param blk in imudp: 8411.978908319:main thread : beginCnfLoad(0x802a1b260) for module 'imudp' 8411.978913360:main thread : calling endCnfLoad() for module 'imudp' 8411.979041683:main thread : module imudp tells us config can be activated 8411.981436622:main thread : Template: Name='RSYSLOG_omudpspoofDfltSourceTpl' 8411.981604979:main thread : imudp 8411.982171343:main thread : pre priv drop activating config 0x801e4c000 for module imudp 8411.982179294:main thread : Trying to open syslog UDP ports at 127.0.0.1:514. 8411.982218865:main thread : ratelimit:imudp(127.0.0.1:514):new ratelimiter:bReduceRepeatMsgs 0 8411.982639625:main thread : activating config 0x801e4c000 for module imudp 8411.982646685:main thread : imudp: config params iMaxLine 65536, lenRcvBuf 2097184 8411.982757035:main thread : Allowed UDP Senders: 8411.984124456:main thread : running module imudp with config 0x801e78280, term mode: cooperative/SIGTTIN 8411.985111180:imudp.c : imudp uses select() 8411.985134341:imudp.c : Listening on UDP syslogd socket 6 (IPv4/port 514). 8411.985141475:imudp.c : --------imUDP calling select, active file descriptors (max 6): 6 8412.256941479:imudp.c : imudp: recvmmsg returned 1 8412.257276361:imudp.c : imudp: recvmmsg returned -1 8412.257291132:imudp.c : Listening on UDP syslogd socket 6 (IPv4/port 514). 8412.257295315:imudp.c : --------imUDP calling select, active file descriptors (max 6): 6 8414.385974230:imudp.c : imudp: recvmmsg returned 1 8414.385998870:imudp.c : imudp: recvmmsg returned -1 8414.386008621:imudp.c : Listening on UDP syslogd socket 6 (IPv4/port 514). 8414.386012513:imudp.c : --------imUDP calling select, active file descriptors (max 6): 6 8416.409035530:imudp.c : imudp: recvmmsg returned 1 # uname -r 11.0-RELEASE-p2 # pkg info rsyslog rsyslog-8.21.0 Name : rsyslog Version : 8.21.0 Installed on : Wed Oct 5 21:27:05 2016 UTC Origin : sysutils/rsyslog8 Architecture : freebsd:11:x86:64 Prefix : /usr/local Categories : sysutils Licenses : LGPL3 and GPLv3 and APACHE20 Maintainer : matthew@FreeBSD.org WWW : http://www.rsyslog.com/ Comment : Syslogd supporting SQL, TCP, and TLS Options : DBI : off DOCS : on GCRYPT : on GNUTLS : off GSSAPI : off MYSQL : off NORMALIZE : off PGSQL : off RELP : on SNMP : off Shared Libs required: librelp.so.0 liblogging-rfc3195.so.0 libfastjson.so.4 liblogging-stdlog.so.0 libgpg-error.so.0 libestr.so.0 libuuid.so.1 libgcrypt.so.20 # /usr/local/etc/rsyslog.conf # Load Modules module(load="imtcp") module(load="imklog") module(load="imudp") module(load="imrelp") module(load="omrelp") module(load="imuxsock") module(load="immark") module(load="impstats") # Disk Queues # zfs create -o canmount=off zroot/var/spool # zfs create zroot/var/spool/rsyslog # mkdir -m0700 /var/log/rsyslog $WorkDirectory /var/spool/rsyslog $MaxMessageSize 64k $MainMsgQueueFileName mainq $MainMsgQueueType LinkedList $MainMsgQueueSaveOnShutDown on $MainMsgQueueMaxDiskSpace 10g $MainMsgQueueSize 10000000 $ActionSendResendLastMsgOnReconnect on input(type="imtcp" address="127.0.0.1" port="514") input(type="imudp" address="127.0.0.1" port="514") action(type="omrelp" target="127.0.0.1" port="44514" ) This looks awfully like https://patch-diff.githubusercontent.com/raw/rsyslog/rsyslog/pull/1147.patch If the new 8.23.0 will be released on 2016/11/15 (viz https://github.com/rsyslog/rsyslog/blob/master/ChangeLog ) then we might as well just bump the version. I'll test locally Matthew's patch and report back if it addressed this.
Please upgrade to the current version of the port: 8.22.0 where this bug has been patched.
Thanks Matthew! Redoing this test using 8.22.0, I still get the same failures. package is custom poudriere, built https://pkg.skunkwerks.at/poudriere/data/latest-per-pkg/rsyslog/8.22.0/11_amd64-default.log - /dev/log works - I can see the outgoing UDP packet on lo0 - rsyslog doesn't see it - redoing these tests using stock FreeBSD port has the same outcome root@wintermute /u/h/dch# jobs Job Group State Command 1 44200 running tail -F /var/log/rsyslog/everything.log & root@wintermute /u/h/dch# sockstat -46l |grep 514 root spiped 1064 3 tcp4 *:4514 *:* root@wintermute /u/h/dch# env RSYSLOG_DEBUG=LogFuncFlow /usr/local/sbin/rsyslogd -i /var/run/syslog.pid -f /usr/local/etc/rsyslog.conf -dn & 5550.429656821:main thread : rsyslogd 8.22.0 startup, module path '', cwd:/usr/home/dch ... root@wintermute /u/h/dch# sockstat -46l |grep 514 root rsyslogd 44540 5 tcp4 127.0.0.1:514 *:* root rsyslogd 44540 7 udp6 *:514 *:* root rsyslogd 44540 8 udp4 *:514 *:* root rsyslogd 44540 9 tcp6 *:43514 *:* root rsyslogd 44540 10 tcp4 *:43514 *:* root spiped 1064 3 tcp4 *:4514 *:* root@wintermute /u/h/dch# logger test 5560.724784811:imuxsock.c : Message from UNIX socket: #11 5560.724802870:imuxsock.c : main Q: qqueueAdd: entry added, size now log 1, phys 1 entries 5560.724822421:imuxsock.c : main Q: EnqueueMsg advised worker start 5560.724826180:imuxsock.c : --------imuxsock calling select, active file descriptors (max 11): 11 5560.724857135:main Q:Reg/w0 : wti 0x801ebf180: worker awoke from idle processing 5560.724863923:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects 5560.724869012:main Q:Reg/w0 : doDeleteBatch: delete batch from store, new sizes: log 1, phys 1 5560.724874135:main Q:Reg/w0 : processBATCH: batch of 1 elements must be processed 5560.724876675:main Q:Reg/w0 : processBATCH: next msg 0: <13>Nov 11 23:06:00 dch: test 5560.724879371:main Q:Reg/w0 : IF 5560.724884107:main Q:Reg/w0 : var 'msg' 5560.724890679:main Q:Reg/w0 : CONTAINS 5560.724895842:main Q:Reg/w0 : string 'rsyslogd-pstats' 5560.724906852:main Q:Reg/w0 : eval expr 0x801e521a0, type 'CMP_CONTAINS' 5560.724909608:main Q:Reg/w0 : eval expr 0x801e42450, type 'V' 5560.724912713:main Q:Reg/w0 : rainerscript: (string) var 1: ' test' 5560.724915011:main Q:Reg/w0 : eval expr 0x801e42450, return datatype 'S':0 5560.724918372:main Q:Reg/w0 : eval expr 0x801e521a0, return datatype 'N':0 5560.724920397:main Q:Reg/w0 : if condition result is 0 5560.724922423:main Q:Reg/w0 : ACTION 1 [builtin:omfile:action(type="builtin:omfile" ...)] 5560.724926927:main Q:Reg/w0 : executing action 1 5560.724930252:main Q:Reg/w0 : action 'rsyslog': called, logging to builtin:omfile (susp 0/0, direct q 0) 5560.724933048:main Q:Reg/w0 : rsyslog queue: qqueueAdd: entry added, size now log 1, phys 1 entries 5560.724938052:main Q:Reg/w0 : rsyslog queue: EnqueueMsg advised worker start 5560.724940482:main Q:Reg/w0 : action 'rsyslog': set suspended state to 0 5560.724942557:main Q:Reg/w0 : END batch execution phase, entering to commit phase [processed 1 of 1 messages] 5560.724944568:main Q:Reg/w0 : processBATCH: batch of 1 elements has been processed 5560.724946632:main Q:Reg/w0 : regular consumer finished, iret=0, szlog 0 sz phys 1 5560.724948784:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 1 objects and enqueued 0 objects 5560.724950878:main Q:Reg/w0 : doDeleteBatch: delete batch from store, new sizes: log 0, phys 0 5560.724953046:main Q:Reg/w0 : regular consumer finished, iret=4, szlog 0 sz phys 0 5560.724954765:main Q:Reg/w0 : main Q:Reg/w0: worker IDLE, waiting for work. 5560.724969354:rsyslog queue:Reg/w0: wti 0x801ebf080: worker awoke from idle processing 5560.724975536:rsyslog queue:Reg/w0: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects 5560.724978318:rsyslog queue:Reg/w0: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1 5560.724985232:rsyslog queue:Reg/w0: action 'rsyslog': is transactional - executing in commit phase 5560.724988624:rsyslog queue:Reg/w0: Action 1 transitioned to state: itx 5560.724991238:rsyslog queue:Reg/w0: doTransaction: have commitTransaction IF, using that, pWrkrInfo 0x801eb8230 5560.724993592:rsyslog queue:Reg/w0: entering actionCallCommitTransaction(), state: itx, actionNbr 1, nMsgs 1 5560.724996536:rsyslog queue:Reg/w0: omfile: write to stream, pData->pStrm 0x806422000, lenBuf 54, strt data 2016-11-11T23:06:00.724791+00:00 wintermute dch: test 5560.724999832:rsyslog queue:Reg/w0: strm 0x806422000: strmFlushinternal: file 12(/var/log/rsyslog/everything.log) flush, buflen 54 5560.725002402:rsyslog queue:Reg/w0: strm 0x806422000: file 12(/var/log/rsyslog/everything.log) doWriteInternal: bFlush 1 5560.725005262:rsyslog queue:Reg/w0: strmPhysWrite, stream 0x806422000, len 54 5560.725053147:rsyslog queue:Reg/w0: strm 0x806422000: file 12 write wrote 54 bytes 5560.725057241:rsyslog queue:Reg/w0: Action 1 transitioned to state: rdy 5560.725059462:rsyslog queue:Reg/w0: actionCommit, action 1, in retry loop, iRet 0 5560.725061582:rsyslog queue:Reg/w0: regular consumer finished, iret=0, szlog 0 sz phys 1 5560.725064696:rsyslog queue:Reg/w0: DeleteProcessedBatch: we deleted 1 objects and enqueued 0 objects 5560.725066684:rsyslog queue:Reg/w0: doDeleteBatch: delete batch from store, new sizes: log 0, phys 0 5560.725068936:rsyslog queue:Reg/w0: regular consumer finished, iret=4, szlog 0 sz phys 0 5560.725070653:rsyslog queue:Reg/w0: rsyslog queue:Reg/w0: worker IDLE, waiting for work. 2016-11-11T23:06:00.724791+00:00 wintermute dch: test root@wintermute /u/h/dch# tcpdump -i lo0 -n -s 1500 -X port 514 & tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on lo0, link-type NULL (BSD loopback), capture size 1500 bytes root@wintermute /u/h/dch# logger -4 -h 127.0.0.1 test 5572.933110005:imudp.c : imudp: recvmmsg returned 1 5572.933123177:imudp.c : imudp: recvmmsg returned -1 23:06:12.933032 IP 127.0.0.1.51977 > 127.0.0.1.514: SYSLOG user.notice, length: 13 5572.933132039:imudp.c : Listening on UDP syslogd socket 7 (IPv6/port 514). 0x0000: 4500 0029 6987 0000 4011 0000 7f00 0001 E..)i...@....... 5572.933136629:imudp.c : Listening on UDP syslogd socket 8 (IPv4/port 514). 0x0010: 7f00 0001 cb09 0202 0015 fe28 3c31 333e ...........(<13> 5572.933139540:imudp.c : --------imUDP calling select, active file descriptors (max 8): 7 0x0020: 6463 683a 2074 6573 74 dch:.test Perhaps I should raise this on the rsyslogd mailing list?
Hmmm.. well, from your build log, configure is now correctly finding pthread_setschedparam: ``` checking for library containing pthread_setschedparam... -lpthread ``` so I guess you've found a different bug. I'm using rsyslog with this patch to log large volumes of UDP traffic successfully. What does your rsyslog.conf look like?
BTW I raised this on the rsyslog list as it looks more like a s/w issue rather than a direct ports/packages one. http://lists.adiscon.net/pipermail/rsyslog/2016-November/043439.html Here's my minimal config: # /usr/local/etc/rsyslog.conf module(load="imtcp") module(load="imklog") module(load="imuxsock") module(load="imudp") input(type="imudp" address="127.0.0.1" port="514") action(type="omfile" file="/var/log/rsyslog.log") Here's output via dtrace, also posted to the list. If you're subscribed there it might be easier to follow in one place, if not I will cross-post as needed. > > - rsyslog doesn't have any log entry, just 2 cryptic lines: > > > > 3092.216287535:imudp.c : imudp: recvmmsg returned 1 > > 3092.216304260:imudp.c : imudp: recvmmsg returned -1 > > hmm, I thought recvmmsg was a linux-only thing. Is it supported on > freebsd? and > if so, does it work the same as on Linux? > > try disabling it and try again. Thanks David. recvmmsg is definitely a FreeBSD thing but how compatible is it I can't tell. https://www.freebsd.org/cgi/man.cgi?query=recvmmsg&manpath=FreeBSD+11.0-RELEASE I can't see any mechanism in ./configure to disable this however. I did run it under dtrace (see below for details) and got -1 and EAGAIN which looks reasonable: The recv(), recvfrom() and recvmsg() return the length of the message on successful completion, whereas recvmmsg() returns the number of received messages. If a message is too long to fit in the supplied buffer, excess bytes may be discarded depending on the type of socket the message is received from (see socket(2)). If no messages are available at the socket, the receive call waits for a message to arrive, unless the socket is non-blocking (see fcntl(2)) in which case the value -1 is returned and the global variable errno is set to EAGAIN. The receive calls except recvmmsg() normally return any data available, up to the requested amount, rather than waiting for receipt of the full amount requested; this behavior is affected by the socket-level options SO_RCVLOWAT and SO_RCVTIMEO described in getsockopt(2). The recvmmsg() function implements this behaviour for each message in the vector. & from here on I'm a bit lost to be honest! I'm happy to grab anything else useful. same content at https://gist.github.com/dch/7e7d2be70e419eb2cad55e00a0430d5b # /usr/local/share/dtrace-toolkit/dtruss -p 46181 -a -s PID/LWP RELATIVE ELAPSD CPU SYSCALL(args) = return 46181/100880: 26 74 8 write(0x1, "8713.574640499:main thread : janitorRun() called\n\0", 0x34) = 52 0 libc.so.7`_write+0xa rsyslogd`dbgprint+0x211 rsyslogd`dbgprintf+0xe9 rsyslogd`janitorRun+0x18 rsyslogd`main+0x613 rsyslogd`_start+0x17f ld-elf.so.1`0x8006b3000 46181/101196: 10 55 3 recvmsg(0x5, 0x801E3BE00, 0x0) = 17 0 libc.so.7`__sys_recvmsg+0xa imudp.so`wrkr+0x432 imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 11 1 0 recvmsg(0x5, 0x801E3BE38, 0x0) = -1 Err#35 libc.so.7`__sys_recvmsg+0xa imudp.so`wrkr+0x432 imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 24 4 2 write(0x1, "8804.086743385:imudp.c : imudp: recvmmsg returned 1\n\0", 0x3B) = 59 0 libc.so.7`_write+0xa rsyslogd`dbgprint+0x211 rsyslogd`dbgprintf+0xe9 imudp.so`wrkr+0x468 imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 30 1 0 recvmsg(0x5, 0x801E3BE00, 0x0) = -1 Err#35 libc.so.7`__sys_recvmsg+0xa imudp.so`wrkr+0x432 imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 33 2 0 write(0x1, "8804.086771347:imudp.c : imudp: recvmmsg returned -1\n\0", 0x3C) = 60 0 libc.so.7`_write+0xa rsyslogd`dbgprint+0x211 rsyslogd`dbgprintf+0xe9 imudp.so`wrkr+0x468 imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 36 2 0 getsockname(0x5, 0x7FFFDF7F98A0, 0x7FFFDF7F989C) = 0 0 libc.so.7`_getsockname+0xa imudp.so`wrkr+0x22a imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 41 4 2 write(0x1, "8804.086789418:imudp.c : Listening on UDP syslogd socket 5 (IPv4/port 514).\n\0", 0x53) = 83 0 libc.so.7`_write+0xa rsyslogd`dbgprint+0x211 rsyslogd`dbgprintf+0xe9 lmnet.so`debugListenInfo+0xa7 imudp.so`wrkr+0x22a imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 45 2 1 write(0x1, "8804.086801418:imudp.c : --------imUDP calling select, active file descriptors (max 5): \0", 0x5F) = 95 0 libc.so.7`_write+0xa rsyslogd`dbgprint+0x211 rsyslogd`dbgprintf+0xe9 imudp.so`wrkr+0x27d imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 46 1 0 write(0x1, "5 \0", 0x2) = 2 0 libc.so.7`_write+0xa rsyslogd`dbgprint+0x211 rsyslogd`dbgprintf+0xe9 imudp.so`wrkr+0x2b5 imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 46181/101196: 48 1 0 write(0x1, "\n\0", 0x1) = 1 0 libc.so.7`_write+0xa rsyslogd`dbgprint+0x211 rsyslogd`dbgprintf+0xe9 imudp.so`wrkr+0x2cb imudp.so`runInput+0xba rsyslogd`thrdStarter+0x9d libthr.so.3`0x8014eab55 calc
Created attachment 176938 [details] Prevent configure detecting recvmmsg(2) Can you try applying the rsyslog-recvmmsg.patch ? This disables configure from detecting recvmmsg(2). If this works that indicates a bug in 11.0's implementation of recvmmsg(2). Or at least, that it is incompatible with the way the function behaves under Linux.
Note that recvmmsg(2) support is new in 11.0-RELEASE, so this should not be a problem on earlier FreeBSD releases.
Hi Matthew this patch does fix the issue. Thank-you so much for helping out. Can I help getting this upstreamed? root@wintermute /# logger -4 -i -P 514 -h 127.0.0.1 barolo magnifico 4928.520709030:imudp.c : recv(6,25),acl:1,msg:<13>dch: barolo magnifico 4928.520732867:imudp.c : msg parser: flags 70, from '~NOTRESOLVED~', msg '<13>dch: barolo magnifico' 4928.520737795:imudp.c : parse using parser list 0x801e2f2b0 (the default list). 4928.520741960:imudp.c : Parser 'rsyslog.rfc5424' returned -2160 4928.520744260:imudp.c : Message will now be parsed by the legacy syslog parser (one size fitsall... ;)). 4928.520747437:imudp.c : Parser 'rsyslog.rfc3164' returned 0 4928.520753081:imudp.c : main Q: qqueueAdd: entry added, size now log 1, phys 1 entries 4928.520765752:imudp.c : main Q: MultiEnqObj advised worker start 4928.520769868:imudp.c : Listening on UDP syslogd socket 6 (IPv4/port 514). 4928.520771749:imudp.c : --------imUDP calling select, active file descriptors (max 6): 6 4928.520797207:main Q:Reg/w0 : wti 0x801e59e00: worker awoke from idle processing 4928.520803734:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects 4928.520806335:main Q:Reg/w0 : doDeleteBatch: delete batch from store, new sizes: log 1, phys 1 4928.520810046:main Q:Reg/w0 : processBATCH: batch of 1 elements must be processed 4928.520812188:main Q:Reg/w0 : processBATCH: next msg 0: <13>dch: barolo magnifico 4928.520814713:main Q:Reg/w0 : ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)] 4928.520819269:main Q:Reg/w0 : executing action 0 4928.520821704:main Q:Reg/w0 : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1) 4928.520830366:main Q:Reg/w0 : dnscache: entry 0x0 found 4928.521244696:main Q:Reg/w0 : action 'action 0': is transactional - executing in commit phase 4928.521249003:main Q:Reg/w0 : Action 0 transitioned to state: itx 4928.521252538:main Q:Reg/w0 : action 'action 0': set suspended state to 0 4928.521254647:main Q:Reg/w0 : END batch execution phase, entering to commit phase [processed 1 of 1messages] 4928.521256770:main Q:Reg/w0 : actionCommitAllDirect: action 0, state 1, nbr to commit 1 isTransactional 1 4928.521258758:main Q:Reg/w0 : doTransaction: have commitTransaction IF, using that, pWrkrInfo 0x801e34c40 4928.521260571:main Q:Reg/w0 : entering actionCallCommitTransaction(), state: itx, actionNbr 0, nMsgs 1 4928.521262936:main Q:Reg/w0 : omfile: write to stream, pData->pStrm 0x803823000, lenBuf 65, strt data 2016-11-12T21:08:48.520699+00:00 localhost dch: barolo magnifico 4928.521265984:main Q:Reg/w0 : strm 0x803823000: strmFlushinternal: file 7(/var/log/rsyslog.log) flush, buflen 65 4928.521473985:main Q:Reg/w0 : strm 0x803823000: file 7(/var/log/rsyslog.log) doWriteInternal: bFlush 1 4928.521477058:main Q:Reg/w0 : strmPhysWrite, stream 0x803823000, len 65 4928.521520718:main Q:Reg/w0 : strm 0x803823000: file 7 write wrote 65 bytes 4928.521526367:main Q:Reg/w0 : Action 0 transitioned to state: rdy 4928.521530655:main Q:Reg/w0 : actionCommit, action 0, in retry loop, iRet 0 4928.521534845:main Q:Reg/w0 : processBATCH: batch of 1 elements has been processed 4928.521538797:main Q:Reg/w0 : regular consumer finished, iret=0, szlog 0 sz phys 1 4928.521543698:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 1 objects and enqueued 0 objects 4928.521547142:main Q:Reg/w0 : doDeleteBatch: delete batch from store, new sizes: log 0, phys 0 4928.521550862:main Q:Reg/w0 : regular consumer finished, iret=4, szlog 0 sz phys 0 4928.521553966:main Q:Reg/w0 : main Q:Reg/w0: worker IDLE, waiting for work. ... drumroll .... 2016-11-12T21:08:48.520699+00:00 localhost dch: barolo magnifico
(In reply to Dave Cottlehuber from comment #7) OK, this presumably indicates a bug in the FreeBSD implementation of recvmmsg(2). Hmmm... there are updates to recvmmsg(2) in HEAD and 11-STABLE which aren't in 11.0-RELEASE. https://svnweb.freebsd.org/base/head/lib/libc/gen/recvmmsg.c?r1=307036&r2=307035&pathrev=307036
(In reply to Matthew Seaman from comment #8) recvmmsg(2) seems to be working fine on recent 11-STABLE: lucid-nonsense:/usr/local/etc:# uname -a FreeBSD lucid-nonsense.infracaninophile.co.uk 11.0-STABLE FreeBSD 11.0-STABLE #9 r308416: Mon Nov 7 14:55:19 GMT 2016 root@lucid-nonsense.infracaninophile.co.uk:/usr/obj/usr/src/sys/GENERIC amd64 lucid-nonsense:...lib/libc/gen:# pkg install rsyslog Updating infracaninophile repository catalogue... infracaninophile repository is up-to-date. All repositories are up-to-date. The following 6 package(s) will be affected (of 0 checked): New packages to be INSTALLED: rsyslog: 8.22.0 libestr: 0.1.10_1 e2fsprogs-libuuid: 1.43.3_1 libee: 0.4.1_1 libfastjson: 0.99.4 liblogging: 1.0.5 [...] lucid-nonsense:/usr/local/etc:# cat rsyslog.conf module(load="imtcp") module(load="imklog") module(load="imuxsock") module(load="imudp") input(type="imudp" address="127.0.0.1" port="1514") lucid-nonsense:/usr/local/etc:# service rsyslogd onestart Starting rsyslogd. lucid-nonsense:/usr/local/etc:# sockstat | grep rsyslogd root rsyslogd 33940 0 dgram /var/run/log root rsyslogd 33940 3 udp4 127.0.0.1:1514 *:* lucid-nonsense:/usr/local/etc:# logger -h 127.0.0.1 -P 1514 testing lucid-nonsense:/usr/local/etc:# cat /tmp/rsyslog.log 2016-11-12T21:46:19.438240+00:00 localhost root: testing
A commit references this bug: Author: matthew Date: Sat Nov 12 22:52:36 UTC 2016 New revision: 425998 URL: https://svnweb.freebsd.org/changeset/ports/425998 Log: recvmmsg(2) is buggy in 11.0-RELEASE, but not recent 11-STABLE or HEAD -- the consequence for rsyslog being that it does not record any log messages received via UDP to a log file. recvmmsg(2) fix was applied to HEAD in r307036 and MFC'd to 11-STABLE in r307311. Therefore prevent configure testing for recvmmsg(2) before OSVERSION 1100504. Note: this is a no-op for older releases than 11 -- recvmmsg(2) doesn't exist there. PR: 214428 Reported by: dch@skunkwerks.at MFH: 2016Q4 Changes: head/sysutils/rsyslog8/Makefile
A commit references this bug: Author: matthew Date: Sun Nov 13 09:33:57 UTC 2016 New revision: 426016 URL: https://svnweb.freebsd.org/changeset/ports/426016 Log: MFH: r425998 recvmmsg(2) is buggy in 11.0-RELEASE, but not recent 11-STABLE or HEAD -- the consequence for rsyslog being that it does not record any log messages received via UDP to a log file. recvmmsg(2) fix was applied to HEAD in r307036 and MFC'd to 11-STABLE in r307311. Therefore prevent configure testing for recvmmsg(2) before OSVERSION 1100504. Note: this is a no-op for older releases than 11 -- recvmmsg(2) doesn't exist there. PR: 214428 Reported by: dch@skunkwerks.at Approved by: ports-secteam (feld) Changes: _U branches/2016Q4/ branches/2016Q4/sysutils/rsyslog8/Makefile
Committed, thanks!