Getting Data In

Event breaking during index time own sourcetype

tfechner
Path Finder

Hi all,

This linebreak/eventbreak problem drives me crazy. I searched all day to find a solution but nothing has helped:

We have a universal forwarder monitoring a logfile: (line by line)

Sep  6 15:49:27 lxXXXXXXX.de user:%ENVIRcom.rsa.csd.config.GenConfigCommandBaseORE_LOG 2018-09-06 15:49:27,559 +0200 DEBUG [http-bio-443-exec-178] [1ee3:1e895a3a561:430e6423-||1536235160000] [2ee3:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigCommandBase] [regionContextHeirarchies: [zvs-prod, ALOA-DEFAULT, dummy]]
Sep  6 15:49:27 lxXXXXXXX.de user:%ENVIRcom.rsa.csd.config.GenConfigGetCommandORE_LOG 2018-09-06 15:49:27,559 +0200 DEBUG [http-bio-443-exec-178] [1ee3:1e895a3a561:430e6423-||1536235160000] [2ee3:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigGetCommand] [Parameter name=SMTP_USERNAME@MCF@zvs-prod@CURRENT, Returned values=]
Sep  6 15:49:27 lxXXXXXXX.de user:%ENVIRcom.rsa.csd.config.GenConfigCommandBaseORE_LOG 2018-09-06 15:49:27,559 +0200 DEBUG [http-bio-443-exec-178] [1ee3:1e895a3a561:430e6423-||1536235160000] [2ee3:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigCommandBase] [regionContextHeirarchies: [zvs-prod, ALOA-DEFAULT, dummy]]
Sep  6 15:49:27 lxXXXXXXX.de user:%ENVIRcom.rsa.csd.config.GenConfigGetCommandORE_LOG 2018-09-06 15:49:27,559 +0200 DEBUG [http-bio-443-exec-178] [1ee3:1e895a3a561:430e6423-||1536235160000] [2ee3:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigGetCommand] [Parameter name=OOB_DISABLE_HEALTH_CHECKS@MCF@zvs-prod@CURRENT, Returned values=true]
Sep  6 15:49:27 lxXXXXXXX.de user:%ENVIRcom.rsa.csd.config.GenConfigCommandBaseORE_LOG 2018-09-06 15:49:27,560 +0200 DEBUG [http-bio-443-exec-178] [1ee3:1e895a3a561:430e6423-||1536235160000] [2ee3:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigCommandBase] [regionContextHeirarchies: [zvs-prod, ALOA-DEFAULT, dummy]]
Sep  6 15:49:27 lxXXXXXXX.de user:%ENVIRcom.rsa.csd.config.GenConfigGetCommandORE_LOG 2018-09-06 15:49:27,560 +0200 DEBUG [http-bio-443-exec-178] [1ee3:1e895a3a561:430e6423-||1536235160000] [2ee3:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigGetCommand] [Parameter name=KBA_MODE@MCF@zvs-prod@CURRENT, Returned values=testing]

On my index-cluster, i have an app defining the index-time parsing as follows:

[rsa]
TIME_PREFIX = %\S+\s+
TIME_FORMAT = %Y-%m-%d %H:%M:%S,%3N %z
MAX_TIMESTAMP_LOOKAHEAD = 40
TZ = DST
LINE_BREAKER=\]([\n\r]+)\w+\s+\d+\s+
EVENT_BREAKER=\]([\n\r]+)\w+\s+\d+\s+
SHOULD_LINEMERGE=false
BREAK_ONLY_BEFORE_DATE = false
TRUNCATE = 20000
MAX_DAYS_AGO = 14

Problem: Some events are multiline

