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.
