Bug 989886

Summary: rsyslog-mmjsonparse plugin from fedora repo doesn't work
Product: [Fedora] Fedora Reporter: Bala.FA <barumuga>
Component: rsyslogAssignee: Tomas Heinrich <theinric>
Status: CLOSED EOL QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 19CC: barumuga, dpati, jlieskov, lkundrak, mah.darade, pvrabec, theinric
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1052951 (view as bug list) Environment:
Last Closed: 2015-02-17 16:25:57 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1052951    

Description Bala.FA 2013-07-30 06:39:41 UTC 
Description of problem:
mmjsonparse fails to parse json message.

Version-Release number of selected component (if applicable):

Name        : rsyslog-mmjsonparse
Arch        : x86_64
Version     : 7.2.6
Release     : 1.fc19
Size        : 11 k
Repo        : installed
From repo   : fedora
Summary     : JSON enhanced logging support
URL         : http://www.rsyslog.com/
License     : (GPLv3+ and ASL 2.0)
Description : This module provides the capability to recognize and parse JSON
            : enhanced syslog messages.


How reproducible:

Add below config into rsyslog #### GLOBAL DIRECTIVES #### 

#$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$ModLoad mmjsonparse
:mmjsonparse:
template(name="GLFS_template" type="list") {
   constant(value="[")
   property(name="timereported" dateFormat="rfc3339")
   constant(value="] ")
   property(name="$!msg")
   constant(value="\n")
}
$ActionFileDefaultTemplate GLFS_template


and restart rsyslog

Steps to Reproduce:
1. run command # logger '@cee: {"msg": "json message"}'

Actual results:
raw json message appears in log file.  for example

[2013-07-30T12:04:49.927523+05:30]  {"msg": "json message"}


Expected results:
parsed json message should appear.  for example

[2013-07-30T11:57:22.660955+05:30] json message


Additional info:

Running rsyslog in debug mode throws below


