Segmentation fault using 2.0.2 (rsyslog 8.23)

[mostolog]

Hi

echo "a" | /usr/lib/lognorm/lognormalizer -r a.rb
Segmentation fault (core dumped)

File a.rb:

version=2

#foo

type=@rfc3164pri:<%priority:number%>
type=@rfc3164header:%date:date-rfc3164% %hostname:word%
type=@rfc3164tag:%syslogtag:char-to{"extradata":":"}%:
type=@rfc3164:%.:@rfc3164pri%%.:@rfc3164header% %.:@rfc3164tag%
type=@rfc3164:%.:@rfc3164header% %.:@rfc3164tag%
type=@syslog:%.:@rfc3164%

#bar
#
#it complains liblognorm error: rulebase file a.rb[23]: invalid
record type detected: ']%'
#if written this way:
#  {"type":"rest","name":"message"}
#]%
# Theres a blank line at the end of file
rule=:%[
  {"type":"@syslog","name":"a"},
  {"type":"rest","name":"message"}]%

[mostolog]

After some more testing, this is what I have observed so far

• Some logs come from app1, which is rfc3164 compliant + bunch of fields I would like to parse
• Other logs come from app2, which is rfc5424 compliant + bunch of fields I would like to parse
• The rest are either rfc3164 or rfc5424, which an unknown set of fields I cant parse by now.

With this in mind, I though it would've been correct to define types as follows:

type=@rfc3164:...
type=@rfc5424:...
type=@syslog:%.:@rfc3164%
type=@syslog:%.:@rfc3164%

rule=app1:%.:@syslog% ...specific app1 fields
rule=app2:%.:@syslog% ...specific app2 fields
rule=app:%.:@syslog% %message:rest%

But seems "type of type of type" kind of doesn't like to liblognorm.

Updated to clarify:

This works:

type=@syslog_pri:<%priority:number%>
type=@rfc3164:%.:@syslog_pri%...
rule=:%.:@rfc3164%...

But this doesn't:

type=@syslog_pri:<%priority:number%>
type=@rfc3164:%.:@syslog_pri%...
type=@syslog:%.:@rfc3164%
rule=:%.:@syslog%...

Could anyone give me some answers?

Thanks

[mostolog]

Another segfault reproducer:

version=2

type=@syslog_pri:<%priority:number%>
#> highlight
type=@rfc3164_header:%date:date-rfc3164% %hostname:word%
type=@rfc3164_msg:%syslogtag:char-to{"extradata":":"}%: %message:rest%
type=@rfc3164:%.:@syslog_pri%%.:@rfc3164_header% %.:@rfc3164_msg%
#. hightlight
type=@rfc3164:%.:@rfc3164_header% %.:@rfc3164_msg%
#. hightlight

# Uncomment these to get a segfault
#type=@rfc5424_header:%date:char-to{"extradata":" "}% %hostname:word% %app-name:char-to{"extradata":" "}%
#rule=:%.:@rfc5424_header%


#type=@rfc5424:%.:@rfc5424_header% %message:rest%
#type=@rfc5424:<%priority:number%>%.:@rfc5424_header% %message:rest%
#. hightlight

# Uncomment those to get a segfault
#type=@syslog:%.:@rfc3164%
#type=@syslog:%.:@rfc5424%
#rule=:%.:@syslog%

rule=:%.:@rfc3164%

[mostolog]

@rgerhards Did you notice this issue?

Running:

echo "<167>2017-02-09T09:31:48.403058+01:00 computer appname[1234]: REDACTED" | /usr/lib/lognorm/lognormalizer -r /my.rb

This works (header is defined with multiple date formats):

type=@syslog_pri:<%priority:number%>
type=@syslog_header:%date:date-rfc3164% %hostname:word%
type=@syslog_header:%date:date-rfc5424% %hostname:word%
type=@syslog_tag:%syslogtag:char-to{"extradata":":"}%:
type=@syslog:%.:@syslog_pri%%.:@syslog_header% %.:@syslog_tag%
type=@syslog:%.:@syslog_header% %.:@syslog_tag%

rule=:%.:@syslog% %message:rest%

This doesn't (syslog_date type is defined and referenced in header) and causes segfault

