How can I force correct separation of events?

[whitmad]

Apologies if this is a silly question, but I'm new to splunk.

I'm attempting to set up a sourcetype that will correctly identify events in a java GC log file (with -XX:+printGCtimestamps to get a sensible timestamp) I have a props.conf like this:

[java-gclog]
SHOULD_LINEMERGE = false
LINE_BREAKER = ([\r\n]+)\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d.\d\d\d
TIME_PREFIX = ^
TIME_FORMAT = %Y-%m-%dT%H:%M:%S.%3N%z
BREAK_ONLY_BEFORE_DATE = true
NO_BINARY_CHECK = 1
pulldown_type = 1

with the intention of defining events as beginning with timestamps - e.g. from the following extract:

2012-06-27T14:38:45.544+0100: 1301932.061: [GC 1301932.061: [ParNew
Desired survivor size 10878976 bytes, new threshold 3 (max 4)
- age   1:    4685032 bytes,    4685032 total
- age   2:    4584496 bytes,    9269528 total
- age   3:    4620296 bytes,   13889824 total
: 191744K->17255K(191744K), 0.0382590 secs] 1679396K->1509410K(3562752K), 0.0383510 secs]
 [Times: user=0.42 sys=0.01, real=0.04 secs] 
2012-06-27T14:38:57.362+0100: 1301943.879: [GC 1301943.879: [ParNew
Desired survivor size 10878976 bytes, new threshold 3 (max 4)
- age   1:    4681056 bytes,    4681056 total
- age   2:    4606872 bytes,    9287928 total
- age   3:    4583200 bytes,   13871128 total
: 187751K->19689K(191744K), 0.0410870 secs] 1679906K->1516349K(3562752K), 0.0411820 secs]
 [Times: user=0.40 sys=0.01, real=0.04 secs] 
2012-06-27T14:39:09.027+0100: 1301955.544: [GC 1301955.544: [ParNew
Desired survivor size 10878976 bytes, new threshold 3 (max 4)
- age   1:    4649608 bytes,    4649608 total
- age   2:    4590408 bytes,    9240016 total
- age   3:    4605208 bytes,   13845224 total
: 190185K->17689K(191744K), 0.0394190 secs] 1686845K->1518823K(3562752K), 0.0395120 secs]
 [Times: user=0.39 sys=0.00, real=0.04 secs] 
2012-06-27T14:39:20.533+0100: 1301967.050: [GC 1301967.050: [ParNew
Desired survivor size 10878976 bytes, new threshold 3 (max 4)
- age   1:    4668224 bytes,    4668224 total
- age   2:    4569728 bytes,    9237952 total
- age   3:    4588960 bytes,   13826912 total
: 188185K->16643K(191744K), 0.0382270 secs] 1689319K->1522269K(3562752K), 0.0383190 secs]
 [Times: user=0.40 sys=0.00, real=0.04 secs] 

In my test system if I delete all the indexes and restart splunk all works correctly for existing data, but it appears that as new data are added, I get incorrect breaking - the [Times] lines get split into separate events:

 [Times: user=0.39 sys=0.00, real=0.04 secs]

I feel I'm missing something obvious - could it be a timing issue where a pause before writing the [Times...] causes it to be treated as a separate event?

[whitmad]

I've found partial answers - it seems the issue is that java (at least the version I'm using) doesn't flush the output for that last part of the message, it is only output with the next message. Increasing "time_before_close" in inputs.conf reduces the frequency with which the problem occurs.

Follow on questions:

is there a way of stitching the end of the message onto the event already received and indexed.

if not, is there a way of suppressing the delayed event segment.

[whitmad]

I agree, hence my follow on questions on dealing with the problem after the fact.

[Lamar]

Yeah, time_before_close may help some. But, if you don't have a meaningful timespan in which the [Times] occurs it will be hard to get that timing (read: parameter) right. I don't think it's a good idea to simply open it up to a largish number.

[sdaniels]

I think you'll want to remove the first two lines -> line merge and line breaker. As long as you are getting the timestamp correctly and you have BREAK_ONLY_BEFORE_DATE = true, that should be all that you need. With just these settings what do you get?

[whitmad]

No, doesn't help - it's definitely a timing issue.

[Lamar]

How long is the pause between writes to disk?