[rsyslog-notify] Forum Thread: Re: Strange linebreak with Jboss access logs - (Mode 'reply')

[noreply at adiscon.com]

User: Chriss.ko 
Forumlink: http://kb.monitorware.com/viewtopic.php?p=24278#p24278

Message: 
----------
Hi Rainer,

I'm sure it was a transient error in my googled config. :( 

Well, I have a other strange error now which came up after a bit testing. I
would like to ask you for some assistance here as well. 

All the lines show up in the jboss-1-access.log twice now:

[code:1hev39i3]
Feb 28 14:38:59 devfe1 JB1access-log 10.0.0.30
[28/Feb/2014:14:38:44 +0100] 0 HTTP/1.1 11001
http-executor-threads - 2372 /as7_logo.png 200 GET 22866
Feb 28 14:38:59 devfe1 JB1access-log  10.0.0.30
[28/Feb/2014:14:38:44 +0100] 0 HTTP/1.1 11001
http-executor-threads - 2372 /as7_logo.png 200 GET 22866
[/code:1hev39i3]

They are not pure double, the second line has two blanks between the
JB1access-log and the 10.0.0.30, so the first line is the one I have on the
sending site.

Client:

[code:1hev39i3]
$template FormatJB1Access,"<188>%TIMESTAMP% %HOSTNAME% %syslogtag%
%msg:::sp-if-no-1st-sp%%msg%\n"

$InputFileName /own/log/jboss/access_log.%$YEAR%-%$MONTH%-%$DAY%
$InputFileTag JB1access-log
$InputFileStateFile stat-JB1access-log
#$InputFileReadMode 2
#$InputFileFacility local2
#$InputFileSeverity info
$InputRunFileMonitor
if $app-name == 'JB1access-log' then @@loghost:514;FormatJB1Access
if $app-name == 'JB1access-log' then /tmp/jb1test
if $app-name == 'JB1access-log' then ~
[/code:1hev39i3]

The /tmp/jb1test looks like that:
[code:1hev39i3]
10.0.0.30 [28/Feb/2014:14:38:44 +0100] 0
HTTP/1.1 11001 http-executor-threads - 2372 /as7_logo.png 200 GET
22866
[/code:1hev39i3]

I reduced the server to the absolute minimum testing configuration:
[code:1hev39i3]
ModLoad imtcp
$InputTCPServerRun 514

$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

$template TraditionalFormat,"%timegenerated% %HOSTNAME%
%syslogtag%%msg:::drop-last-lf%\n"

$template Jboss1AccessLogHostLogs,"/own/log/%FROMHOST%/test.log"
if \
        $source != 'adm' \
                and \
        $app-name contains 'JB1access-log' \
then -?Jboss1AccessLogHostLogs
[/code:1hev39i3]


