How to sort time duration from a single event - only one timestamp

[stcrispan]

I've got log events showing up with internal timestamps, but they show up in single Splunk timestamps. The customer (the guy who gets, and provides the logs) wants to know how long, in ms, each transaction takes. I have several examples:

1130 120711 (1719) 2 JobBegin:servicerequest=RestInput
1130 120711 (1726) 3 Collect Event:ReceiptData < servicerequest=RestInput
1130 120711 (5026) 3 Sender of job set to:
1130 120711 (1730) 3 preproc message:ReceiptData < servicerequest=RestInput
1130 120711 (1731) 3 Doing message:ReceiptData < servicerequest=RestInput
1130 120711 (1739) 3   Process:ProcessingEngine_New_job_1_exstream (v. 1) > PDFOutput(null)
1130 120711 (0089) 2 EX002522W (1) The locale is not set for this application. The language and locale will be set to default.
1130 120711 (0089) 3 EX002697I (1) Data aggregation has been enabled due to XML end tag processing.
1130 120711 (0089) 3 EX001800I (1) >>>>>>>>>>>> Driver File: opening the customer driver file named ReceiptData. <<<<<<<<<<<<
1130 120711 (0089) 3 EX001000I (1) ********************* Customer 1:    Starts at input record 3 (byte 144)
1130 120711 (0089) 1 EX004108E (1) The PNG pass-through file ($$CNT$$J+jQzJSMMF_9TsTKtJIJrg==) for variable RES MANAGER FILE is not a supported file or is damaged. File is ignored.
1130 120711 (0089) 1 EX004108E (2) The PNG pass-through file ($$CNT$$k7iFrf4NoInN9jSQT9WfcQ==) for variable RES MANAGER FILE is not a supported file or is damaged. File is ignored.
1130 120711 (0089) 2 EX004146W (1) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
1130 120711 (0089) 2 EX004146W (2) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
1130 120711 (0089) 2 EX004146W (3) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
1130 120711 (0090) 2 OpenText Exstream Engine exited with exit code 8.
1130 120711 (5105) 3 Receiver of created document set (Document, reciever):9EA0E5DD-229B-DD41-A061-57EA9F23DE51,
1130 120711 (5105) 3 Receiver of created document set (Document, reciever):2A150B40-AB32-1F47-90E1-70EE6993F215,
1130 120711 (1723) 2 JobEnd:servicerequest=RestInput
1130 120711 (0576) 3 Queue item AD30B1A5-F1B1-2045-A230-DC4698EED6B6 with external ID '' completed successfully.
1130 120711 (0576) 3 Queue item 9EA0E5DD-229B-DD41-A061-57EA9F23DE51 with external ID '' completed successfully.
1130 120711 (0576) 3 Queue item 2A150B40-AB32-1F47-90E1-70EE6993F215 with external ID '' completed successfully.
1130 120711 (0572) 3 Tracker '89DF82A1-337D-484A-A574-C9497D55420D' (StrsID 5043113, external ID '') completed successfully.

...and...

