Segfault when attempting to check length of non-existent JSON message property #1920

deoren · 2017-10-27T22:57:10Z

As noted on #1071, when I attempt to check the length of a JSON message property (whether at the root or part of a subtree) rsyslog quickly segfaults and crashes.

Configuration that can be used to repro the problem

Here is a trimmed configuration that allows me to reproduce the problem:

$ActionFileDefaultTemplate RSYSLOG_FileFormat
$RepeatedMsgReduction off
$WorkDirectory /var/spool/rsyslog

module(
    load="builtin:omfile"
    fileOwner="syslog"
    fileGroup="adm"
    dirOwner="syslog"
    dirGroup="adm"
    fileCreateMode="0640"
    dirCreateMode="0755"
)

module(load="imudp")
module(load="imptcp")

input(type="imudp" port="514" ruleset="receiver-standard-rules")
input(type="imptcp" port="514" KeepAlive="on" ruleset="receiver-standard-rules")

ruleset(name="receiver-standard-rules") {

    if ($!origin!hostname == "") then {
        continue
    }

    action(
        name="test-messages"
        type="omfile"
        file="/var/log/rsyslog_testing.log"
    )
}

Systems I used to reproduce the problem

I believe I can trim the configuration further to still replicate the segfault and will do if/when requested.

I've reproduced the segfault on:

Ubuntu 16.04 + rsyslog v8.30.0 (Adiscon PPA)
Ubuntu 14.04 + rsyslog v8.30.0 (Adiscon PPA)
Ubuntu 16.04, stock rsyslog 8.16.0-1ubuntu3

Steps to reproduce

logger --tcp --port 514 --server TESTBOX_FQDN "hello!"
logger --udp --port 514 --server TESTBOX_FQDN "hello!"

This is whether I'm testing against a remote instance of rsyslog v8.30.0 running on an Ubuntu 16.04 or an Ubuntu 14.04 box using the latest v8.30.0 version from the Adiscon Ubuntu PPA.