Sep  6 15:49:44 lXXXXXde ...+.net+clr+2.0.50727;+.net+clr+3.0.30729;+.net+clr+3.5.30729;+rv:11.0)+like+gecko|5.0+(Windows+NT+10.0;+WOW64;+Trident/7.0;+.NET4.0C;+.NET4.0E;+.NET+CLR+2.0.50727;+.NET+CLR+3.0.30729;+.NET+CLR+3.5.30729;+rv:11.0)+like+Gecko|Win32&EXTERNAL_TIMEOUT=&TIMEZONE=1&pm_fpsdx=96&BROWSER_MAJOR_VERSION=NaN&JAVA=1&COOKIE=1&pm_fpol=true&SOFTWARE=&pm_fpsdy=96&version=3.4.0.0_2&pm_fpup=&pm_fpslx=96&pm_fpsly=96&pm_fpsfse=true&BROWSER_TYPE=Mozilla&pm_fpacn=Mozilla&INTERNAL_TIMEOUT=&pm_fpsbd=0&SUPPRESSED=false&LANGUAGE=lang%3Dde-DE|syslang%3Dde-DE|userlang%3Dde-DE&pm_fpsui=&pm_fpasw=flash|ieatgpc&pm_fposp=&OS=Windows&pm_fpsaw=1920&DISPLAY=24|1920|1200|1160&LANGUAGE_BROWSER=de-DE&pm_fpspd=24&ACCEPT_LANGUAGE=de-DE&LANGUAGE_USER=de-DE
ipHist=V=2&BT/0000004900000164d0f8bdde00000165af0e4de6440511f243106cae426666dbff02BD/0000004900000164d0f8bdde0000016...
Sep  6 15:49:44 lXXXXXde ...5af0e4de6440511f243106cae426666dbff8c38e246BU/0000004900000164d0f8bdde00000165af0e4de6440511f243106cae426666dbffd98d4a6dBL/0000004900000164d0f8bdde00000165af0e4de6440511f243106cae426666dbffdeDEBS/00000045000001657c01be9400000165af0e4de6440511f2430ff7e5426671507f1deeaef9GS/0000000100000165af0e4de600000165af0e4de63f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165af0296e700000165af0296e73f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165aefedb3600000165aefedb363f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165aeea741a00000165aeea741a3f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165aee4cd4600000165aee...
Sep  6 15:49:44 lXXXXXde ...4cd463f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165ae90a1e900000165ae90a1e93f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165ae8e154100000165ae8e15413f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165ae8a69aa00000165ae8a69aa3f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165ae7d045a00000165ae7d045a3f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165ae7673d600000165ae7673d63f8000003f8000003f8000007fdb41295d0100005800000000000fbb730000000100000001027a115d004d608cGS/0000000100000165ae6703f400000165ae6703f43f8000003f8000003f8000007fdb41295d01...

So Ineed linemerge=true and a line break. The time stamp is inside the messages...

now.. how do I deal with that?

0 Karma
1 Solution

tfechner
Path Finder

Solved:
props.conf
TIME_PREFIX = %\S+\s+
TIME_FORMAT = %Y-%m-%d %H:%M:%S,%3N %z
MAX_TIMESTAMP_LOOKAHEAD = 40
TZ = DST
SHOULD_LINEMERGE = false
LINE_BREAKER =([\r\n]+)\w+\s+\d+\s+\d\d:\d\d:\d\d\s+\S+\s+(?!...)
SEDCMD-strip-continued = s/.{3}[\r\n]?+\w+\s+\d+\s+\d+:\d+:\d+\s+\S+\s+.{3}//g
TRUNCATE = 50000

Solved with a negative look ahead regex.
Sedcmd for removing the syslog header for events that should be merged into one.

View solution in original post

0 Karma

tfechner
Path Finder

Solved:
props.conf
TIME_PREFIX = %\S+\s+
TIME_FORMAT = %Y-%m-%d %H:%M:%S,%3N %z
MAX_TIMESTAMP_LOOKAHEAD = 40
TZ = DST
SHOULD_LINEMERGE = false
LINE_BREAKER =([\r\n]+)\w+\s+\d+\s+\d\d:\d\d:\d\d\s+\S+\s+(?!...)
SEDCMD-strip-continued = s/.{3}[\r\n]?+\w+\s+\d+\s+\d+:\d+:\d+\s+\S+\s+.{3}//g
TRUNCATE = 50000

Solved with a negative look ahead regex.
Sedcmd for removing the syslog header for events that should be merged into one.

0 Karma

sudosplunk
Motivator

Thanks for providing log analysis.

I took all your samples of data, put them in a file and loaded that into splunk. Below configurations worked for me.

[test:breaking]
LINE_BREAKER = \]([\r\n]+)[\s\w]+\:\d{2}\:\d{2} # I am using end(\r\n)begin, a line ending with ']' followed a line beginning with 'Sep'
SHOULD_LINEMERGE = false
TIME_PREFIX = %\S+\s+
TIME_FORMAT = %Y-%m-%d %H:%M:%S,%3N %z
MAX_TIMESTAMP_LOOKAHEAD = 40

props.conf
alt text

Data in splunk:
alt text

Give a try and let me know if it works for you.

0 Karma

tfechner
Path Finder

I changed the line breaker in my props.conf on the indexer receiving the logs via syslog:
lines are broken , but not into seperat events:

cut&paste from the search-console:

07/09/2018
10:14:55.922    

Sep  7 10:14:55 lXXXXXXX.com user:%ENVIRcom.rsa.csd.config.GenConfigGetCommandORE_LOG 2018-09-07 10:14:55,922 +0200 DEBUG [http-bio-443-exec-208] [b1f6:1e895a3a561:430e6423-||1536301474107] [c1f6:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigGetCommand] [Parameter name=OOBSMS_OTP_TOKEN_SIZE@MCF@dummy@CURRENT, Returned values=6]
Sep  7 10:14:55 lXXXXXXX.com user:%ENVIRcom.rsa.csd.config.GenConfigCommandBaseORE_LOG 2018-09-07 10:14:55,922 +0200 DEBUG [http-bio-443-exec-208] [b1f6:1e895a3a561:430e6423-||1536301474107] [c1f6:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigCommandBase] [regionContextHeirarchies: [kopprod, KOP, dummy]]
Sep  7 10:14:55 lXXXXXXX.com user:%ENVIRcom.rsa.csd.config.GenConfigGetCommandORE_LOG 2018-09-07 10:14:55,923 +0200 DEBUG [http-bio-443-exec-208] [b1f6:1e895a3a561:430e6423-||1536301474107] [c1f6:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigGetCommand] [Parameter name=TRY_COUNT_PER_QUESTION@MCF@kopprod@CURRENT, Returned values=2]
Sep  7 10:14:55 lXXXXXXX.com user:%ENVIRcom.rsa.csd.config.GenConfigCommandBaseORE_LOG 2018-09-07 10:14:55,923 +0200 DEBUG [http-bio-443-exec-208] [b1f6:1e895a3a561:430e6423-||1536301474107] [c1f6:1e895a3a561:430e6423-_TRX] [com.rsa.csd.config.GenConfigCommandBase] [regionContextHeirarchies: [kopprod, KOP, dummy]]
Sep  7 10:14:55 lXXXXXXX.com user:%ENVIRorg.springframework.orm.hibernate3.HibernateTemplateORE_LOG 2018-09-07 10:14:55,923 +0200 DEBUG [http-bio-443-exec-208] [b1f6:1e895a3a561:430e6423-||1536301474107] [c1f6:1e895a3a561:430e6423-_TRX] [org.springframework.orm.hibernate3.HibernateTemplate] [Found thread-bound Session for HibernateTemplate]
Show all 257 lines
0 Karma

tfechner
Path Finder

mh. stzrange.. some logs changed now the log format:

Sep 12 13:35:33 LxxxxX.com user:%ENVIRcom.passmarksecurity.impl.PassMarkSessionImplORE_LOG 2018-09-12 13:35:33,207 +0200 DEBUG [http-bio-443-exec-244] [1777-:0c1451dc561:430e6423-] [0777-:0c1451dc561:430e6423-_TRX] [com.passmarksecurity.impl.PassMarkSessionImpl] [Adding facts to user history and committing]
Sep 12 13:35:33 LxxxxX.com user:%ENVIRcom.passmarksecurity.impl.PassMarkUserImplORE_LOG 2018-09-12 13:35:33,208 +0200 DEBUG [http-bio-443-exec-244] [1777-:0c1451dc561:430e6423-] [0777-:0c1451dc561:430e6423-_TRX] [com.passmarksecurity.impl.PassMarkUserImpl] [Writing encoded user history value of V=2&BT/00000091000001618903437700000165c72a2cfa42172b4541b7ac0a41c2a4d47f02GB/0000000100000165c72a2cfa00000165c72a2cfa3f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebBD/00000016000001653328c1d100000165c72a2cfa421
72b454193a17e415eea477f609685feBU/00000017000001653328c1d100000165c72a2cfa42172b45419b1005416a033c7f3bab2f21BL/00000060000001628fb948b900000165c72a2cfa42172b4541b7ac0a41c182397fdeDEBS/0000000100000165c72a2cfa00000165c72a2cfa3f8000003f8000003f8000007ff55e2b66GS/00000012000001655c3d9e9b00000165c72a2cfa42172b4541927468414483ec7fd796a06b0100005800000000000fbbcf0000000100000001001b849100020cebGB/0000000100000165c35a3fdc00000165c35a3fdc3f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b84910002
0cebBS/0000002500000163afba8f6900000165c35a3fdc41f00000414e811c4157b87d7ff7664150GB/0000000100000165af51a08c00000165af51a08c3f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebGB/0000000100000165aeaca85a00000165aeaca85a3f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebBS/0000000d0000016531f5580200000165aeaca85a41fb1618418232ea41118f957ff55e2b6aGB/0000000100000165a9c3327e00000165a9c3327e3f8000003f8000003f8000007fae52f10e0100005800000000000
03cd00000000100000001001b849100020cebGB/0000000100000165a8e22bb800000165a8e22bb83f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebGB/0000000100000165a86d52d800000165a86d52d83f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebGB/00000001000001659f4cdb95000001659f4cdb953f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebGB/00000001000001659e170fc1000001659e170fc13f8000003f8000003f8000007fdde38d5e0100005
80000000000003cd00000000100000001001b849100020cebBD/0000001100000164da739db5000001659e170fc141f00000413ec34f410c44907f5f354a26BU/000000090000016531f55802000001659e170fc141f00000413ec34f40d027a87fd07e2602GS/00000001000001659e170fc1000001659e170fc13f8000003f8000003f8000007fddd9b43601000058000000000001ba510000000100000001001b849100020cebGB/00000001000001658ead4b0c000001658ead4b0c3f8000003f8000003f8000007fdde38d5e010000580000000000003cd00000000100000001001b849100020cebGS/0000001400000164da739db5000001658ead4b0c41f0866b
416f29874132bc2d7fdde38b60010000580000000000003cd00000000100000001001b849100020cebGB/00000001000001658abf192b000001658abf192b3f8000003f8000003f8000007fdcdaf2a1010000580000000000003cd00000000100000001071659e500572b6eBD/00000001000001658abf192b000001658abf192b3f8000003f8000003f8000007f6098412cGS/00000001000001658abf192b000001658abf192b3f8000003f8000003f8000007fdc4d943f010000580000000000005edb0000000100000001071659e500572b6eGB/00000001000001658989d168000001658989d1683f8000003f8000003f8000007fdde38d5e010000580000000000
003cd00000000100000001001b849100020cebGB/0000000100000165858cfdaa00000165858cfdaa3f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebGB/00000001000001658057234700000165805723473f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebGB/00000001000001658007725000000165800772503f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebGB/00000001000001657f30c71d000001657f30c71d3f8000003f8000003f8000007fae52f10e010000
580000000000003cd00000000100000001001b849100020cebGB/00000001000001657b2f491e000001657b2f491e3f8000003f8000003f8000007fae52f10e010000580000000000003cd00000000100000001001b849100020cebGB/000000010000016579f8e5ee0000016579f8e5ee3f8000003f8000003f8000007fdde38d5e010000580000000000003cd00000000100000001001b849100020cebGB/00000001000001656a977e88000001656a977e883f8000003f8000003f8000007fdde38d5e010000580000000000003cd00000000100000001001b849100020cebBL/00000031000001618903437700000163edad3a7c41f00000408924923f7c52017fde--]
Sep 12 13:35:33 LxxxxX.com user:%ENVIRorg.springframework.orm.hibernate3.HibernateTemplateORE_LOG 2018-09-12 13:35:33,208 +0200 DEBUG [http-bio-443-exec-244] [1777-:0c1451dc561:430e6423-] [0777-:0c1451dc561:430e6423-_TRX] [org.springframework.orm.hibernate3.HibernateTemplate] [Found thread-bound Session for HibernateTemplate]

Sep 12 13:42:08 lxxxxxX.com user:%ENVIRorg.dozer.MappingProcessorORE_LOG 2018-09-12 13:42:08,798 +0200 DEBUG [http-bio-443-exec-225] [] [] [org.dozer.MappingProcessor] [MAPPED: StatusHeader.reasonDescription --> StatusHeader.reasonDescription VALUES: Operations were completed successfully

--> Operations were completed successfully

MAPID: ]

Splunk breaks almost every line into one event:
This event is parsed into one event:

Sep 12 15:05:55 lxrsa407p.vkbads.de ...:NA
substring.device.print.systemLanguage:null
calc.iFramesBit.daysSinceLastHit:-1
trx.atm.latitude:null
transaction.current.event.current.transfer.own.extRiskScore:null
efn.payee.score:0
trx.list.fw_color.efn.flash.frame.days:-999
trx.geoLocationHorizontalAccuracy:10000
user.device.max_auth_level_requested:null
device_profile.days_since:null
user.webDevice.reqCombinationProb:null
transaction.current.event.current.transfer.executionSpeed:null
user.ip.current.value.efraud.riskScore:0
user.payee_account.numOfPaymentsInterval.numOfPayements_30_mn:null
lists_data.fraud.client_cookie:null
trx.list.fw_color.fraud.flash.lvl:-999
interval.referrence.date:W...