type=@syslog_pri:<%priority:number%>
type=@syslog_date:%date:date-rfc3164%
type=@syslog_date:%date:date-rfc5424%
type=@syslog_header:%.:@syslog_date% %hostname:word%
type=@syslog_tag:%syslogtag:char-to{"extradata":":"}%:
type=@syslog:%.:@syslog_pri%%.:@syslog_header% %.:@syslog_tag%
type=@syslog:%.:@syslog_header% %.:@syslog_tag%

rule=:%.:@syslog% %message:rest%

[rgerhards]

not really, currently busy with other things. Will come to this here when I have time, except if someone else fixed it already ;-)

In general, you do not need to ping me on those cases, I usually ;-) do not overlook things. When I am done with the current todo list, I'll simply go through the issue trackers and pick the next thing(s) to do.

[20ton]

The problem occurs when a user type references another user type : a pointer to the first type is stored in the second, but the array is realloc-ed when you add a third user type, and the pointer becomes invalid.

valgrind says it all (line numbers from master today):

==17969== Invalid read of size 8
==17969==    at 0x504BD7A: tryParser (pdag.c:1439)
==17969==    by 0x504BD7A: ln_normalizeRec (pdag.c:1569)
==17969==    by 0x504BD82: tryParser (pdag.c:1439)
==17969==    by 0x504BD82: ln_normalizeRec (pdag.c:1569)
==17969==    by 0x504BE17: ln_normalizeRec (pdag.c:1575)
==17969==    by 0x504C3FD: ln_normalize (pdag.c:1647)
==17969==    by 0x109D0F: normalize (lognormalizer.c:228)
==17969==    by 0x109D0F: main (lognormalizer.c:511)
==17969==  Address 0x5cb9bd8 is 8 bytes inside a block of size 32 free'd
==17969==    at 0x4C2EDAF: realloc (vg_replace_malloc.c:785)
==17969==    by 0x504A842: ln_pdagFindType (pdag.c:159)
==17969==    by 0x504E0AC: processType (samp.c:648)
==17969==    by 0x504E0AC: ln_processSamp (samp.c:886)
==17969==    by 0x504E0AC: ln_sampRead (samp.c:1048)
==17969==    by 0x504E6AF: ln_sampLoad (samp.c:1160)
==17969==    by 0x5049AAB: ln_loadSamples (liblognorm.c:167)
==17969==    by 0x109F4C: main (lognormalizer.c:489)
==17969==  Block was alloc'd at
==17969==    at 0x4C2EDAF: realloc (vg_replace_malloc.c:785)
==17969==    by 0x504A842: ln_pdagFindType (pdag.c:159)
==17969==    by 0x504E0AC: processType (samp.c:648)
==17969==    by 0x504E0AC: ln_processSamp (samp.c:886)
==17969==    by 0x504E0AC: ln_sampRead (samp.c:1048)
==17969==    by 0x504E6AF: ln_sampLoad (samp.c:1160)
==17969==    by 0x5049AAB: ln_loadSamples (liblognorm.c:167)
==17969==    by 0x109F4C: main (lognormalizer.c:489)

Reduced reproducer:

version=2
type=@hex-byte:%..:hexnumber{"maxval": "255"}%
type=@two-hex-bytes:%f1:@hex-byte% %f2:@hex-byte%
type=@unused:stop
rule=:two bytes %.:@two-hex-bytes% %-:@unused%

Pull request: #289

[davidelang]

does this problem still happen with the current version?

[20ton]

Yes, I've found it in 2.0.3-1~bpo9+1 (debian backports), but the problem is still present with a fresh checkout

[solhuebner]

@20ton did 2.0.5 fix the issue?

[20ton]

Nope, it was merged less than one hour after the release:

commit e94a801 (HEAD -> master, origin/master, origin/HEAD)
Merge: 28b7c1f 3a9b136
Author: Rainer Gerhards rgerhards@adiscon.com
Date: Thu Apr 26 12:15:10 2018 +0200

Merge pull request #289 from 20ton/nested-user-types

Fix for use after free (issue #235)

commit 28b7c1f
Author: Rainer Gerhards rgerhards@adiscon.com
Date: Thu Apr 26 12:12:25 2018 +0200

bump version number for next release cycle

commit 2179061 (tag: v2.0.5, origin/stable)
Author: Rainer Gerhards rgerhards@adiscon.com
Date: Thu Apr 26 11:27:39 2018 +0200

prepare for 2.0.5 release

[solhuebner]

I see :)
Thanks for the details