1130 120649 (1719) 2 JobBegin:servicerequest=RestInput
1130 120649 (1726) 3 Collect Event:ReceiptData < servicerequest=RestInput
1130 120649 (5026) 3 Sender of job set to:
1130 120649 (1730) 3 preproc message:ReceiptData < servicerequest=RestInput
1130 120649 (1731) 3 Doing message:ReceiptData < servicerequest=RestInput
1130 120649 (1739) 3   Process:ProcessingEngine_New_job_1_exstream (v. 1) > PDFOutput(null)
1130 120649 (0089) 2 EX002522W (1) The locale is not set for this application. The language and locale will be set to default.
1130 120649 (0089) 3 EX002697I (1) Data aggregation has been enabled due to XML end tag processing.
1130 120649 (0089) 3 EX001800I (1) >>>>>>>>>>>> Driver File: opening the customer driver file named ReceiptData. <<<<<<<<<<<<
1130 120649 (0089) 3 EX001000I (1) ********************* Customer 1:    Starts at input record 3 (byte 144)
1130 120649 (0089) 1 EX004108E (1) The PNG pass-through file ($$CNT$$J+jQzJSMMF_9TsTKtJIJrg==) for variable RES MANAGER FILE is not a supported file or is damaged. File is ignored.
1130 120649 (0089) 1 EX004108E (2) The PNG pass-through file ($$CNT$$k7iFrf4NoInN9jSQT9WfcQ==) for variable RES MANAGER FILE is not a supported file or is damaged. File is ignored.
1130 120649 (0089) 2 EX004146W (1) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
1130 120649 (0089) 2 EX004146W (2) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
1130 120649 (0089) 2 EX004146W (3) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
1130 120649 (0090) 2 OpenText Exstream Engine exited with exit code 8.
1130 120649 (5105) 3 Receiver of created document set (Document, reciever):A9B71115-46B1-354C-B6BF-6592C958BCE0,
1130 120649 (5105) 3 Receiver of created document set (Document, reciever):136A1DC1-A85D-414A-AE68-DF988B1CEC04,
1130 120649 (1723) 2 JobEnd:servicerequest=RestInput
1130 120649 (0576) 3 Queue item 7096C45D-3BFB-8643-AE26-E7A0931B02E0 with external ID '' completed successfully.
1130 120649 (0576) 3 Queue item A9B71115-46B1-354C-B6BF-6592C958BCE0 with external ID '' completed successfully.
1130 120650 (0576) 3 Queue item 136A1DC1-A85D-414A-AE68-DF988B1CEC04 with external ID '' completed successfully.
1130 120650 (0572) 3 Tracker '4A788746-710D-9646-8EF7-C1A3A396A637' (StrsID 5043092, external ID '') completed successfully.

So as you can no doubt see, the first event in each example is a date time stamp and an event code "(1719)" and ends with "(0572)", but what is really needed is for each log entry to be broken out by date time stamp, the difference calculated and able to be displayed by the host which provided the log entry.

I'm guessing it might require a method to identify the beginning of the log entry, then discern the date-time stamp (as a time entry), then identify the end of the log entry, and discern the date-time stamp (as a time entry), then determine the difference between the two...all of which is above my skill level.

Anyone feel like taking a stab at this?

[stcrispan]

Paydirt! I modified your search, thus:

index=uws_esm "1719" AND "0572" 
| rex "(?<job_start>[^|]+)\s\(1719" 
| rex "(?<job_end>\d\d\d\d\s\d\d\d\d\d\d\s\(0572\)\s\d\s)"  
| eval job_start_epoch = strptime(job_start, "%m%d %H%M%S") 
| eval job_end_epoch = strptime(job_end, "%m%d %H%M%S") 
| eval job_dur_in_sec = job_end_epoch - job_start_epoch
| timechart count by job_dur_in_sec

So now the inevitable questions: what was the purpose of field=data, and max_match=0?

Also, you may notice that I replace my original rex for 0572 with a convoluted string...the consarned thing simply would NOT pull data as the original rex, not until I put that whole nonsense in there...it only pulled like four or five, and and the rest were "null". Weird, huh?

[adonio · Accepted solution]

hello there,

run this search anywhere:

