0

First Event

17:09:05:362 INFO com.a.b.App - Making a GET Request and req-id: [123456]

Second Event

17:09:06:480 INFO com.a.b.App - Output Status Code: 200 req-id:"123456"

I tried to use index="xyz" container="service-name" | transaction "req-id" startswith="Making a GET Request" endswith="Output Status Code" | table duration but it is also not working.

I want to calculate duration of above two events for every request. I went over some solutions in splunk and Stack Overflow, but still can't get the proper result.

Sat
  • 3,520
  • 9
  • 39
  • 66
  • are you `req_id` fields ever duplicated? – warren Feb 17 '23 at 00:09
  • yes, in the middle one more log/event also has req-id – Sat Feb 17 '23 at 09:04
  • message-1: `com.a.d.controller : Request initiated x-req-id: [12345]` message-2: `com.a.d.controller : header: x-req-id: 12345` message-3: `com.a.d.service : Result of data: <200, x-req-id:"12345", .....` I need to calculate time duration between message-1 and message-3 – Sat Feb 17 '23 at 09:06

2 Answers2

1

Try doing it with stats instead:

index=ndx sourcetype=srctp 
| rex field=_raw "req\-id\D+(?<req_id>\d+)"
| rex field=_raw "(?<sequence>Making a GET Request)"
| rex field=_raw "(?<sequence>Output Status Code)"
| eval sequence=sequence+";"+_time
| stats values(sequence) as sequence by req_id
| mvexpand sequence
| rex field=sequence "(?<sequence>[^;]+);(?<time>\d+)"
| eval time=strftime(time,"%c")

This will extract the "req-id" into a field named req_id, and the start and end of the sequence into a field named sequence

Presuming the sample data you shared is correct, when you stats values(sequence) as sequence, it will put the "Making..." entry first and the "Output..." entry second

Because values() will do this, when you mvexpand and then split the values()'d field part into sequence and time, they'll be in the proper order

If the sample data is incomplete, you may need to tweak the regexes for populating sequence

warren
  • 32,620
  • 21
  • 85
  • 124
  • `sourcetype=xyz container_name="abc-mno" | rex field=_raw "x\-req\-id\S+(?\d+)" | rex field=_raw "com.a.b.controller\- (?Making a GET Request)" | rex field=_raw "com.a.b.Service\- (?Output Status Code)" | eval sequence=sequence+";"+_time | stats values(sequence) as sequence by x_req_id | mvexpand sequence | rex field=sequence "(?[^;]+);(? – Sat Feb 16 '23 at 07:46
  • @Sat - it sounds like you've got a formatting issue in the regex. What does your sample data *actually* look like? – warren Feb 16 '23 at 14:18
  • I have provided my sample data only in the above query.. only different is with sourceType, container-name, package, class-names and text messages. message-1: `com.a.d.controller : Request initiated x-req-id: [12345]` message-2: `com.a.d.service : Result of data: <200, x-req-id:"12345", .....` – Sat Feb 16 '23 at 14:40
  • @Sat - see my update: try changing "`\S+`" to "`\D+`" in the `req_id` extraction – warren Feb 17 '23 at 00:11
  • I tried by changing `\S+` with `\D+` but still same issue – Sat Feb 17 '23 at 09:10
  • @Sat - I shortened the `rex` line – warren Feb 17 '23 at 16:34
0

It’s seem you’re going with my previously suggested approach

Now you have 2 possibilities

1. SPL

Below the simplest query, only invoking 1 rex and assuming _time field correctly filled

index=<your_index> source=<your_source>
("*Making a GET Request*" OR "*Output Status Code*")
| rex field=_raw "req\-id\D+(?<req_id>\d+)"
| stats max(_time) as end, min(_time) as start by id
| eval duration = end - start
| table id duration

Note that depending the amount of data to scan, this one can be ressources consuming for your Splunk cluster

2. Log the response time directly in API (more efficient)

It seem you are working on an API. You must have capabilities to get the response time of each call and directly trace it in your log

Then you can exploit it easily in SPL without calculation

It always preferable to persist data at index time vs. operate systematic calculation at search time

Hakan
  • 126
  • 5