Ref-count increment is not required because callers are supposed to pass exclusive ownership while setting value of a key. What you are seeing is result of bad-usage (where caller probably free'ed up the json_object after setting it as value of some key).
To understand this better, look at some call-sites. Let us take an example, say set <x> = <y>; It calls msgSetJSONFromVar from execSet. Notice how in each scenario the json_object passed to msgAddJSON is an exclusive copy. If you go through all the call-sites that invoke msgAddJSON, you'll see that exclusive-copy-only is an invariant that is always maintained. The "bad-usage" that I mentioned above means some caller has not maintained that invariant, and that lead to the json_object being free'ed after adding it to msg. Am I making sense? On Wed, Jun 10, 2015 at 2:39 AM, David Boles (dboles) <[email protected]> wrote: > I finished setting up a debugging environment for 8.10.0 and spent some time > stepping through the code. First, I noticed that the json_object that was in > pMsg got overwritten on an unrelated call to json_object_new_object(). That > suggested that the json-c library thought it owned that memory while a pMsg > still had a pointer to it. In reading the code I noticed that in msgDelJSON() > under the condition "if(name[1] == '\0')" there is a json_object_put() but > under the matching condition in msgAddJSON() there is no json_object_get(). > > After more reading through the code to get a rough idea of code flow I > applied the following delta: > > --- ../pristine/rsyslog-8.10.0/runtime/msg.c 2015-05-19 03:53:40.000000000 > -0500 > +++ runtime/msg.c 2015-06-09 14:47:51.066158522 -0500 > @@ -4343,6 +4343,7 @@ > } > > if(name[1] == '\0') { /* full tree? */ > + json_object_get(json); > if(*pjroot == NULL) > *pjroot = json; > else > > and rebuilt. That change eliminated the overwriting of the pMsg->json object > and eliminated the segfault. I then performed the following steps: > > (1) launched the patched rsyslogd > (2) pumped 100K messages through it to reach steady state > (3) measured the memory footprint of rsyslogd > (4) pumped another 100K messages through it > (5) measured the RSS memory footprint of rsyslogd again and verified that > there was no change > > I don't know whether my patch is correct or not but I'll be continuing down > this path until I get feedback. If it is correct, then it's a fix for issue > #368. > > Thanks, > > David Boles > ________________________________________ > From: David Boles (dboles) > Sent: Monday, June 08, 2015 4:36 PM > To: rsyslog-users > Subject: RE: [rsyslog] Unable to use foreach > > Note - I don't get a segfault when mmexternal is enabled unless I also access > $!. I can log the contents of my mmexternal rewritten "msg" without error. > However, because I'm logging "msg" I get a quote-ified representation of the > JSON that I want. > > Even if my Python script doesn't modify anything but "msg", as soon as I > either do the RSYSLOG_DebugFormat action (which accesses $!) or perform > either an omfile or ommongodb action with a template referencing $! then > rsyslogd segfaults. I don't know rsyslogd internals at all but below you'll > find a backtrace from the point of the segfault. I've confirmed that it is > getting the "!" property and am working to set up a debugging environment now. > > This has been filed as an issue per Rainer's request several days ago. > > Thanks, > > David Boles > > ======== > > Program received signal SIGSEGV, Segmentation fault. > [Switching to Thread 0x7ffff4a2e700 (LWP 4761)] > printbuf_reset (p=0xffffffffffffffff) at printbuf.c:182 > 182 p->buf[0] = '\0'; > Missing separate debuginfos, use: debuginfo-install glib2-2.40.0-4.el7.x86_64 > glibc-2.17-55.el7.x86_64 l > iblogging-1.0.5-1.el7.x86_64 libmongo-client-0.1.8-1.el7.x86_64 > libuuid-2.23.2-22.el7_1.x86_64 systemd-l > ibs-208-20.el7_1.3.x86_64 zlib-1.2.7-13.el7.x86_64 > (gdb) bt > #0 printbuf_reset (p=0xffffffffffffffff) at printbuf.c:182 > #1 0x00007ffff719247e in json_object_to_json_string_ext (jso=0x7fffe8002580, > flags=flags@entry=1) > at json_object.c:274 > #2 0x00007ffff71924da in json_object_to_json_string (jso=<optimized out>) at > json_object.c:286 > #3 0x00007ffff7192d15 in json_object_get_string (jso=<optimized out>) at > json_object.c:738 > #4 0x000000000041b7d1 in getJSONPropVal (pMsg=<optimized out>, > pProp=0x6aaa00, > pRes=pRes@entry=0x7ffff4a2d968, buflen=buflen@entry=0x7ffff4a2d95c, > pbMustBeFreed=0x7ffff4a2da42) > at msg.c:2802 > #5 0x000000000041bbcc in MsgGetProp (pMsg=pMsg@entry=0x7ffff0004030, > pTpe=pTpe@entry=0x6aa9e0, > pProp=pProp@entry=0x6aaa00, pPropLen=pPropLen@entry=0x7ffff4a2da44, > pbMustBeFreed=pbMustBeFreed@entry=0x7ffff4a2da42, > ttNow=ttNow@entry=0x7ffff4a2db10) at msg.c:3285 > #6 0x000000000044472c in tplToString (pTpl=0x6a8700, > pMsg=pMsg@entry=0x7ffff0004030, > iparam=iparam@entry=0x7fffe8002940, ttNow=ttNow@entry=0x7ffff4a2db10) at > ../template.c:194 > #7 0x000000000043fbff in prepareDoActionParams (pWti=0x6b1fc0, > ttNow=0x7ffff4a2db10, > pMsg=0x7ffff0004030, pAction=0x6b9680) at ../action.c:933 > #8 processMsgMain (pAction=pAction@entry=0x6b9680, pWti=pWti@entry=0x6b1fc0, > pMsg=0x7ffff0004030, > ttNow=ttNow@entry=0x7ffff4a2db10) at ../action.c:1300 > #9 0x0000000000440337 in doSubmitToActionQ (pAction=0x6b9680, pWti=0x6b1fc0, > pMsg=<optimized out>) > at ../action.c:1449 > #10 0x00000000004390a7 in execAct (stmt=0x6b95f0, pWti=0x6b1fc0, > pMsg=0x7ffff0004030) at ruleset.c:202 > #11 scriptExec (root=<optimized out>, pMsg=pMsg@entry=0x7ffff0004030, > pWti=pWti@entry=0x6b1fc0) > at ruleset.c:454 > #12 0x0000000000439884 in processBatch (pBatch=0x6b1ff8, pWti=0x6b1fc0) at > ruleset.c:508 > #13 0x0000000000448cd4 in msgConsumer (notNeeded=<optimized out>, > pBatch=0x6b1ff8, pWti=0x6b1fc0) > at rsyslogd.c:575 > #14 0x00000000004357ee in ConsumerReg (pThis=0x6b1b20, pWti=0x6b1fc0) at > queue.c:1897 > #15 0x000000000043182e in wtiWorker (pThis=pThis@entry=0x6b1fc0) at wti.c:334 > #16 0x000000000043001a in wtpWorker (arg=0x6b1fc0) at wtp.c:389 > #17 0x00007ffff79b1df3 in start_thread () from /lib64/libpthread.so.0 > #18 0x00007ffff6aba3dd in clone () from /lib64/libc.so.6 > (gdb) list > 177 } > 178 } > 179 > 180 void printbuf_reset(struct printbuf *p) > 181 { > 182 p->buf[0] = '\0'; > 183 p->bpos = 0; > 184 } > 185 > 186 void printbuf_free(struct printbuf *p) > (gdb) p p > $1 = (struct printbuf *) 0xffffffffffffffff > > > ________________________________________ > From: [email protected] [[email protected]] > on behalf of David Lang [[email protected]] > Sent: Monday, June 08, 2015 3:40 PM > To: rsyslog-users > Subject: Re: [rsyslog] Unable to use foreach > > given that input, what does your python script output? > > since you are getting a segfault when mmexternal is enabled, I would guess > that > you are returning something invalid and rsyslog is not properly handling the > error. > > I'll also point out that what you are passing to your script is much larger > than > it needs to be (you have the same data in the original message, in rawmessge, > in > $! and sometimes in other things). I would suggest creating a template that > just > has $! in it, and set variables for anything you need that's not already in > there. > > David Lang > > On Mon, 8 Jun 2015, David Boles (dboles) wrote: > >> Date: Mon, 8 Jun 2015 20:34:45 +0000 >> From: "David Boles (dboles)" <[email protected]> >> Reply-To: rsyslog-users <[email protected]> >> To: rsyslog-users <[email protected]> >> Subject: Re: [rsyslog] Unable to use foreach >> >> David, >> >> Sorry for the delay in responding - my focus was elsewhere temporarily. What >> you say about $! and new content below makes sense. I've tried an experiment >> with the RSYSLOG_DebugFormat mechanism by running with the following >> /etc/rsyslog.conf tweaked in three ways: >> >> -------- >> module(load="imuxsock") >> module(load="mmexternal") >> module(load="mmjsonparse") >> module(load="ommongodb") >> >> template(name="yyd-log-info" type="list") { >> property(name="timestamp") >> constant(value=" ") >> property(name="hostname") >> constant(value=" ") >> property(name="msg") >> constant(value="\n") >> } >> >> # 1 >> *.* /var/log/debug_pre.log;RSYSLOG_DebugFormat >> >> if ($fromhost-ip == '127.0.0.1' and $syslogfacility-text != 'kern') then { >> action(type="mmjsonparse") >> if $parsesuccess == "OK" then { >> # 2 >> action(type="mmexternal" >> binary="/tmp/snowflake/rewriter.py" >> interface.input="fulljson" ) >> action(type="omfile" >> template="yyd-log-info" >> file="/var/log/yyd_anon.log") >> } >> } >> >> # 3 >> #*.* /var/log/debug_post.log;RSYSLOG_DebugFormat >> -------- >> >> (1) One mode was with the mmexternal action after # 2 commented out and the >> DebugFormat action at # 3, yielding: >> -------- >> Debug line with all properties: >> FROMHOST: 'dboles-victim-0', fromhost-ip: '127.0.0.1', HOSTNAME: >> 'dboles-victim-0', PRI: 12, >> syslogtag ':', programname: '', APP-NAME: '', PROCID: '-', MSGID: '-', >> TIMESTAMP: 'Jun 8 15:37:24', STRUCTURED-DATA: '-', >> msg: ' @cee:{"msg":"[umberlog test] testing ... 1, 2, >> 3\n","count":"2","el.0.type":"ladybug","el.0.name":"natalie","el.0.spots":"12","el.1.type":"ant","el.1.name":"B289","el.1.role":"worker","el.1.age":"9","pid":"32294","facility":"user","priority":"warn","uid":"1002","gid":"1002","host":"dboles-victim-0","program":"","timestamp":"2015-06-08T15:37:24.449217401-0400"}' >> escaped msg: ' @cee:{"msg":"[umberlog test] testing ... 1, 2, >> 3\n","count":"2","el.0.type":"ladybug","el.0.name":"natalie","el.0.spots":"12","el.1.type":"ant","el.1.name":"B289","el.1.role":"worker","el.1.age":"9","pid":"32294","facility":"user","priority":"warn","uid":"1002","gid":"1002","host":"dboles-victim-0","program":"","timestamp":"2015-06-08T15:37:24.449217401-0400"}' >> inputname: imuxsock rawmsg: '<12>Jun 8 15:37:24 : @cee:{"msg":"[umberlog >> test] testing ... 1, 2, >> 3\n","count":"2","el.0.type":"ladybug","el.0.name":"natalie","el.0.spots":"12","el.1.type":"ant","el.1.name":"B289","el.1.role":"worker","el.1.age":"9","pid":"32294","facility":"user","priority":"warn","uid":"1002","gid":"1002","host":"dboles-victim-0","program":"","timestamp":"2015-06-08T15:37:24.449217401-0400"}' >> $!:{ "msg": "[umberlog test] testing ... 1, 2, 3\n", "count": "2", >> "el.0.type": "ladybug", "el.0.name": "natalie", "el.0.spots": "12", >> "el.1.type": "ant", "el.1.name": "B289", "el.1.role": "worker", "el.1.age": >> "9", "pid": "32294", "facility": "user", "priority": "warn", "uid": "1002", >> "gid": "1002", "host": "dboles-victim-0", "program": "", "timestamp": >> "2015-06-08T15:37:24.449217401-0400" } >> $.: >> $/: >> -------- >> This makes sense - the mmjsonparse populates the $! element. >> >> (2) The second mode was with the mmexternal action at # 2 enabled and the >> DebugFormat action at # 3 - this results in rsyslogd suffering a segfault. >> >> >> (3) The third mode has the mmexternal action at # 2 enabled and the >> DebugFormat action at #1 enabled: >> >> Debug line with all properties: >> FROMHOST: 'dboles-victim-0', fromhost-ip: '127.0.0.1', HOSTNAME: >> 'dboles-victim-0', PRI: 12, >> syslogtag ':', programname: '', APP-NAME: '', PROCID: '-', MSGID: '-', >> TIMESTAMP: 'Jun 8 15:41:26', STRUCTURED-DATA: '-', >> msg: ' @cee:{"msg":"[umberlog test] testing ... 1, 2, >> 3\n","count":"2","el.0.type":"ladybug","el.0.name":"natalie","el.0.spots":"12","el.1.type":"ant","el.1.name":"B289","el.1.role":"worker","el.1.age":"9","pid":"1828","facility":"user","priority":"warn","uid":"1002","gid":"1002","host":"dboles-victim-0","program":"","timestamp":"2015-06-08T15:41:26.302102005-0400"}' >> escaped msg: ' @cee:{"msg":"[umberlog test] testing ... 1, 2, >> 3\n","count":"2","el.0.type":"ladybug","el.0.name":"natalie","el.0.spots":"12","el.1.type":"ant","el.1.name":"B289","el.1.role":"worker","el.1.age":"9","pid":"1828","facility":"user","priority":"warn","uid":"1002","gid":"1002","host":"dboles-victim-0","program":"","timestamp":"2015-06-08T15:41:26.302102005-0400"}' >> inputname: imuxsock rawmsg: '<12>Jun 8 15:41:26 : @cee:{"msg":"[umberlog >> test] testing ... 1, 2, >> 3\n","count":"2","el.0.type":"ladybug","el.0.name":"natalie","el.0.spots":"12","el.1.type":"ant","el.1.name":"B289","el.1.role":"worker","el.1.age":"9","pid":"1828","facility":"user","priority":"warn","uid":"1002","gid":"1002","host":"dboles-victim-0","program":"","timestamp":"2015-06-08T15:41:26.302102005-0400"}' >> $!: >> $.: >> $/: >> >> -------- >> >> You also asked for what my external Python script gets as input: >> >> { "msg": " @cee:{\"msg\":\"[umberlog test] testing ... 1, 2, >> 3\\n\",\"count\":\"2\",\"el.0.type\":\" >> ladybug\",\"el.0.name\":\"natalie\",\"el.0.spots\":\"12\",\"el.1.type\":\"ant\",\"el.1.name\":\"B289 >> \",\"el.1.role\":\"worker\",\"el.1.age\":\"9\",\"pid\":\"4440\",\"facility\":\"user\",\"priority\":\ >> "warn\",\"uid\":\"1002\",\"gid\":\"1002\",\"host\":\"dboles-victim-0\",\"program\":\"\",\"timestamp\ >> ":\"2015-06-08T16:28:12.877502675-0400\"}", "rawmsg": "<12>Jun 8 16:28:12 : >> @cee:{\"msg\":\"[umberl >> og test] testing ... 1, 2, >> 3\\n\",\"count\":\"2\",\"el.0.type\":\"ladybug\",\"el.0.name\":\"natalie\ >> ",\"el.0.spots\":\"12\",\"el.1.type\":\"ant\",\"el.1.name\":\"B289\",\"el.1.role\":\"worker\",\"el.1 >> .age\":\"9\",\"pid\":\"4440\",\"facility\":\"user\",\"priority\":\"warn\",\"uid\":\"1002\",\"gid\":\ >> "1002\",\"host\":\"dboles-victim-0\",\"program\":\"\",\"timestamp\":\"2015-06-08T16:28:12.877502675- >> 0400\"}", "timereported": "2015-06-08T16:28:12.877616-04:00", "hostname": >> "dboles-victim-0", "syslog >> tag": ":", "inputname": "imuxsock", "fromhost": "dboles-victim-0", >> "fromhost-ip": "127.0.0.1", "pri" >> : "12", "syslogfacility": "1", "syslogseverity": "4", "timegenerated": >> "2015-06-08T16:28:12.877616-0 >> 4:00", "programname": "", "protocol-version": "0", "structured-data": "-", >> "app-name": "", "procid": >> "-", "msgid": "-", "uuid": null, "$!": { "msg": "[umberlog test] testing ... >> 1, 2, 3\n", "count": " >> 2", "el.0.type": "ladybug", "el.0.name": "natalie", "el.0.spots": "12", >> "el.1.type": "ant", "el.1.na >> me": "B289", "el.1.role": "worker", "el.1.age": "9", "pid": "4440", >> "facility": "user", "priority": >> "warn", "uid": "1002", "gid": "1002", "host": "dboles-victim-0", "program": >> "", "timestamp": "2015-0 >> 6-08T16:28:12.877502675-0400" } } >> >> >> >> >> >> ________________________________________ >> From: [email protected] [[email protected]] >> on behalf of David Lang [[email protected]] >> Sent: Monday, June 01, 2015 5:06 PM >> To: rsyslog-users >> Subject: Re: [rsyslog] Unable to use foreach >> >> On Sun, 24 May 2015, David Boles (dboles) wrote: >> >>> Thanks Rainer / David, >>> >>> Based on Rainer's input I've pivoted to going down the mmexternal path and >>> have questions based on experimenting with that. >>> >>> To answer David's "what are you trying to do" question and make things as >>> simple and concrete as possible I've created a clean example (log entry >>> generator, rsyslog configuration, mmexternal plugin, etc.) that captures >>> what I'm trying to do. To avoid pasting a bunch of stuff into these emails >>> I set up a git repo with the example at: >>> >>> https://github.com/davidboles/snowflake.git >>> >>> The README.md explains the elements of that repo. I have the following >>> questions: >>> >>> (1) The generated result does not have the { "hostname" : "frodo" } anywhere >>> in it. The docs say that I can add elements to the JSON elements of the >>> message, although that sentence is ambiguous as to whether I can do so if I >>> haven't modified some other element. >> >> sorry for the delay in responding >> >> in rsyslog, you don't have many elements. There are only a handful of >> built-in >> properties and then everything else is in $! >> >> so if you want to modify anything in $!, you must output a completely new $! >> string (which is the JSON representation of the tree. >> >> If you are wanting to add a new item "elements", that means that you are >> going >> to modify the $! variable to include your new element. >> >> the section talking about "if you modify the message variable tree" is saying >> that if you don't change $!, you can't add new variables, because all >> variables >> are inside of $!. >> >> although, since this talks about the inability to delete things, it may be >> that >> what you output is merged with what's already in $!. I'd have to test this >> (see >> how to test below) >> >>> (2) If I uncomment the template line (line 20 of build.conf) then syslog >>> SEGV's. How do I access the jsonmesg content after getting stuff back >>> through >>> mmexternal? >> >> it's not line 20 in the currently visible file, but the best way to >> troubleshoot >> "how do I access blah" is to write a file with the format RSYSLOG_DebugFormat >> and it will show you all the variables that are defined at that point. In a >> situation like yours where you are doing multiple parse actions, it will show >> you the variables as of that point in the processing. >> >> so, to see how to access the variables that were set with mmexternal, after >> that >> action add another one >> /var/log/test-debug;RSYSLOG_DebugFormat >> >> and then look at the $!: line in that debug output. It will show you exactly >> what variables are defined at that point. >> >> I suspect that what you are outputting doesn't quite match >> >>> (3) The field "MUTABLE" has the value "Alpha" in the input to the mmexternal >>> unit (I can see it in /tmp/rewriter.trace entries). What JSON should my >>> rewriter.py emit to cause that to be rewritten to "Beta"? >> >> I think it would be useful for you to show what the string is that >> rewriter.py >> receives, what it outputs, and what the resulting debug is. I think that will >> make it pretty obvious as to what's happening >> >> David Lang >> >>> Thanks, >>> >>> David Boles >>> >>> >>> >>> ________________________________________ >>> From: [email protected] [[email protected]] >>> on behalf of Rainer Gerhards [[email protected]] >>> Sent: Friday, May 22, 2015 5:05 PM >>> To: rsyslog-users >>> Subject: Re: [rsyslog] Unable to use foreach >>> >>> External plugin interface: >>> https://github.com/rsyslog/rsyslog/blob/master/plugins/external/INTERFACE.md >>> >>> Overview : >>> https://github.com/rsyslog/rsyslog/blob/master/plugins/external/README.md >>> >>> Sent from phone, thus brief. >>> _______________________________________________ >>> rsyslog mailing list >>> http://lists.adiscon.net/mailman/listinfo/rsyslog >>> http://www.rsyslog.com/professional-services/ >>> What's up with rsyslog? Follow https://twitter.com/rgerhards >>> NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of >>> sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T >>> LIKE THAT. >>> >> _______________________________________________ >> rsyslog mailing list >> http://lists.adiscon.net/mailman/listinfo/rsyslog >> http://www.rsyslog.com/professional-services/ >> What's up with rsyslog? Follow https://twitter.com/rgerhards >> NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of >> sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T >> LIKE THAT. >> _______________________________________________ >> rsyslog mailing list >> http://lists.adiscon.net/mailman/listinfo/rsyslog >> http://www.rsyslog.com/professional-services/ >> What's up with rsyslog? Follow https://twitter.com/rgerhards >> NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of >> sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T >> LIKE THAT. >> > _______________________________________________ > rsyslog mailing list > http://lists.adiscon.net/mailman/listinfo/rsyslog > http://www.rsyslog.com/professional-services/ > What's up with rsyslog? Follow https://twitter.com/rgerhards > NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of > sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T > LIKE THAT. > _______________________________________________ > rsyslog mailing list > http://lists.adiscon.net/mailman/listinfo/rsyslog > http://www.rsyslog.com/professional-services/ > What's up with rsyslog? Follow https://twitter.com/rgerhards > NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of > sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T > LIKE THAT. -- Regards, Janmejay http://codehunk.wordpress.com _______________________________________________ rsyslog mailing list http://lists.adiscon.net/mailman/listinfo/rsyslog http://www.rsyslog.com/professional-services/ What's up with rsyslog? Follow https://twitter.com/rgerhards NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.