6172.415459260:7f7f82513700: Message from UNIX socket: #4
6172.415481722:7f7f82513700: main Q: entry added, size now log 1, phys 1 entries
6172.415488519:7f7f82513700: main Q: EnqueueMsg advised worker start
6172.415491862:7f7f82513700: --------imuxsock calling select, active file descriptors (max 4): 4 
6172.415501658:7f7f81471700: wti 0x7f7f857fcff0: worker awoke from idle processing
6172.415505597:7f7f81471700: we deleted 0 objects and enqueued 0 objects
6172.415507350:7f7f81471700: delete batch from store, new sizes: log 1, phys 1
6172.415510217:7f7f81471700: processBatch: batch of 1 elements must be processed
6172.415513059:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active (nil), stmt 0x7f7f85801130, nodetype 4004
6172.415515619:7f7f81471700: RRRR: execAct [mmjsonparse]: batch of 1 elements, active (nil)
6172.415518624:7f7f81471700: Called action(NotAllMark), processing batch[0] via 'mmjsonparse'
6172.415520590:7f7f81471700: Called action(Batch), logging to mmjsonparse
6172.415523379:7f7f81471700: tryDoAction 0x7f7f858016e0, pnElem 1, nElem 1
6172.415525486:7f7f81471700: Action 0x7f7f858016e0 transitioned to state: itx
6172.415527344:7f7f81471700: entering actionCalldoAction(), state: itx
6172.415529946:7f7f81471700: mmjsonparse: toParse: ' {"msg": "json message"}'
6172.415551947:7f7f81471700: mmjsonparse: Error parsing JSON ' {"msg": "json message"}': Extra characters after JSON object
6172.415555778:7f7f81471700: Action 0x7f7f858016e0 transitioned to state: rdy
6172.415557880:7f7f81471700: action 0x7f7f858016e0 call returned 0
6172.415560613:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active (nil), stmt 0x7f7f85802080, nodetype 4001
6172.415562840:7f7f81471700: batch: item 0 PRIFILT 1
6172.415564789:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active 0x7f7f740008c0, stmt 0x7f7f85801190, nodetype 4004
6172.415567083:7f7f81471700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f7f740008c0
6172.415569147:7f7f81471700: Called action(NotAllMark), processing batch[0] via 'builtin:omfile'
6172.415570926:7f7f81471700: Called action(Batch), logging to builtin:omfile
6172.415577211:7f7f81471700: tryDoAction 0x7f7f85801e30, pnElem 1, nElem 1
6172.415579223:7f7f81471700: Action 0x7f7f85801e30 transitioned to state: itx
6172.415581006:7f7f81471700: entering actionCalldoAction(), state: itx
6172.415583062:7f7f81471700: file to log to: /var/log/messages
6172.415584985:7f7f81471700: write to stream, pData->pStrm 0x7f7f74000ef0, lenBuf 60
6172.415587223:7f7f81471700: action 0x7f7f85801e30 call returned -2121
6172.415589773:7f7f81471700: strm 0x7f7f74000ef0: file 6(messages) flush, buflen 60
6172.415592062:7f7f81471700: strmPhysWrite, stream 0x7f7f74000ef0, len 60
6172.415610465:7f7f81471700: strm 0x7f7f74000ef0: file 6 write wrote 60 bytes
6172.415612931:7f7f81471700: Action 0x7f7f85801e30 transitioned to state: rdy
6172.415615361:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active (nil), stmt 0x7f7f85803010, nodetype 4001
6172.415617408:7f7f81471700: batch: item 0 PRIFILT 0
6172.415619258:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active 0x7f7f740008c0, stmt 0x7f7f858020e0, nodetype 4004
6172.415621227:7f7f81471700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f7f740008c0
6172.415622944:7f7f81471700: Called action(Batch), logging to builtin:omfile
6172.415625303:7f7f81471700: tryDoAction 0x7f7f85802ac0, pnElem 1, nElem 1
6172.415627273:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active (nil), stmt 0x7f7f85803700, nodetype 4001
6172.415629176:7f7f81471700: batch: item 0 PRIFILT 0
6172.415630840:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active 0x7f7f740008c0, stmt 0x7f7f85803070, nodetype 4004
6172.415633396:7f7f81471700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f7f740008c0
6172.415635013:7f7f81471700: Called action(Batch), logging to builtin:omfile
6172.415637054:7f7f81471700: tryDoAction 0x7f7f858031b0, pnElem 1, nElem 1
6172.415638917:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active (nil), stmt 0x7f7f85803df0, nodetype 4001
6172.415640788:7f7f81471700: batch: item 0 PRIFILT 0
6172.415642482:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active 0x7f7f740008c0, stmt 0x7f7f85803760, nodetype 4004
6172.415644482:7f7f81471700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f7f740008c0
6172.415646100:7f7f81471700: Called action(Batch), logging to builtin:omfile
6172.415647988:7f7f81471700: tryDoAction 0x7f7f858038a0, pnElem 1, nElem 1
6172.415649864:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active (nil), stmt 0x7f7f85804510, nodetype 4001
6172.415651748:7f7f81471700: batch: item 0 PRIFILT 0
6172.415653512:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active 0x7f7f740008c0, stmt 0x7f7f85803e50, nodetype 4004
6172.415655795:7f7f81471700: RRRR: execAct [builtin:omusrmsg]: batch of 1 elements, active 0x7f7f740008c0
6172.415657395:7f7f81471700: Called action(Batch), logging to builtin:omusrmsg
6172.415659373:7f7f81471700: tryDoAction 0x7f7f85803fc0, pnElem 1, nElem 1
6172.415661240:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active (nil), stmt 0x7f7f85804c00, nodetype 4001
6172.415663160:7f7f81471700: batch: item 0 PRIFILT 0
6172.415664819:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active 0x7f7f740008c0, stmt 0x7f7f85804570, nodetype 4004
6172.415666909:7f7f81471700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f7f740008c0
6172.415668518:7f7f81471700: Called action(Batch), logging to builtin:omfile
6172.415670543:7f7f81471700: tryDoAction 0x7f7f858046b0, pnElem 1, nElem 1
6172.415672473:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active (nil), stmt 0x7f7f857fcae0, nodetype 4001
6172.415674387:7f7f81471700: batch: item 0 PRIFILT 0
6172.415676088:7f7f81471700: RRRR: scriptExec: batch of 1 elements, active 0x7f7f740008c0, stmt 0x7f7f85804c60, nodetype 4004
6172.415678141:7f7f81471700: RRRR: execAct [builtin:omfile]: batch of 1 elements, active 0x7f7f740008c0
6172.415679720:7f7f81471700: Called action(Batch), logging to builtin:omfile
6172.415681704:7f7f81471700: tryDoAction 0x7f7f85804da0, pnElem 1, nElem 1
6172.416721483:7f7f81471700: ruleset.ProcessMsg() returns 0
6172.416724669:7f7f81471700: regular consumer finished, iret=0, szlog 0 sz phys 1
6172.416728384:7f7f81471700: we deleted 1 objects and enqueued 0 objects
6172.416730225:7f7f81471700: delete batch from store, new sizes: log 0, phys 0
6172.416732276:7f7f81471700: regular consumer finished, iret=4, szlog 0 sz phys 0
6172.416734222:7f7f81471700: main Q:Reg/w0: worker IDLE, waiting for work.



After recompiling rsyslog-7.2.6-1.fc19.src.rpm got from fedora repo on fedora 19 system solves this.
Comment 3 Tomas Heinrich 2014-01-07 17:26:35 UTC 
Bala, can you test that this now works correctly with the latest packages in f19/f20?

It works for me with
json-c-0.11-5.fc21.x86_64
rsyslog-7.4.2-2.fc20.x86_64
Comment 4 Fedora End Of Life 2015-01-09 19:09:50 UTC 
This message is a notice that Fedora 19 is now at end of life. Fedora 
has stopped maintaining and issuing updates for Fedora 19. It is 
Fedora's policy to close all bug reports from releases that are no 
longer maintained. Approximately 4 (four) weeks from now this bug will
be closed as EOL if it remains open with a Fedora 'version' of '19'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 19 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.
Comment 5 Fedora End Of Life 2015-02-17 16:25:57 UTC 
Fedora 19 changed to end-of-life (EOL) status on 2015-01-06. Fedora 19 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.