weblogic and line breaking

[murhammr]

i am trying to read the weblogic DefaultAuditRecorder.log which looks like this (and doesn't seem to be covered in the weblogic app in splunkbase)

#### Audit Record Begin <Jan 8, 2018 3:50:52 PM>  <Severity =SUCCESS>  <<<Event Type = Authorization Audit Event V2 ><Subject: 2
        Principal = class weblogic.security.principal.WLSUserImpl("username")
        Principal = class weblogic.security.principal.WLSGroupImpl("groupname")
><ONCE><<adm>><type=<adm>, category=AdminChannel>>> Audit Record End ####

Some small percentage of events are not breaking at "#### Audit Record Begin", but instead randomly cut in the middle:

ipal = class weblogic.security.principal.WLSGroupImpl("groupname")
><ONCE><<adm>><type=<adm>, category=AdminChannel>>> Audit Record End ####

an 9, 2018 2:28:02 PM>  <Severity =SUCCESS>  <<<Event Type = Authorization Audit Event V2 ><Subject: 2
    Principal = class weblogic.security.principal.WLSUserImpl("username")
    Principal = class weblogic.security.principal.WLSGroupImpl("groupname")
><ONCE><<adm>><type=<adm>, category=AdminChannel>>> Audit Record End ####

my props.conf :

[weblogic:audit]
KV_MODE = auto
SHOULD_LINEMERGE = true
BREAK_ONLY_BEFORE_DATE = true
TIME_PREFIX = ####\sAudit\sRecord\sBegin\s<
TIME_FORMAT = %b %d, %Y %I:%M:%S %p
MAX_TIMESTAMP_LOOKAHEAD = 24

I've tried using these but no luck here either:

#MUST_BREAK_AFTER = Audit\sRecord\sEnd\s####
#BREAK_ONLY_BEFORE = ####\sAudit\sRecord\sBegin

I've reviewed the props.conf man page several times but I can't seem to identify where I've gone wrong.

[micahkemp]

Linebreaking should be configured like this:

[weblogic:audit]
LINE_BREAKER = ([\n\r]+)#### Audit Record Begin
SHOULD_LINEMERGE = false

Use LINE_BREAKER properly instead of relying on SHOULD_LINEMERGE. From props.conf doc:

* NOTE: You get a significant boost to processing speed when you use
  LINE_BREAKER to delimit multi-line events (as opposed to using
  SHOULD_LINEMERGE to reassemble individual lines into multi-line events).
  * When using LINE_BREAKER to delimit events, SHOULD_LINEMERGE should be set
    to false, to ensure no further combination of delimited events occurs.
  * Using LINE_BREAKER to delimit events is discussed in more detail in the web
    documentation at the following url:
    http://docs.splunk.com/Documentation/Splunk/latest/Data/Configureeventlinebreaking

[murhammr]

Thanks @micahkemp. I am still having issues. I've tried some different values for LINE_BREAKER and it does work sometimes but not all. I also see some "DateParserVerbose - Failed to parse timestamp" errors on this sourcetype which I suspect are due to the LINE_BREAKER issues.

Here are my props via btool:

[weblogic:audit]
ANNOTATE_PUNCT = True
AUTO_KV_JSON = true
BREAK_ONLY_BEFORE = 
BREAK_ONLY_BEFORE_DATE = True
CHARSET = UTF-8
DATETIME_CONFIG = /etc/datetime.xml
EXTRACT-WLS_INSTANCE_NAME = \/\w+\/\w+\/\w+\/(?<wls_instance>\w+)\/\w+\/\w+\/\w+\/\w+ in source
HEADER_MODE = 
KV_MODE = auto
LEARN_MODEL = true
LEARN_SOURCETYPE = true
LINE_BREAKER = (Audit Record End ####)
LINE_BREAKER_LOOKBEHIND = 100
LOOKUP-dropdowns = dropdownsLookup host OUTPUT unix_category unix_group
MATCH_LIMIT = 100000
MAX_DAYS_AGO = 2000
MAX_DAYS_HENCE = 2
MAX_DIFF_SECS_AGO = 3600
MAX_DIFF_SECS_HENCE = 604800
MAX_EVENTS = 2000
MAX_TIMESTAMP_LOOKAHEAD = 48
MUST_BREAK_AFTER = 
MUST_NOT_BREAK_AFTER = 
MUST_NOT_BREAK_BEFORE = 
SEGMENTATION = indexing
SEGMENTATION-all = full
SEGMENTATION-inner = inner
SEGMENTATION-outer = outer
SEGMENTATION-raw = none
SEGMENTATION-standard = standard
SHOULD_LINEMERGE = false
TIME_FORMAT = %b %e, %Y %I:%M:%S %p
TIME_PREFIX = #### Audit Record Begin <
TRANSFORMS = 
TRUNCATE = 999999
detect_trailing_nulls = false
maxDist = 100
priority = 
sourcetype = 

When I run this search, i have 99% of punct values begining with ####, as expected, but a small random amount that are resulting from faulty line_breaking. (see pic please)

  index=xxx  sourcetype=weblogic:audit  | stats count by punct

punct       count   
####____<_,__::_>__<_=>__<<<__=_____><:_t_=__...("  5300
####____<_,__::_>__<_=>__<<<__=_____><:_><><<>><=<  1081
####____<_,__::_>__<_=>__<<<__=____><_=_:_t_=__...  6
####_   3
___<_,__::_>__<_=>__<<<__=_____><:_t_=__...("")t_=  3
")t_=__...("")><><<>><=<>,_=>>>_    2
####____<_,__::_>__<_=>__<<<__=_____><:_t   2
####____<_,__::_>__<_=>__<<<__=_____><:_t_=__.  2
####____<_,__::_>__<_=>__<<<__=_____><:_t_=__..     2
.("")t_=__...("")><><<>><=<>,_=>>>_     2
..("")t_=__...("")><><<>><=<>,_=>>>_    2
=>>>_   2
>>>_    2
_=__...("")><><<>><=<>,_=>>>_   2
_=__...("")t_=__...("")><><<>><=<>,_=>>>_   2
")><><<>><=<>,_=>>>_    1 

[micahkemp]

The linebreaker in your btool output doesn't match what I suggested.

[murhammr]

right - I've tried a few different LINE_BREAKERs but always end up with the same results which makes me wonder if it's another setting causing the problem. Here is your recommended LINE_BREAKER:

[weblogic:audit]
ANNOTATE_PUNCT = True
AUTO_KV_JSON = true
BREAK_ONLY_BEFORE = 
BREAK_ONLY_BEFORE_DATE = True
CHARSET = UTF-8
DATETIME_CONFIG = /etc/datetime.xml
EXTRACT-WLS_INSTANCE_NAME = \/\w+\/\w+\/\w+\/(?<wls_instance>\w+)\/\w+\/\w+\/\w+\/\w+ in source
HEADER_MODE = 
KV_MODE = auto
LEARN_MODEL = true
LEARN_SOURCETYPE = true
LINE_BREAKER = ([\n\r]+)#### Audit Record Begin
LINE_BREAKER_LOOKBEHIND = 100
LOOKUP-dropdowns = dropdownsLookup host OUTPUT unix_category unix_group
MATCH_LIMIT = 100000
MAX_DAYS_AGO = 2000
MAX_DAYS_HENCE = 2
MAX_DIFF_SECS_AGO = 3600
MAX_DIFF_SECS_HENCE = 604800
MAX_EVENTS = 2000
MAX_TIMESTAMP_LOOKAHEAD = 48
MUST_BREAK_AFTER = 
MUST_NOT_BREAK_AFTER = 
MUST_NOT_BREAK_BEFORE = 
SEGMENTATION = indexing
SEGMENTATION-all = full
SEGMENTATION-inner = inner
SEGMENTATION-outer = outer
SEGMENTATION-raw = none
SEGMENTATION-standard = standard
SHOULD_LINEMERGE = false
TIME_FORMAT = %b %e, %Y %I:%M:%S %p
TIME_PREFIX = <
TRANSFORMS = 
TRUNCATE = 999999
detect_trailing_nulls = false
maxDist = 100
priority = 
sourcetype = 

and same type of results for punct:

punct       count   
####____<_,__::_>__<_=>__<<<__=_____><:_t_=__...("  1658
####____<_,__::_>__<_=>__<<<__=_____><:_><><<>><=<  360
####____<_,__::_>__<_=>__<<<__=____><_=_:_t_=__...  6
####____<_,__::_>__<_=>__<<<__=_____><  2
:_t_=__...("")t_=__...("")><><<>><=<>,_=>>>____###  2
####____<_,_    1
####____<_,__::_>__<_=>__<<<__=__   1
####____<_,__::_>__<_=>__<<<__=_____><:_t_=__..     1
.("")t_=__...("")><><<>><=<>,_=>>>____####  1
=>>>____####    1
>><=<>,_=>>>____####    1
>__<_=>__<<<__=_____><:_t_=__...("")t_=__...("")><  1
_####   1
_::_>__<_=>__<<<__=_____><:_t_=__...("")t_=__...("  1
___><:_t_=__...("")t_=__...("")><><<>><=<>,_=>>>__  1 

[micahkemp]

Are your events initially coming in with the sourcetype weblogic:audit, or are you rewriting events to that sourcetype after they come into splunk?

Can you paste your inputs.conf for these events?

Also worth noting: only new events that come in will be affected by these new configs. If you are searching previously indexed data you will still see the incorrectly split events.

[murhammr]

yes, i am looking at new events as i'm testing; not the previously indexed events.

i have looked at the source log file and the events look fine. no corruption, or incomplete entries.

i am not rewriting events. here is the inputs monitor stanza:

[monitor:///path/to/logs/DefaultAuditRecorder.log]
sourcetype = weblogic:audit
index = xxx
disabled = false

[micahkemp]

Can you post a sample log that breaks incorrectly when you try to index it? You can redact it as necessary, but make sure you've tried to index it and it breaks incorrectly for you (specifically for the sample data you paste).

[murhammr]

As you can see from my punct list above, they are breaking at random places. Here is one example. source from the logfile:

#### Audit Record Begin <Jan 11, 2018 1:28:49 PM>  <Severity =SUCCESS>  <<<Event Type = Authorization Audit Event V2 ><Subject: 0
><ONCE><<jndi>><type=<jndi>, application=, path={xxx,xxx}, action=lookup>>> Audit Record End ####

here are the 2 broken events:

1/11/18 1:28:49.000 PM
#### Audit Record Begin <

1/11/18 1:28:49.000 PM
Jan 11, 2018 1:28:49 PM>  <Severity =SUCCESS>  <<<Event Type = Authorization Audit Event V2 ><Subject: 0
><ONCE><<jndi>><type=<jndi>, application=, path={xxx,xxx}, action=lookup>>> Audit Record End ####

corresponding _internal error:

01-11-2018 13:29:07.250 -0600 WARN DateParserVerbose - Failed to parse timestamp. Defaulting to timestamp of previous event (Thu Jan 11 13:28:49 2018). Context: source::/path/to/logs/DefaultAuditRecorder.log|host::hostname|weblogic:audit|9800\n    

[micahkemp]

Can you add --debug to your btool command and paste the results? I love that you've included btool results every time, but it would also be nice if that output showed which file was responsible for each line (basically, it shows which lines you've added to props, and which are still default).

This appears to be working flawlessly on my test setup, but, your original post suggested it happened only on a small set of events, and I'm not sure I'm testing events which show that behavior.

[murhammr]

it does happen to fewer than 1% of events. i can't identify anything that is common to the events that are being broken incorrectly. i see same behavior on all hosts which have this log file.

/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    [weblogic:audit]
/opt/splunk/etc/system/default/props.conf                  ANNOTATE_PUNCT = True
/opt/splunk/etc/system/default/props.conf                  AUTO_KV_JSON = true
/opt/splunk/etc/system/default/props.conf                  BREAK_ONLY_BEFORE = 
/opt/splunk/etc/system/default/props.conf                  BREAK_ONLY_BEFORE_DATE = True
/opt/splunk/etc/system/default/props.conf                  CHARSET = UTF-8
/opt/splunk/etc/system/default/props.conf                  DATETIME_CONFIG = /etc/datetime.xml
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    EXTRACT-WLS_INSTANCE_NAME = \/\w+\/\w+\/\w+\/(?<wls_instance>\w+)\/\w+\/\w+\/\w+\/\w+ in source
/opt/splunk/etc/system/default/props.conf                  HEADER_MODE = 
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    KV_MODE = auto
/opt/splunk/etc/system/default/props.conf                  LEARN_MODEL = true
/opt/splunk/etc/system/default/props.conf                  LEARN_SOURCETYPE = true
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    LINE_BREAKER = ([\n\r]+)#### Audit Record Begin
/opt/splunk/etc/system/default/props.conf                  LINE_BREAKER_LOOKBEHIND = 100
/opt/splunk/etc/apps/splunk_app_for_nix/default/props.conf LOOKUP-dropdowns = dropdownsLookup host OUTPUT unix_category unix_group
/opt/splunk/etc/system/default/props.conf                  MATCH_LIMIT = 100000
/opt/splunk/etc/system/default/props.conf                  MAX_DAYS_AGO = 2000
/opt/splunk/etc/system/default/props.conf                  MAX_DAYS_HENCE = 2
/opt/splunk/etc/system/default/props.conf                  MAX_DIFF_SECS_AGO = 3600
/opt/splunk/etc/system/default/props.conf                  MAX_DIFF_SECS_HENCE = 604800
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    MAX_EVENTS = 2000
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    MAX_TIMESTAMP_LOOKAHEAD = 48
/opt/splunk/etc/system/default/props.conf                  MUST_BREAK_AFTER = 
/opt/splunk/etc/system/default/props.conf                  MUST_NOT_BREAK_AFTER = 
/opt/splunk/etc/system/default/props.conf                  MUST_NOT_BREAK_BEFORE = 
/opt/splunk/etc/system/default/props.conf                  SEGMENTATION = indexing
/opt/splunk/etc/system/default/props.conf                  SEGMENTATION-all = full
/opt/splunk/etc/system/default/props.conf                  SEGMENTATION-inner = inner
/opt/splunk/etc/system/default/props.conf                  SEGMENTATION-outer = outer
/opt/splunk/etc/system/default/props.conf                  SEGMENTATION-raw = none
/opt/splunk/etc/system/default/props.conf                  SEGMENTATION-standard = standard
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    SHOULD_LINEMERGE = false
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    TIME_FORMAT = %b %e, %Y %I:%M:%S %p
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    TIME_PREFIX = <
/opt/splunk/etc/system/default/props.conf                  TRANSFORMS = 
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf    TRUNCATE = 999999
/opt/splunk/etc/system/default/props.conf                  detect_trailing_nulls = false
/opt/splunk/etc/system/default/props.conf                  maxDist = 100
/opt/splunk/etc/system/default/props.conf                  priority = 
/opt/splunk/etc/system/default/props.conf                  sourcetype = 

[murhammr]

i can't identify anything unique to the events that are impacted, but it is fewer than 1%.

/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf [weblogic:audit]
/opt/splunk/etc/system/default/props.conf ANNOTATE_PUNCT = True
/opt/splunk/etc/system/default/props.conf AUTO_KV_JSON = true
/opt/splunk/etc/system/default/props.conf BREAK_ONLY_BEFORE =
/opt/splunk/etc/system/default/props.conf BREAK_ONLY_BEFORE_DATE = True
/opt/splunk/etc/system/default/props.conf CHARSET = UTF-8
/opt/splunk/etc/system/default/props.conf DATETIME_CONFIG = /etc/datetime.xml
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf EXTRACT-WLS_INSTANCE_NAME = \/\w+\/\w+\/\w+\/(?\w+)\/\w+\/\w+\/\w+\/\w+ in source
/opt/splunk/etc/system/default/props.conf HEADER_MODE =
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf KV_MODE = auto
/opt/splunk/etc/system/default/props.conf LEARN_MODEL = true
/opt/splunk/etc/system/default/props.conf LEARN_SOURCETYPE = true
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf LINE_BREAKER = ([\n\r]+)#### Audit Record Begin
/opt/splunk/etc/system/default/props.conf LINE_BREAKER_LOOKBEHIND = 100
/opt/splunk/etc/apps/splunk_app_for_nix/default/props.conf LOOKUP-dropdowns = dropdownsLookup host OUTPUT unix_category unix_group
/opt/splunk/etc/system/default/props.conf MATCH_LIMIT = 100000
/opt/splunk/etc/system/default/props.conf MAX_DAYS_AGO = 2000
/opt/splunk/etc/system/default/props.conf MAX_DAYS_HENCE = 2
/opt/splunk/etc/system/default/props.conf MAX_DIFF_SECS_AGO = 3600
/opt/splunk/etc/system/default/props.conf MAX_DIFF_SECS_HENCE = 604800
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf MAX_EVENTS = 2000
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf MAX_TIMESTAMP_LOOKAHEAD = 48
/opt/splunk/etc/system/default/props.conf MUST_BREAK_AFTER =
/opt/splunk/etc/system/default/props.conf MUST_NOT_BREAK_AFTER =
/opt/splunk/etc/system/default/props.conf MUST_NOT_BREAK_BEFORE =
/opt/splunk/etc/system/default/props.conf SEGMENTATION = indexing
/opt/splunk/etc/system/default/props.conf SEGMENTATION-all = full
/opt/splunk/etc/system/default/props.conf SEGMENTATION-inner = inner
/opt/splunk/etc/system/default/props.conf SEGMENTATION-outer = outer
/opt/splunk/etc/system/default/props.conf SEGMENTATION-raw = none
/opt/splunk/etc/system/default/props.conf SEGMENTATION-standard = standard
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf SHOULD_LINEMERGE = false
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf TIME_FORMAT = %b %e, %Y %I:%M:%S %p
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf TIME_PREFIX = <
/opt/splunk/etc/system/default/props.conf TRANSFORMS =
/opt/splunk/etc/apps/my_weblogic_ta/local/props.conf TRUNCATE = 999999
/opt/splunk/etc/system/default/props.conf detect_trailing_nulls = false
/opt/splunk/etc/system/default/props.conf maxDist = 100
/opt/splunk/etc/system/default/props.conf priority =
/opt/splunk/etc/system/default/props.conf sourcetype =

[mayurr98]

hey @murhammr
Attributes that apply only when the SHOULD_LINEMERGE setting is true

MUST_BREAK_AFTER = Audit\sRecord\sEnd\s####
BREAK_ONLY_BEFORE = ####\sAudit\sRecord\sBegin
SHOULD_LINEMERGE=true

Refer this link
https://docs.splunk.com/Documentation/SplunkCloud/6.6.3/Data/Configureeventlinebreaking#Attributes_t...

let me know if this helps !

[mayurr98]

have you tried this?

[murhammr]

I did try these settings before I posted the question, and get the same results that i've posted in the comment below.