So I looked a bit into the debug log and I found that:
This is the correct one:
[code:1hev39i3]
4993.564722155:7f2d99961700: rainerscript: executing step,
opcode 2...
4993.564759331:7f2d99961700: rainerscript: opcode AND
4993.564778597:7f2d99961700: rainerscript: script
execution terminated with state 0
4993.564797420:7f2d99961700: result of rainerscript filter
evaluation: 0
4993.564816693:7f2d99961700: Processing next action
4993.564844738:7f2d99961700: Called action(Batch), logging to
builtin-file
4993.564865149:7f2d99961700: XXXXX:  tryDoAction
0x7f2d9d2f0c80, pnElem 4, nElem 4
4993.564885189:7f2d99961700: ruleset: get iRet 0 from
rule.ProcessMsg()
4993.564904148:7f2d99961700: ruleset.ProcessMsg() returns 0
4993.564923247:7f2d99961700: regular consumer finished, iret=0,
szlog 0 sz phys 4
4993.564945763:7f2d99961700: we deleted 4 objects and enqueued
0 objects
4993.564988087:7f2d99961700: delete batch from store, new
sizes: log 0, phys 0
4993.565007857:7f2d99961700: regular consumer finished, iret=4,
szlog 0 sz phys 0
4993.565026586:7f2d99961700: main Q:Reg/w0: worker
IDLE, waiting for work.
4994.362330049:7f2d98f60700: poll returned with i 0, pUsr
0x7f2d8c00ec50
4994.362381671:7f2d98f60700: netstream 0x7f2d8c00ecc0 with new
data
4994.362452381:7f2d98f60700: main Q: entry added, size now
log 1, phys 1 entries
4994.362485233:7f2d98f60700: main Q: MultiEnqObj advised
worker start
4994.362739261:7f2d99961700: wti 0x7f2d9d2ef890: worker
awoke from idle processing
4994.362776388:7f2d99961700: we deleted 0 objects and enqueued
0 objects
4994.362796475:7f2d99961700: delete batch from store, new
sizes: log 1, phys 1
4994.362821279:7f2d99961700: msg parser: flags 30, from
'devfe1.example.de', msg '<133>Feb 28 14:43:19 devfe1
JB1access-log 10.0.0.30 [28/Feb/'
4994.362841454:7f2d99961700: parse using parser list
0x7f2d9d2e4130 (the default list).
4994.362862738:7f2d99961700: Parser 'rsyslog.rfc5424'
returned -2160
4994.362882481:7f2d99961700: Message will now be parsed by the
legacy syslog parser (one size fits all... ;)).
4994.362903777:7f2d99961700: MsgSetTAG in: len 13,
pszBuf: JB1access-log
4994.362922838:7f2d99961700: MsgSetTAG exit: pMsg->iLenTAG
13, pMsg->TAG.szBuf: JB1access-log
4994.362941534:7f2d99961700: Parser 'rsyslog.rfc3164'
returned 0
4994.362960994:7f2d99961700: processBatch: batch of 1
elements must be processed
4994.362980539:7f2d99961700: Processing next rule
4994.363007800:7f2d99961700: rainerscript: executing step,
opcode 1002...
4994.363027782:7f2d99961700: rainerscript: opcode
PUSHMSGVAR
4994.363078682:7f2d99961700: rainerscript: executing step,
opcode 1003..
[/code:1hev39i3]