| makeresults 
| eval data="1130 120649 (1719) 2 JobBegin:servicerequest=RestInput
 1130 120649 (1726) 3 Collect Event:ReceiptData < servicerequest=RestInput
 1130 120649 (5026) 3 Sender of job set to:
 1130 120649 (1730) 3 preproc message:ReceiptData < servicerequest=RestInput
 1130 120649 (1731) 3 Doing message:ReceiptData < servicerequest=RestInput
 1130 120649 (1739) 3   Process:ProcessingEngine_New_job_1_exstream (v. 1) > PDFOutput(null)
 1130 120649 (0089) 2 EX002522W (1) The locale is not set for this application. The language and locale will be set to default.
 1130 120649 (0089) 3 EX002697I (1) Data aggregation has been enabled due to XML end tag processing.
 1130 120649 (0089) 3 EX001800I (1) >>>>>>>>>>>> Driver File: opening the customer driver file named ReceiptData. <<<<<<<<<<<<
 1130 120649 (0089) 3 EX001000I (1) ********************* Customer 1:    Starts at input record 3 (byte 144)
 1130 120649 (0089) 1 EX004108E (1) The PNG pass-through file ($$CNT$$J+jQzJSMMF_9TsTKtJIJrg==) for variable RES MANAGER FILE is not a supported file or is damaged. File is ignored.
 1130 120649 (0089) 1 EX004108E (2) The PNG pass-through file ($$CNT$$k7iFrf4NoInN9jSQT9WfcQ==) for variable RES MANAGER FILE is not a supported file or is damaged. File is ignored.
 1130 120649 (0089) 2 EX004146W (1) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
 1130 120649 (0089) 2 EX004146W (2) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
 1130 120649 (0089) 2 EX004146W (3) Table rows set to split across pages are not supported in UDL output types. Rows will print on a single page and may cause output inconsistencies.
 1130 120649 (0090) 2 OpenText Exstream Engine exited with exit code 8.
 1130 120649 (5105) 3 Receiver of created document set (Document, reciever):A9B71115-46B1-354C-B6BF-6592C958BCE0,
 1130 120649 (5105) 3 Receiver of created document set (Document, reciever):136A1DC1-A85D-414A-AE68-DF988B1CEC04,
 1130 120649 (1723) 2 JobEnd:servicerequest=RestInput
 1130 120649 (0576) 3 Queue item 7096C45D-3BFB-8643-AE26-E7A0931B02E0 with external ID '' completed successfully.
 1130 120649 (0576) 3 Queue item A9B71115-46B1-354C-B6BF-6592C958BCE0 with external ID '' completed successfully.
 1130 120650 (0576) 3 Queue item 136A1DC1-A85D-414A-AE68-DF988B1CEC04 with external ID '' completed successfully.
 1130 120650 (0572) 3 Tracker '4A788746-710D-9646-8EF7-C1A3A396A637' (StrsID 5043092, external ID '') completed successfully."
 | rex field=data max_match=0 "(?<job_start>[^|]+)\s\(1719"
 | rex field=data max_match=0 "(?<job_end>.+?)\(0572"
 | eval job_start_epoch = strptime(job_start, "%m%d %H%M%S")
 | eval job_end_epoch = strptime(job_end, "%m%d %H%M%S")
 | eval job_dur_in_sec = job_end_epoch - job_start_epoch

the last 5 rows are the solution

hope it helps

[adonio]

hello there,

couple of things:
1. if it is all a single event, you can break it with rex or other methods
2. you can also line break in props.conf which will give you a single event for each line (or however you want)
3. i dont see milliseconds anywhere in the data, on the first sample, it starts at: 1130 120711 and ends at 1130 120711 (same timestamp, so less than a 1000 milliseconds for sure). on the second sample, it starts at '1130 120649and ends at1130 120650` so between 1000-2000 milliseconds, but again, where in the data are the milliseconds
4. would recommend adding a year to your timestamp

show us where the data about the milliseconds and we will assist with relevant search to solve the challenge

[stcrispan]

Ok, so just to update the issue, I've figured out a way to extract the "1130 120631" part of the "JobBegin" line:

^(?.+?)(1719

...using regex101.com

Now to change it into a proper date time stamp.

[stcrispan]

Ok, so converting to Date Time stamp appears to be an eval-strptime situation:

index=fool "1719" AND "0572" 
| rex "^(?<Job_Begin>.+?)\(1917"    #OR (Job_end, using 0572
| eval JobBeginEpoch=strptime(Job_Begin,"%m%d %H%M%S") 

Now comes the tricky part, of marking the first Event "Job_Begin", grabbing the time, marking the second event "Job_End" and marking that time, then figuring out the difference and plotting that per host.

[stcrispan]

adonio, thank you for your response, and the suggestions.

You are correct, there does not appear to be milliseconds being supplied by the events, so perhaps my goals are a bit ambitious...obviously, if ms are not supplied, the difference in ms cannot be determined. In that case, I would have to provide stats in seconds, but I'm not sure how to break out the time date stamp in a way which would allow me to subtract 59 from 00 and get 1 second. Also, how would I go about adding a year to the date stamp? I imagine it would be extracted from the Splunk timestamp on the event.

I'm all for using rex, and like I said I'm a total newb, so any techniques you'd care to share would to a long way.