Line Break Problem due to non-standard timestamps

[xanthakita]

Hi Have some data coming into Splunk that has some unusual timestamp formatting:

here is an example log file:

* Error log created: 2020-01-10 11:16:21.269198                               *
********************************************************************************
** Past trace BEGIN                                                          **
********************************************************************************
11:15:46.344416(5b4)   CINDbResultSet::AllocateCache() - BEGIN
11:15:46.344416(5b4)   CINODBCResultSet::AllocateCache() - END
11:15:46.345417(5b4)   CINODBCResultSet::~CINODBCResultSet():
               QUERY: SELECT * FROM IN_VERSION WHERE VERSION_ID = ? OPTION (FAST 1)
               PARMS: 0=321Z333_0BLRSQ1PT0010YQ
               DURATION: 0.001525 s
11:15:46.345417(5b4)   Session SPID: 519
11:15:46.345417(5b4)   CINODBCResultSet::ExecDirect():
               QUERY: SELECT * FROM IN_LOGOB WHERE LOGOB_ID = ? OPTION (FAST 1)
               PARMS: 0=321Z333_0BLRSP1PT000PRB
11:15:46.345417(5b4)   CINODBCResultSet::AllocateStatementHandle m_retCode = 0 m_hstmt = 0x0000000003F43EF0
11:15:46.346412(5b4)   DBReturnCode: 1
11:15:46.346412(5b4)   CINDbResultSet::AllocateCache() - BEGIN
11:15:46.346412(5b4)   CINODBCResultSet::AllocateCache() - END
11:15:46.347415(5b4)   CINODBCResultSet::~CINODBCResultSet():
               QUERY: SELECT * FROM IN_LOGOB WHERE LOGOB_ID = ? OPTION (FAST 1)
               PARMS: 0=321Z333_0BLRSP1PT000PRB
               DURATION: 0.001353 s
11:15:46.347415(5b4)   Session SPID: 519

as you can see there is a date and time at the top of the file... but each event has its own timestamp (without a date)
(I'm also clueless what that (5b4) means if anyone has any insight on that!

If anyone has any suggestions I would greatly appreciate it. I have looked and tried several things none worked.

Many Thanks,
Jonathan Wagner

[nickhills]

I have just checked using your log sample above.

I think your config will break all lines (including those which dont start with a date - so the QUERY: lines)

Try this:

 SHOULD_LINEMERGE=true
 LINE_BREAKER=([\r\n]+)
 NO_BINARY_CHECK=true
 TIME_FORMAT=%H:%M:%S.%6Q
 TIME_PREFIX=^
 MAX_TIMESTAMP_LOOKAHEAD=16

Keeping line merging should group consecutive lines that do not themself have a timestamp.

When you have funky time issues, its often good to be specific about where to look for the time and the format it is in.
As long as you are importing your logs on the date that they relate to - splunk will guess that the date is 'today'. That can cause you issues if you are importing old data, and also (depending on luck) around midnigh

[xanthakita]

so the following props.conf SEEMS to have resolved the issue...
[inserver]
LINE_BREAKER = ([\r\n]+)\d{2}:\d{2}:\d{2}.\d{6}(
SHOULD_LINEMERGE = false

I'm still a little afraid its going to break but I'm hopeful...

[nickhills]

How is Splunk breaking this data at present?
Do you have anything configured already in props.conf to handle it?

Random shot in the dark: could (5b4) be a UTC offset in an odd format?

[xanthakita]

its breaking in odd places... perhaps at a blank line in the actual file...though i'm not 100% certain of that
here is what the search returns currently:
1/22/20
11:55:04.213 PM
23:55:04.213420(1f24) VSLRuleRepository setting offline state to TRUE
23:55:04.214419(1f24) LicenseRepository setting offline state to TRUE
23:55:04.215419(1f24) CINExternalOsmTreeRecoveryMonitor - Initialize recovery worker thread pool.
23:55:04.234424(1f24) CINDepartmentCrossNodeCache setting offline state to TRUE
23:55:04.235421(1f24) CINUserCache setting offline state to TRUE
Show all 10 lines
host = HDC0208index = perceptivesource = D:\inserver6\log\intool_CI_SBC_S2B_Import_FAC_20200122.logsourcetype = inserver
1/22/20
11:50:04.639 PM
23:50:04.639018(1c6c) VSLRuleRepository setting offline state to TRUE
23:50:04.640017(1c6c) LicenseRepository setting offline state to TRUE
23:50:04.640017(1c6c) CINExternalOsmTreeRecoveryMonitor - Initialize recovery worker thread pool.
23:50:04.659024(1c6c) CINDepartmentCrossNodeCache setting offline state to TRUE
23:50:04.660025(1c6c) CINUserCache setting offline state to TRUE
Show all 10 lines
host = HDC0208index = perceptivesource = D:\inserver6\log\intool_CI_SBC_S2B_Import_FAC_20200122.logsourcetype = inserver
1/22/20
11:45:05.036 PM
23:45:05.036601(b40) VSLRuleRepository setting offline state to TRUE
23:45:05.037595(b40) LicenseRepository setting offline state to TRUE
23:45:05.037595(b40) CINExternalOsmTreeRecoveryMonitor - Initialize recovery worker thread pool.
23:45:05.059596(b40) CINDepartmentCrossNodeCache setting offline state to TRUE
23:45:05.059596(b40) CINUserCache setting offline state to TRUE
Show all 10 lines
host = HDC0208index = perceptivesource = D:\inserver6\log\intool_CI_SBC_S2B_Import_FAC_20200122.logsourcetype = inserver
1/22/20
11:40:04.221 PM
23:40:04.221350(83c) Starting local heartbeat thread.
23:40:04.341359(83c) Stopping local heartbeat thread.
23:40:04.371361(cd0) CINExternalOsmTreeRecoveryMonitor - Shutdown recovery pool.
host = HDC0208index = perceptivesource = D:\inserver6\log\intool_CI_SBC_S2B_Import_FAC_20200122.logsourcetype = inserver

there are roughly 1500 lines in this particular file and its just breaking out 10-20 lines at a time.

as to your question about props.conf I have played with a few things and this is the closest that almost works in my test bed though I havn't implemented it on my prod server

[inserver]
LINE_BREAKER = ([\r\n]+)\d{2}:\d{2}:\d{2}\.\d{6}\(
SHOULD_LINEMERGE = false

so I need to test that and see if that helps... Ill post here if it does... but I know I'm still going to get errors about the lack of a proper date in the timestamp... so any ideas on that?

[xanthakita]

actually when I put that props.conf into production its apparently working and its setting the date based on today (which the file is and the time based on the line... so... maybe I'm ok... thank you for feedback