If testing the rsyslog instance from the same box you run logger, be aware (I wasn't until today) that the logger command from Ubuntu 14.04 box fails to work properly when using the -n option. The Sending UDP packets with logger command askubuntu.com Q/A entry has more info.

Debug/Valgrind output

This output was generated two days ago from fffda03. The output is roughly the same as that from v8.30.0, but more detail appears to be present in this build.

3039.891831720:92c8700: debug.c: thread created, tid 43035, name 'rs:main Q:Reg'
3039.894584170:imuxsock.c     : main Q: queue.c: EnqueueMsg advised worker start
3039.895594451:imuxsock.c     : imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3 
3039.896501099:main Q:Reg/w0  : wti.c: wti 0x63abce0: worker starting
3039.909109190:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects
3039.911333881:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1
3039.921467434:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements must be processed
3039.922634833:main Q:Reg/w0  : ruleset.c: processBATCH: next msg 0: <46>Oct 25 23:10:39 rsyslogd:  [origin software="rsyslogd" swVersion="8.31.0.master" x-pid="43028" x-info="http://www.rsyslog.co
3039.925356433:main Q:Reg/w0  : ruleset.c: END batch execution phase, entering to commit phase [processed 1 of 1 messages]
3039.926128619:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements has been processed
3039.927654831:main Q:Reg/w0  : queue.c: regular consumer finished, iret=0, szlog 0 sz phys 1
3039.930401746:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 1 objects and enqueued 0 objects
3039.930800150:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 0, phys 0
3039.931254704:main Q:Reg/w0  : queue.c: regular consumer finished, iret=4, szlog 0 sz phys 0
3039.931910886:main Q:Reg/w0  : wti.c: main Q:Reg/w0: worker IDLE, waiting for work.
3090.196115925:imptcp.c       : imptcp.c: imptcp: epoll returned 1 events
3090.196811297:imptcp.c       : imptcp.c: imptcp: new connection on listen socket 7
3090.198965316:imptcp.c       : imptcp.c: KEEPALIVE enabled for socket 11
3090.323921505:imptcp.c       : imptcp.c: iRet: 0
3090.324279744:imptcp.c       : imptcp.c: imptcp: AcceptConnReq on listen socket 7 returned 0
3090.325479087:imptcp.c       : imptcp.c: imptcp: added socket 11 to epoll[6] set
3090.326041451:imptcp.c       : imptcp.c: iRet: -3006
3090.326425000:imptcp.c       : imptcp.c: imptcp: AcceptConnReq on listen socket 7 returned -3006
3090.326928346:imptcp.c       : imptcp.c: imptcp going on epoll_wait
3090.327065200:imptcp.c       : imptcp.c: imptcp: epoll returned 1 events
3090.327583465:imptcp.c       : imptcp.c: imptcp: new activity on session socket 11
3090.328765830:imptcp.c       : imptcp.c: imptcp: data(131072) on socket 11: <13>1 2017-10-25T18:11:30.197765-05:00 ubuntu-virtual-machine root - - [timeQuality tzKnown="1" isSynced="1" syncAccuracy="881871"] hello

3090.333553357:imptcp.c       : parser.c: msg parser: flags 30, from '192.168.146.131', msg '<13>1 2017-10-25T18:11:30.197765-05:00 ubuntu-virtual-machin'
3090.334169241:imptcp.c       : parser.c: parse using parser list 0x6277380 (the default list).
3090.339990679:imptcp.c       : pmrfc5424.c: Message has RFC5424/syslog-protocol format.
3090.348972848:imptcp.c       : parser.c: Parser 'rsyslog.rfc5424' returned 0
3090.349640660:imptcp.c       : ratelimit.c: RRRRRR: localRet 0
3090.359349606:imptcp.c       : main Q: queue.c: qqueueAdd: entry added, size now log 1, phys 1 entries
3090.365981301:main Q:Reg/w0  : wti 0x63abce0: wti.c: worker awoke from idle processing
3090.368277710:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects
3090.368354604:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1
3090.368432155:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements must be processed
3090.368492911:main Q:Reg/w0  : ruleset.c: processBATCH: next msg 0: <13>1 2017-10-25T18:11:30.197765-05:00 ubuntu-virtual-machine root - - [timeQuality tzKnown="1" isSynced="1" syncAccuracy="88187
3090.369289139:main Q:Reg/w0  : rainerscript.c:     IF
3090.370010664:main Q:Reg/w0  : rainerscript.c:         var '!origin!hostname'
3090.370600976:main Q:Reg/w0  : rainerscript.c:       ==
3090.371076292:main Q:Reg/w0  : rainerscript.c:         string ''
3090.374676266:main Q:Reg/w0  : rainerscript.c: eval expr 0x62a06c0, type 'CMP_EQ'
3090.375306487:main Q:Reg/w0  : rainerscript.c: eval expr 0x62a0550, type 'V'
3090.375417604:imptcp.c       : main Q: queue.c: MultiEnqObj advised worker start
3090.377675454:imptcp.c       : imptcp.c: imptcp: session on socket 11 closed with iRet 0.
==43028== Thread 7 rs:main Q:Reg:
==43028== Invalid read of size 4
==43028==    at 0x5885904: fjson_object_iter_begin (json_object_iterator.c:69)
==43028==    by 0x58835D2: _fjson_find_child (json_object.c:376)
==43028==    by 0x5883E48: fjson_object_object_add_ex (json_object.c:445)
==43028==    by 0x4345F7: jsonPathFindNext (msg.c:4656)
==43028==    by 0x434663: jsonPathFindParent (msg.c:4674)
==43028==    by 0x4396BF: msgGetJSONPropJSONorString (msg.c:3092)
==43028==    by 0x42209D: evalVar (rainerscript.c:2202)
==43028==    by 0x42209D: cnfexprEval (rainerscript.c:2749)
==43028==    by 0x421D73: cnfexprEval (rainerscript.c:2343)
==43028==    by 0x424B75: cnfexprEvalBool (rainerscript.c:2905)
==43028==    by 0x45D354: execIf (ruleset.c:308)
==43028==    by 0x45D354: scriptExec (ruleset.c:603)
==43028==    by 0x45DE0B: processBatch (ruleset.c:649)
==43028==    by 0x40EDF3: msgConsumer (rsyslogd.c:695)
==43028==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==43028== 
==43028== 
==43028== Process terminating with default action of signal 11 (SIGSEGV)
==43028==  Access not within mapped region at address 0x0
==43028==    at 0x5885904: fjson_object_iter_begin (json_object_iterator.c:69)
==43028==    by 0x58835D2: _fjson_find_child (json_object.c:376)
==43028==    by 0x5883E48: fjson_object_object_add_ex (json_object.c:445)
==43028==    by 0x4345F7: jsonPathFindNext (msg.c:4656)
==43028==    by 0x434663: jsonPathFindParent (msg.c:4674)
==43028==    by 0x4396BF: msgGetJSONPropJSONorString (msg.c:3092)
==43028==    by 0x42209D: evalVar (rainerscript.c:2202)
==43028==    by 0x42209D: cnfexprEval (rainerscript.c:2749)
==43028==    by 0x421D73: cnfexprEval (rainerscript.c:2343)
==43028==    by 0x424B75: cnfexprEvalBool (rainerscript.c:2905)
==43028==    by 0x45D354: execIf (ruleset.c:308)
==43028==    by 0x45D354: scriptExec (ruleset.c:603)
==43028==    by 0x45DE0B: processBatch (ruleset.c:649)
==43028==    by 0x40EDF3: msgConsumer (rsyslogd.c:695)
==43028==  If you believe this happened as a result of a stack
==43028==  overflow in your program's main thread (unlikely but
==43028==  possible), you can try to increase the size of the
==43028==  main thread stack using the --main-stacksize= flag.
==43028==  The main thread stack size used in this run was 8388608.
==43028== 
==43028== HEAP SUMMARY:
==43028==     in use at exit: 1,193,708 bytes in 1,528 blocks
==43028==   total heap usage: 2,101 allocs, 573 frees, 1,311,219 bytes allocated
==43028== 
==43028== LEAK SUMMARY:
==43028==    definitely lost: 0 bytes in 0 blocks
==43028==    indirectly lost: 0 bytes in 0 blocks
==43028==      possibly lost: 1,728 bytes in 6 blocks
==43028==    still reachable: 1,191,980 bytes in 1,522 blocks
==43028==         suppressed: 0 bytes in 0 blocks
==43028== Rerun with --leak-check=full to see details of leaked memory
==43028== 
==43028== For counts of detected and suppressed errors, rerun with: -v
==43028== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
Killed

Steps I followed to build from source

service rsyslog stop
sudo apt-get update
sudo apt-get -y install libtool autoconf automake valgrind git-core build-essential pkg-config libestr-dev zlib1g-dev uuid-dev libgcrypt20-dev liblogging-stdlog-dev libhiredis-dev uuid-dev libgcrypt11-dev liblogging-stdlog-dev flex bison libdbi-dev libmysqlclient-dev postgresql-client libpq-dev libnet-dev librdkafka-dev libgrok-dev libgrok1 libgrok-dev libpcre3-dev libtokyocabinet-dev libglib2.0-dev libmongo-client-dev
cd /tmp
git clone https://github.com/rsyslog/libfastjson
cd libfastjson/
sh autogen.sh
./configure
make
sudo make install
cd /tmp
git clone https://github.com/rsyslog/rsyslog
cd rsyslog
sh autogen.sh
./configure --enable-imptcp
make
sudo make install
wget https://gist.githubusercontent.com/deoren/fd61fe29619d4387b643656c5671490d/raw/a9255c92fd9398a433826d5ce95d8d56d080b9cd/rsyslog-issue-1920.conf -O /tmp/rsyslog-issue-1920.conf
valgrind rsyslogd -dn -f /tmp/rsyslog-issue-1920.conf

The text was updated successfully, but these errors were encountered:

deoren · 2017-10-27T23:19:31Z

I just compiled rsyslog from the latest sources in master (0507f3c) and the problem persists.

6241.909140281:imptcp.c       : imptcp.c: imptcp: epoll returned 1 events
6241.909931656:imptcp.c       : imptcp.c: imptcp: new connection on listen socket 7
6241.911084142:imptcp.c       : imptcp.c: KEEPALIVE enabled for socket 11
6242.017685098:imptcp.c       : imptcp.c: iRet: 0
6242.017999648:imptcp.c       : imptcp.c: imptcp: AcceptConnReq on listen socket 7 returned 0
6242.019041934:imptcp.c       : imptcp.c: imptcp: added socket 11 to epoll[6] set
6242.019595105:imptcp.c       : imptcp.c: iRet: -3006
6242.019981418:imptcp.c       : imptcp.c: imptcp: AcceptConnReq on listen socket 7 returned -3006
6242.020580163:imptcp.c       : imptcp.c: imptcp going on epoll_wait
6242.020708007:imptcp.c       : imptcp.c: imptcp: epoll returned 1 events
6242.021264960:imptcp.c       : imptcp.c: imptcp: new activity on session socket 11
6242.022437756:imptcp.c       : imptcp.c: imptcp: data(131072) on socket 11: <13>1 2017-10-27T18:17:21.913191-05:00 ubuntu-virtual-machine ubuntu - - [timeQuality tzKnown="1" isSynced="1" syncAccuracy="1470515"] hello!

6242.027146396:imptcp.c       : parser.c: msg parser: flags 30, from '192.168.146.131', msg '<13>1 2017-10-27T18:17:21.913191-05:00 ubuntu-virtual-machin'
6242.027745422:imptcp.c       : parser.c: parse using parser list 0x6277380 (the default list).
6242.032917265:imptcp.c       : pmrfc5424.c: Message has RFC5424/syslog-protocol format.
6242.042048843:imptcp.c       : parser.c: Parser 'rsyslog.rfc5424' returned 0
6242.042724746:imptcp.c       : ratelimit.c: RRRRRR: localRet 0
6242.051813592:imptcp.c       : main Q: queue.c: qqueueAdd: entry added, size now log 1, phys 1 entries
6242.052905808:main Q:Reg/w0  : wti 0x63acd20: wti.c: worker awoke from idle processing
6242.053073699:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects
6242.053238479:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1
6242.053421790:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements must be processed
6242.053527140:main Q:Reg/w0  : ruleset.c: processBATCH: next msg 0: <13>1 2017-10-27T18:17:21.913191-05:00 ubuntu-virtual-machine ubuntu - - [timeQuality tzKnown="1" isSynced="1" syncAccuracy="147
6242.054972744:main Q:Reg/w0  : rainerscript.c:     IF
6242.056412345:main Q:Reg/w0  : rainerscript.c:         var '!origin!hostname'
6242.057386893:main Q:Reg/w0  : rainerscript.c:       ==
6242.057890223:main Q:Reg/w0  : rainerscript.c:         string ''
6242.059285362:main Q:Reg/w0  : rainerscript.c: eval expr 0x62a06c0, type 'CMP_EQ'
6242.059403100:imptcp.c       : main Q: queue.c: MultiEnqObj advised worker start
6242.061893279:imptcp.c       : imptcp.c: imptcp: session on socket 11 closed with iRet 0.
6242.062931552:imptcp.c       : imptcp.c: imptcp going on epoll_wait
6242.063087387:main Q:Reg/w0  : rainerscript.c: eval expr 0x62a0550, type 'V'
==37494== Thread 7 rs:main Q:Reg:
==37494== Invalid read of size 4
==37494==    at 0x5885904: fjson_object_iter_begin (json_object_iterator.c:69)
==37494==    by 0x58835D2: _fjson_find_child (json_object.c:376)
==37494==    by 0x5883E48: fjson_object_object_add_ex (json_object.c:445)
==37494==    by 0x434637: jsonPathFindNext (msg.c:4655)
==37494==    by 0x4346A3: jsonPathFindParent (msg.c:4673)
==37494==    by 0x4396CF: msgGetJSONPropJSONorString (msg.c:3091)
==37494==    by 0x4220BD: evalVar (rainerscript.c:2202)
==37494==    by 0x4220BD: cnfexprEval (rainerscript.c:2749)
==37494==    by 0x421D93: cnfexprEval (rainerscript.c:2343)
==37494==    by 0x424B95: cnfexprEvalBool (rainerscript.c:2905)
==37494==    by 0x45D374: execIf (ruleset.c:308)
==37494==    by 0x45D374: scriptExec (ruleset.c:603)
==37494==    by 0x45DE2B: processBatch (ruleset.c:649)
==37494==    by 0x40EDF3: msgConsumer (rsyslogd.c:695)
==37494==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==37494== 
==37494== 
==37494== Process terminating with default action of signal 11 (SIGSEGV)
==37494==  Access not within mapped region at address 0x0
==37494==    at 0x5885904: fjson_object_iter_begin (json_object_iterator.c:69)
==37494==    by 0x58835D2: _fjson_find_child (json_object.c:376)
==37494==    by 0x5883E48: fjson_object_object_add_ex (json_object.c:445)
==37494==    by 0x434637: jsonPathFindNext (msg.c:4655)
==37494==    by 0x4346A3: jsonPathFindParent (msg.c:4673)
==37494==    by 0x4396CF: msgGetJSONPropJSONorString (msg.c:3091)
==37494==    by 0x4220BD: evalVar (rainerscript.c:2202)
==37494==    by 0x4220BD: cnfexprEval (rainerscript.c:2749)
==37494==    by 0x421D93: cnfexprEval (rainerscript.c:2343)
==37494==    by 0x424B95: cnfexprEvalBool (rainerscript.c:2905)
==37494==    by 0x45D374: execIf (ruleset.c:308)
==37494==    by 0x45D374: scriptExec (ruleset.c:603)
==37494==    by 0x45DE2B: processBatch (ruleset.c:649)
==37494==    by 0x40EDF3: msgConsumer (rsyslogd.c:695)
==37494==  If you believe this happened as a result of a stack
==37494==  overflow in your program's main thread (unlikely but
==37494==  possible), you can try to increase the size of the
==37494==  main thread stack using the --main-stacksize= flag.
==37494==  The main thread stack size used in this run was 8388608.
==37494== 
==37494== HEAP SUMMARY:
==37494==     in use at exit: 1,193,715 bytes in 1,528 blocks
==37494==   total heap usage: 2,521 allocs, 993 frees, 1,591,668 bytes allocated
==37494== 
==37494== LEAK SUMMARY:
==37494==    definitely lost: 0 bytes in 0 blocks
==37494==    indirectly lost: 0 bytes in 0 blocks
==37494==      possibly lost: 1,728 bytes in 6 blocks
==37494==    still reachable: 1,191,987 bytes in 1,522 blocks
==37494==         suppressed: 0 bytes in 0 blocks
==37494== Rerun with --leak-check=full to see details of leaked memory
==37494== 
==37494== For counts of detected and suppressed errors, rerun with: -v
==37494== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
KILLED

deoren · 2017-10-27T23:25:07Z

I just modified the OP to remove this block:

module(
    load="imuxsock"
    sysSock.use="on"
    SysSock.Annotate="on"
    SysSock.ParseTrusted="on"
)

and have updated the URL to the config file provided by the gist to reference the new version that leaves out loading the imuxsock module (since I can repro the problem without it).

ghost · 2017-10-30T12:05:30Z

I was able to reproduce this with following configuration:

set $!r = $!var!var2;

The Segmentation Fault is triggered when the path consists of at least one variable.
For example the following does not trigger the Segmentation Fault:

set $!r = $!var;

ghost · 2017-11-02T16:44:53Z

The problem should be fixed now.
@deoren can you test if your Segmentation Fault is solved?

rgerhards · 2017-11-02T17:01:40Z

As a side-note, it looks like parts of the variable handling would benefit from some review/refactoring ;-) #1956

deoren · 2017-11-02T19:00:06Z

@PascalWithopf: The problem should be fixed now.
@deoren can you test if your Segmentation Fault is solved?

I'll test and report back as soon as I can. Thanks!

deoren · 2017-11-02T21:23:29Z

@PascalWithopf I assume I need to clone from your fork and not from rsyslog/rsyslog master? I just built from de4ccbf and the issue is still present. About to build from your fork next (from a clean snapshot) and will test again.

deoren · 2017-11-02T21:53:15Z

@PascalWithopf I tested c7a5085 from the i-1920 branch from your repo and was unable to reproduce the segfault.

Output from valgrind rsyslogd -dn -f /tmp/rsyslog-issue-1920.conf:

9149.737646820:main thread    : rsyslogd.c: ----RSYSLOGD INITIALIZED
9268.479486841:imptcp.c       : imptcp.c: imptcp: epoll returned 1 events
9268.480280363:imptcp.c       : imptcp.c: imptcp: new connection on listen socket 6
9268.481503899:imptcp.c       : imptcp.c: KEEPALIVE enabled for socket 10
9268.573438388:imptcp.c       : imptcp.c: iRet: 0
9268.573760916:imptcp.c       : imptcp.c: imptcp: AcceptConnReq on listen socket 6 returned 0
9268.574820561:imptcp.c       : imptcp.c: imptcp: added socket 10 to epoll[5] set
9268.575345512:imptcp.c       : imptcp.c: iRet: -3006
9268.575775606:imptcp.c       : imptcp.c: imptcp: AcceptConnReq on listen socket 6 returned -3006
9268.576295820:imptcp.c       : imptcp.c: imptcp going on epoll_wait
9268.576415680:imptcp.c       : imptcp.c: imptcp: epoll returned 1 events
9268.576960567:imptcp.c       : imptcp.c: imptcp: new activity on session socket 10
9268.578147425:imptcp.c       : imptcp.c: imptcp: data(131072) on socket 10: <13>1 2017-11-02T16:47:48.484222-05:00 ubuntu-virtual-machine ubuntu - - [timeQuality tzKnown="1" isSynced="0"] hello!

9268.583991878:imptcp.c       : parser.c: msg parser: flags 30, from '192.168.146.131', msg '<13>1 2017-11-02T16:47:48.484222-05:00 ubuntu-virtual-machin'
9268.586468645:imptcp.c       : parser.c: parse using parser list 0x6277380 (the default list).
9268.590867481:imptcp.c       : pmrfc5424.c: Message has RFC5424/syslog-protocol format.
9268.600337912:imptcp.c       : parser.c: Parser 'rsyslog.rfc5424' returned 0
9268.608285123:imptcp.c       : ratelimit.c: RRRRRR: localRet 0
9268.614970338:imptcp.c       : main Q: queue.c: qqueueAdd: entry added, size now log 1, phys 1 entries
9268.621809873:imptcp.c       : wtp.c: main Q:Reg: started with state 0, num workers now 1
9268.623359176:92e3700: debug.c: thread created, tid 33690, name 'rs:main Q:Reg'
9268.626235453:imptcp.c       : main Q: queue.c: MultiEnqObj advised worker start
9268.628700127:imptcp.c       : imptcp.c: imptcp: session on socket 10 closed with iRet 0.
9268.629480132:imptcp.c       : imptcp.c: imptcp going on epoll_wait
9268.630074536:main Q:Reg/w0  : wti.c: wti 0x63a8500: worker starting
9268.634127429:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects
9268.636154858:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1
9268.641767382:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements must be processed
9268.642390600:main Q:Reg/w0  : ruleset.c: processBATCH: next msg 0: <13>1 2017-11-02T16:47:48.484222-05:00 ubuntu-virtual-machine ubuntu - - [timeQuality tzKnown="1" isSynced="0"] hello!
9268.643194985:main Q:Reg/w0  : rainerscript.c:     IF
9268.644119387:main Q:Reg/w0  : rainerscript.c:         var '!origin!hostname'
9268.644464831:main Q:Reg/w0  : rainerscript.c:       ==
9268.644975124:main Q:Reg/w0  : rainerscript.c:         string ''
9268.652733998:main Q:Reg/w0  : rainerscript.c: eval expr 0x629c030, type 'CMP_EQ'
9268.653209367:main Q:Reg/w0  : rainerscript.c: eval expr 0x629bec0, type 'V'
9268.655101307:main Q:Reg/w0  : rainerscript.c: rainerscript: (json/string) var 200: '(null)'
9268.658394307:main Q:Reg/w0  : rainerscript.c: eval expr 0x629bec0, return datatype 'S':0
9268.659251656:main Q:Reg/w0  : rainerscript.c: eval expr 0x629c030, return datatype 'N':1
9268.660416981:main Q:Reg/w0  : ruleset.c: if condition result is 1
9268.662088246:main Q:Reg/w0  : rainerscript.c:     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
9268.662971502:main Q:Reg/w0  : ruleset.c: executing action 0
9268.663826781:main Q:Reg/w0  : ../action.c: action 'test-messages': called, logging to builtin:omfile (susp 0/0, direct q 1)
9268.675476107:main Q:Reg/w0  : ../action.c: action 'test-messages': is transactional - executing in commit phase
9268.676104805:main Q:Reg/w0  : ../action.c: wti 0x63a8500: we need to create a new action worker instance for action 0
9268.677449997:main Q:Reg/w0  : ../action.c: wti 0x63a8500: created action worker instance 1 for action 0
9268.678498801:main Q:Reg/w0  : ../action.c: action[test-messages] transitioned to state: itx
9268.679951164:main Q:Reg/w0  : ../action.c: action 'test-messages': set suspended state to 0
9268.680889139:main Q:Reg/w0  : ruleset.c: END batch execution phase, entering to commit phase [processed 1 of 1 messages]
9268.681530934:main Q:Reg/w0  : ../action.c: actionCommitAllDirect: action 0, state 1, nbr to commit 1 isTransactional 1
9268.682188528:main Q:Reg/w0  : ../action.c: actionCommit[test-messages]: enter, 1 msgs
9268.682834412:main Q:Reg/w0  : ../action.c: actionCommit[test-messages]: processing...
9268.683356913:main Q:Reg/w0  : ../action.c: actionTryCommit[test-messages] enter
9268.684365272:main Q:Reg/w0  : ../action.c: doTransaction: have commitTransaction IF, using that, pWrkrInfo 0x63a8640
9268.684981931:main Q:Reg/w0  : ../action.c: entering actionCallCommitTransaction[test-messages], state: itx, nMsgs 1
9268.703553929:main Q:Reg/w0  : stream.c: file stream rsyslog_testing.log params: flush interval 0, async write 0
9268.704687111:main Q:Reg/w0  : omfile.c: omfile: write to stream, pData->pStrm 0x63bb140, lenBuf 70, strt data 2017-11-02T16:47:48.484222-05:00 ubuntu-virtual-machine ubuntu hello!

9268.707839810:main Q:Reg/w0  : strm 0x63bb140: stream.c: strmFlushinternal: file -1(rsyslog_testing.log) flush, buflen 70
9268.708718133:main Q:Reg/w0  : strm 0x63bb140: stream.c: file -1(rsyslog_testing.log) doWriteInternal: bFlush 1
9268.709758284:main Q:Reg/w0  : stream.c: strmPhysWrite, stream 0x63bb140, len 70
9268.712551376:main Q:Reg/w0  : stream.c: file '/var/log/rsyslog_testing.log' opened as #10 with mode 420
9268.714565145:main Q:Reg/w0  : strm 0x63bb140: stream.c: opened file '/var/log/rsyslog_testing.log' for WRITE as 10
9268.715792990:main Q:Reg/w0  : strm 0x63bb140: stream.c: file 10 write wrote 70 bytes
9268.717120108:main Q:Reg/w0  : ../action.c: actionCallCommitTransaction[test-messages] state: itx mod commitTransaction returned 0
9268.717820662:main Q:Reg/w0  : ../action.c: action[test-messages] transitioned to state: rdy
9268.718661166:main Q:Reg/w0  : ../action.c: actionTryCommit[test-messages] past doTransaction
9268.719339720:main Q:Reg/w0  : ../action.c: actionTryCommit[test-messages] exit 0
9268.719901186:main Q:Reg/w0  : ../action.c: actionCommit[test-messages]: done, iRet 0
9268.720661485:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements has been processed
9268.721883353:main Q:Reg/w0  : queue.c: regular consumer finished, iret=0, szlog 0 sz phys 1
9268.723466920:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 1 objects and enqueued 0 objects
9268.723852763:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 0, phys 0
9268.724253045:main Q:Reg/w0  : queue.c: regular consumer finished, iret=4, szlog 0 sz phys 0
9268.724917945:main Q:Reg/w0  : wti.c: main Q:Reg/w0: worker IDLE, waiting for work.
9276.496947047:imudp.c        : imudp.c: imudp: epoll_wait() returned with 1 fds
9276.499668562:imudp.c        : imudp.c: imudp: recvmmsg returned 1
9276.501610826:imudp.c        : imudp.c: recv(3,118),acl:1,msg:<13>1 2017-11-02T16:47:56.496529-05:00 ubuntu-virtual-machine ubuntu - - [timeQuality tzKnown="1" isSynced="0"] hello!
9276.503272731:imudp.c        : parser.c: msg parser: flags 70, from '~NOTRESOLVED~', msg '<13>1 2017-11-02T16:47:56.496529-05:00 ubuntu-virtual-machin'
9276.503430160:imudp.c        : parser.c: parse using parser list 0x6277380 (the default list).
9276.503548582:imudp.c        : pmrfc5424.c: Message has RFC5424/syslog-protocol format.
9276.503720475:imudp.c        : parser.c: Parser 'rsyslog.rfc5424' returned 0
9276.503888051:imudp.c        : ratelimit.c: RRRRRR: localRet 0
9276.505067508:imudp.c        : imudp.c: imudp: recvmmsg returned -1
9276.505495971:imudp.c        : main Q: queue.c: qqueueAdd: entry added, size now log 1, phys 1 entries
9276.513049490:main Q:Reg/w0  : wti 0x63a8500: wti.c: worker awoke from idle processing
9276.513415014:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects
9276.513552439:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1
9276.513683147:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements must be processed
9276.513795950:main Q:Reg/w0  : ruleset.c: processBATCH: next msg 0: <13>1 2017-11-02T16:47:56.496529-05:00 ubuntu-virtual-machine ubuntu - - [timeQuality tzKnown="1" isSynced="0"] hello!
9276.515475721:main Q:Reg/w0  : rainerscript.c:     IF
9276.515698210:main Q:Reg/w0  : rainerscript.c:         var '!origin!hostname'
9276.516088443:main Q:Reg/w0  : rainerscript.c:       ==
9276.516368999:main Q:Reg/w0  : rainerscript.c:         string ''
9276.516807797:main Q:Reg/w0  : rainerscript.c: eval expr 0x629c030, type 'CMP_EQ'
9276.516936556:main Q:Reg/w0  : rainerscript.c: eval expr 0x629bec0, type 'V'
9276.517052141:main Q:Reg/w0  : rainerscript.c: rainerscript: (json/string) var 200: '(null)'
9276.517158537:main Q:Reg/w0  : rainerscript.c: eval expr 0x629bec0, return datatype 'S':0
9276.517270159:main Q:Reg/w0  : rainerscript.c: eval expr 0x629c030, return datatype 'N':1
9276.517388447:main Q:Reg/w0  : ruleset.c: if condition result is 1
9276.517495198:main Q:Reg/w0  : rainerscript.c:     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
9276.517751832:main Q:Reg/w0  : ruleset.c: executing action 0
9276.517873484:main Q:Reg/w0  : ../action.c: action 'test-messages': called, logging to builtin:omfile (susp 0/0, direct q 1)
9276.518276777:main Q:Reg/w0  : ../action.c: action 'test-messages': is transactional - executing in commit phase
9276.518470935:main Q:Reg/w0  : ../action.c: action[test-messages] transitioned to state: itx
9276.518591816:main Q:Reg/w0  : ../action.c: action 'test-messages': set suspended state to 0
9276.518707644:main Q:Reg/w0  : ruleset.c: END batch execution phase, entering to commit phase [processed 1 of 1 messages]
9276.518824285:main Q:Reg/w0  : ../action.c: actionCommitAllDirect: action 0, state 1, nbr to commit 1 isTransactional 1
9276.519066892:main Q:Reg/w0  : ../action.c: actionCommit[test-messages]: enter, 1 msgs
9276.519192614:main Q:Reg/w0  : ../action.c: actionCommit[test-messages]: processing...
9276.519303685:main Q:Reg/w0  : ../action.c: actionTryCommit[test-messages] enter
9276.519448497:main Q:Reg/w0  : ../action.c: doTransaction: have commitTransaction IF, using that, pWrkrInfo 0x63a8640
9276.519567098:main Q:Reg/w0  : ../action.c: entering actionCallCommitTransaction[test-messages], state: itx, nMsgs 1
9276.519695094:main Q:Reg/w0  : omfile.c: omfile: write to stream, pData->pStrm 0x63bb140, lenBuf 70, strt data 2017-11-02T16:47:56.496529-05:00 ubuntu-virtual-machine ubuntu hello!

9276.520126715:main Q:Reg/w0  : strm 0x63bb140: stream.c: strmFlushinternal: file 10(/var/log/rsyslog_testing.log) flush, buflen 70
9276.520257257:imudp.c        : main Q: queue.c: MultiEnqObj advised worker start
9276.520876806:main Q:Reg/w0  : strm 0x63bb140: stream.c: file 10(/var/log/rsyslog_testing.log) doWriteInternal: bFlush 1
9276.521020416:main Q:Reg/w0  : stream.c: strmPhysWrite, stream 0x63bb140, len 70
9276.521209030:main Q:Reg/w0  : strm 0x63bb140: stream.c: file 10 write wrote 70 bytes
9276.521365105:main Q:Reg/w0  : ../action.c: actionCallCommitTransaction[test-messages] state: itx mod commitTransaction returned 0
9276.521489372:main Q:Reg/w0  : ../action.c: action[test-messages] transitioned to state: rdy
9276.521595055:main Q:Reg/w0  : ../action.c: actionTryCommit[test-messages] past doTransaction
9276.521700866:main Q:Reg/w0  : ../action.c: actionTryCommit[test-messages] exit 0
9276.521806818:main Q:Reg/w0  : ../action.c: actionCommit[test-messages]: done, iRet 0
9276.527939217:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements has been processed
9276.528012631:main Q:Reg/w0  : queue.c: regular consumer finished, iret=0, szlog 0 sz phys 1
9276.528265910:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 1 objects and enqueued 0 objects
9276.528361443:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 0, phys 0
9276.528438635:main Q:Reg/w0  : queue.c: regular consumer finished, iret=4, szlog 0 sz phys 0
9276.531921877:main Q:Reg/w0  : wti.c: main Q:Reg/w0: worker IDLE, waiting for work.

That was from me calling the logger command with tcp and udp connectivity options:

ubuntu@ubuntu-virtual-machine:~$ logger --tcp --port 514 --server 192.168.146.131 "hello!"
ubuntu@ubuntu-virtual-machine:~$ logger --udp --port 514 --server 192.168.146.131 "hello!"

192.168.146.131 is the public IP for the Ubuntu 16.04 test VM I used to build/run rsyslog as shown above (sent message from the box where rsyslog was running).

Full steps taken to build/run rsyslog:

service rsyslog stop
sudo apt-get update
sudo apt-get -y install libtool autoconf automake valgrind git-core build-essential pkg-config libestr-dev zlib1g-dev uuid-dev libgcrypt20-dev liblogging-stdlog-dev libhiredis-dev uuid-dev libgcrypt11-dev liblogging-stdlog-dev flex bison libdbi-dev libmysqlclient-dev postgresql-client libpq-dev libnet-dev librdkafka-dev libgrok-dev libgrok1 libgrok-dev libpcre3-dev libtokyocabinet-dev libglib2.0-dev libmongo-client-dev
cd /tmp
git clone https://github.com/rsyslog/libfastjson
cd libfastjson/
sh autogen.sh
./configure
make
sudo make install
cd /tmp
git clone https://github.com/PascalWithopf/rsyslog
cd rsyslog
git checkout i-1920
sh autogen.sh
./configure --enable-imptcp
make
sudo make install
wget https://gist.githubusercontent.com/deoren/fd61fe29619d4387b643656c5671490d/raw/a9255c92fd9398a433826d5ce95d8d56d080b9cd/rsyslog-issue-1920.conf -O /tmp/rsyslog-issue-1920.conf
valgrind rsyslogd -dn -f /tmp/rsyslog-issue-1920.conf

This conf file was posted to rsyslog/rsyslog#1920 to reproduce the segfault encountered when checking for a blank JSON message property.

Example conf to repro segfault per rsyslog/rsyslog#1920

lock · 2019-12-26T21:30:50Z

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

ghost mentioned this issue Nov 2, 2017

Segfault when variable path consists of variables #1957

Merged

rgerhards closed this as completed in #1957 Nov 3, 2017

deoren added a commit to deoren/rsyslog-examples that referenced this issue Nov 27, 2017

Add example conf to repro segfault

e7a7f08

This conf file was posted to rsyslog/rsyslog#1920 to reproduce the segfault encountered when checking for a blank JSON message property.

deoren mentioned this issue Nov 27, 2017

Example conf to repro segfault per rsyslog/rsyslog#1920 deoren/rsyslog-examples#1

Merged

deoren added a commit to deoren/rsyslog-examples that referenced this issue Nov 27, 2017

Merge pull request #1 from deoren/i-1920

f0e51f5

Example conf to repro segfault per rsyslog/rsyslog#1920

lock bot locked as resolved and limited conversation to collaborators Dec 26, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Segfault when attempting to check length of non-existent JSON message property #1920

Segfault when attempting to check length of non-existent JSON message property #1920

deoren commented Oct 27, 2017 •

edited

deoren commented Oct 27, 2017

deoren commented Oct 27, 2017

ghost commented Oct 30, 2017

ghost commented Nov 2, 2017

rgerhards commented Nov 2, 2017

deoren commented Nov 2, 2017

deoren commented Nov 2, 2017

deoren commented Nov 2, 2017

lock bot commented Dec 26, 2019

Segfault when attempting to check length of non-existent JSON message property #1920

Segfault when attempting to check length of non-existent JSON message property #1920

Comments

deoren commented Oct 27, 2017 • edited

Configuration that can be used to repro the problem

Systems I used to reproduce the problem

Steps to reproduce

Debug/Valgrind output

Steps I followed to build from source

deoren commented Oct 27, 2017

deoren commented Oct 27, 2017

ghost commented Oct 30, 2017

ghost commented Nov 2, 2017

rgerhards commented Nov 2, 2017

deoren commented Nov 2, 2017

deoren commented Nov 2, 2017

deoren commented Nov 2, 2017

lock bot commented Dec 26, 2019

deoren commented Oct 27, 2017 •

edited