And this the failed:
[code:1hev39i3]
4994.363238337:7f2d99961700: rainerscript: executing step,
opcode 105...
4994.363257091:7f2d99961700: rainerscript: opcode
CMP_CONTAINS
4994.363277021:7f2d99961700: rainerscript: executing step,
opcode 2...
4994.363295766:7f2d99961700: rainerscript: opcode AND
4994.363314965:7f2d99961700: rainerscript: script
execution terminated with state 0
4994.363352803:7f2d99961700: result of rainerscript filter
evaluation: 1
4994.363375480:7f2d99961700: Processing next action
4994.363398206:7f2d99961700: Called action(NotAllMark),
processing batch[0] via 'builtin-file'
4994.363417534:7f2d99961700: Called action(Batch), logging to
builtin-file
4994.363443196:7f2d99961700: prop repl 4,
pRes='devfe1.example.de', len -1
4994.363462948:7f2d99961700: end prop repl,
pRes='devfe1.example.de', len 19
4994.363482820:7f2d99961700: XXXXX:  tryDoAction
0x7f2d9d2f0c80, pnElem 1, nElem 1
4994.363503015:7f2d99961700: Action 0x7f2d9d2f0c80 transitioned
to state: itx
4994.363521821:7f2d99961700: entering actionCalldoAction(),
state: itx
4994.363540666:7f2d99961700: file to log to:
Jboss1AccessLogHostLogs
4994.363603470:7f2d99961700: file stream test.log
params: flush interval 0, async write 0
4994.363627693:7f2d99961700: Added new entry 0 for file cache,
file '/own/log/devfe1.example.de/test.log'.
4994.363647496:7f2d99961700: write to stream, pData->pStrm
0x7f2d940008c0, lenBuf 151
4994.363667684:7f2d99961700: action 0x7f2d9d2f0c80 call
returned -2121
4994.363699102:7f2d99961700: strm 0x7f2d940008c0: file
-1(test.log) flush, buflen 151
4994.363750541:7f2d99961700: file
'/own/log/devfe1.example.de/test.log' opened as #50 with mode
420
4994.363779271:7f2d99961700: strm 0x7f2d940008c0: opened
file '/own/log/devfe1.example.de/test.log' for WRITE as 50
4994.363831875:7f2d99961700: strm 0x7f2d940008c0: file 50
write wrote 151 bytes
4994.363858423:7f2d99961700: Action 0x7f2d9d2f0c80 transitioned
to state: rdy
4994.363879975:7f2d99961700: ruleset: get iRet 0 from
rule.ProcessMsg()
4994.363898858:7f2d99961700: ruleset.ProcessMsg() returns 0
4994.363918258:7f2d99961700: regular consumer finished, iret=0,
szlog 0 sz phys 1
4994.363939716:7f2d99961700: we deleted 1 objects and enqueued
0 objects
4994.363958802:7f2d99961700: delete batch from store, new
sizes: log 0, phys 0
4994.363977623:7f2d99961700: regular consumer finished, iret=4,
szlog 0 sz phys 0
4994.363998435:7f2d99961700: main Q:Reg/w0: worker
IDLE, waiting for work.
4994.365808442:7f2d98f60700: poll returned with i 0, pUsr
0x7f2d8c001350
4994.365836338:7f2d98f60700: New connect on NSD
0x7f2d8c001680.
4994.366299875:7f2d98f60700: adding nsdpoll entry
0/0x7f2d8c022220, sock 51
4994.366333215:7f2d98f60700: New session created with NSD
0x7f2d8c022220.
4994.366355321:7f2d98f60700: poll returned with i 0, pUsr
0x7f2d8c022220
4994.366374325:7f2d98f60700: netstream 0x7f2d8c022290 with new
data
4994.366405177:7f2d98f60700: main Q: entry added, size now
log 1, phys 1 entries
4994.366436521:7f2d98f60700: main Q: MultiEnqObj advised
worker start
4994.366471423:7f2d99961700: wti 0x7f2d9d2ef890: worker
awoke from idle processing
4994.366499149:7f2d99961700: we deleted 0 objects and enqueued
0 objects
4994.366518431:7f2d99961700: delete batch from store, new
sizes: log 1, phys 1
4994.366539384:7f2d99961700: msg parser: flags 30, from
'devfe1.example.de', msg '<188>Feb 28 14:43:19 devfe1
JB1access-log  10.0.0.30 [28/Feb'
4994.366558888:7f2d99961700: parse using parser list
0x7f2d9d2e4130 (the default list).
4994.366578707:7f2d99961700: Parser 'rsyslog.rfc5424'
returned -2160
4994.366597786:7f2d99961700: Message will now be parsed by the
legacy syslog parser (one size fits all... ;)).
4994.366617460:7f2d99961700: MsgSetTAG in: len 13,
pszBuf: JB1access-log
4994.366636344:7f2d99961700: MsgSetTAG exit: pMsg->iLenTAG
13, pMsg->TAG.szBuf: JB1access-log
4994.366654627:7f2d99961700: Parser 'rsyslog.rfc3164'
returned 0
4994.366673366:7f2d99961700: processBatch: batch of 1
elements must be processed
4994.366691977:7f2d99961700: Processing next rule
4994.366713179:7f2d99961700: rainerscript: executing step,
opcode 1002...
4994.366750297:7f2d99961700: rainerscript: opcode
PUSHMSGVAR
4994.366771671:7f2d99961700: rainerscript: executing step,
opcode 1003...
4994.366790846:7f2d99961700: rainerscript: opcode
PUSHCONSTANT
4994.366810431:7f2d99961700: rainerscript: executing step,
opcode 101...
4994.366829152:7f2d99961700: rainerscript: opcode CMP_NEQ
4994.366848721:7f2d99961700: rainerscript: executing step,
opcode 1002...
4994.366867241:7f2d99961700: rainerscript: opcode
PUSHMSGVAR
4994.366889033:7f2d99961700: rainerscript: executing step,
opcode 1003...
4994.366908193:7f2d99961700: rainerscript: opcode
PUSHCONSTANT
[/code:1hev39i3]

So there are two different lines:
[code:1hev39i3]
4994.362821279:7f2d99961700: msg parser: flags 30, from
'devfe1.example.de', msg '<133>Feb 28 14:43:19 devfe1
JB1access-log 10.0.0.30 [28/Feb/'
[/code:1hev39i3]

[code:1hev39i3]
4994.366539384:7f2d99961700: msg parser: flags 30, from
'devfe1.example.de', msg '<188>Feb 28 14:43:19 devfe1
JB1access-log  10.0.0.30 [28/Feb'
[/code:1hev39i3]

Where does that second blank come from? It is not showing up in original
files which the rsyslog is reading. The local created file from the rsyslog
is OK as well. 
The only problem is the rsyslog on the server site.

Do you need more information to help me?

Cheers,

Chriss