Is there a limit of characters at syslog messages?
The lines ubove starting with a number have a length about 520 chars.

Another event has about 800 chars....

Loganalysis , I found:
- very long lines with 512 chars without ending "]"
- an event ends always with a bracket "]"
- timestamp I use is not at the beginning of an event
- each event starts with this regex: (\w+\s\d+\s\d+:\d{2}:\d{2} Lx.+
- there are some multi line events , but always ending with a ]

I tried:
Version1:
with sedcmd removing linebreaks "\w][\r\n]+"
LINE_BREAKER=([\r\n]+)[\s\w]+:\d{2}:\d{2}
SHOULD_LINEMERGE=false

Version2:
SHOULD_LINEMERGE=true
BREAK_ONLY_BEFORE =(\w+\s\d+\s\d+:\d{2}:\d{2} lxrs)
BREAK_ONLY_BEFORE_DATE = false
MUST_NOT_BREAK_AFTER=\w[\r\n]+
MUST_BREAK_AFTER=][\r\n]+

Version3:
LINE_BREAKER=([\r\n]+)[\s\w]+:\d{2}:\d{2}
SHOULD_LINEMERGE=false

I am crazy now....

0 Karma

tfechner
Path Finder

ok after a weekend wainting and restarting splunk the event breaking works.
But how to solve the event merging?

I have in this bunch of logs this logs:
Sep 10 08:45:33 lXXXXXXXs.de user:%ENVIRcom..PassMarkUserImplORE_LOG 2018-09-10 08:45:33,517 +0200 DEBUG [http-bio-443-exec-203] [5153-:5f7e2e3b561:430e6423-] [4153-:5f7e2e3b561:430e6423-_TRX] [com.passmarksecurity.impl.PassMarkUserImpl] [Writing encoded user history value of V=2&B0000[and many more zeros ]...

The next event starting with the zeros from the event ubove:

Sep 10 08:45:33 lxrsa407p.vkbads.de ..000000408924923fe48c487f5be92486BU/0000000100000165ad9d141800000165ad9d14183f8000003f8000003f8000007fe1a3fe1fBL/0000003d00000162707ca43700000165ad9d141841f00000408924923ff9263c7fdeDEBS/000001ba00000154a43aed5d00000165ad9d141841f00000408924923ff8f58d7fb94c45dbGS/

So how to fix this and join this events

0 Karma

FrankVl
Ultra Champion

See my updated answer above. You need to define your linebreaker such that it keeps all of those together in 1 event and then use SEDCMD to strip out those ... and extra headers.

0 Karma

sudosplunk
Motivator

Hi @tfechner,

Did you try configurations I've suggested in my answer above? If yes, then can you push these configs to UF also and see if it works. Thanks.

0 Karma

mstjohn_splunk
Splunk Employee
Splunk Employee

Hi @tfechener,

Did either of the answers below solve your problem? If so, please resolve this post by approving one of them.

If your problem is still not solved, keep us updated so that someone else can help ya.

Thanks!

0 Karma

FrankVl
Ultra Champion

No, you don't need linemerge = true for multiline events (although that does sound logical, I get that).

As long as you define your LINE_BREAKER correctly and set SHOULD_LINEMERGE = false, you should be good to go. And remove that BREAK_ONLY_BEFORE_DATE = false those BREAK_... settings should not be combined with LINE_BREAKER.

The LINE_BREAKER you have seems fine to me.

But the trick here is that is not just about line breaking, because this is not actually simple multiline events. This is logs getting spread out over multiple syslog messages each with their own timestamp and hostname header which you would probably want to strip out, right?

I think you should be able to use a SEDCMD in your props.conf to strip out those ...<syslogheader>... parts.

SEDCMD-strip-continued = s/\.{3}[\r\n]+\w+\s+\d+\s+\d+:\d+:\d+\s+\S+\s+\.{3}//g
0 Karma
Get Updates on the Splunk Community!

Extending Observability Content to Splunk Cloud

Register to join us !   In this Extending Observability Content to Splunk Cloud Tech Talk, you'll see how to ...

What's new in Splunk Cloud Platform 9.1.2312?

Hi Splunky people! We are excited to share the newest updates in Splunk Cloud Platform 9.1.2312! Analysts can ...

What’s New in Splunk Security Essentials 3.8.0?

Splunk Security Essentials (SSE) is an app that can amplify the power of your existing Splunk Cloud Platform, ...