find top maximum transaction duration

[indeed_2000]

Hi
I have log file like this:

2021-07-15 00:00:01,869 INFO APP.InEE-p1-1234567 [AppListener] Receive Message[A123]: Q[p1.APP], IID[null], Cookie[{"NODE":"0000aa000"}]
.
.
2021-07-15 00:00:01,988 INFO APP.InEE-p1-1234567 [AaaPowerManager] Send Message [X0000A0000] to [APP.p2] with IID[null], LTE[00000]
.
.
2021-07-15 00:00:11,714 INFO APP.InE-p2-9876543 [AppListener] Receive Message[Y000000Z00000]: Q[p2.APP], IID[null], Cookie[null]
.
.
2021-07-15 00:00:11,747 INFO APP.InEE-P2-9876543_CLIENT.InEE-p1-1234567 [AaaPowerManager] Send Message [A123] to [APP.p1] with IID[null], LTE[00000]
.
.

want to calculate duration of each transaction like this ("Send Message"-"Receive Message"="duration")
00:00:11,747  -  00:00:01,869  = 00:00:09:878

output exception:
id                      duration
1234567       00:00:09:878

any idea?
Thanks

[richgalloway]

Is the id field extracted correctly?  The last event contains both 1234567 and 9876543 so which is the correct id?

If you're using the transaction command then the startswith and endswith option values may need to be expanded to include more text so the right events are used.

If using the stats command then you'll probably need to eliminate unwanted events before calculating the range.

[indeed_2000]

1-Yes id extraction work but separate them.

2-last item contain both which 1234567  is correct.

3-which one is better for this scenario?

4-would you please tell me spl command.

 Thanks 

[richgalloway]

This query uses the second id in an event that contains more than one.

| rex max_match=2 "\.\w+-\w+-(?<id>\d+)"
| eval id=coalesce(mvindex(id,1),mvindex(id,0))
| stats range(_time) as duration by id
| eval duration=tostring(duration,"duration")
| table id duration

[indeed_2000]

Here is the output

id                     duration

1234567      00:00:00:119
9876543      00:00:00:000

[richgalloway]

There are a couple of ways to do that.  Both of these example assume the id field is already extracted.

| transaction id startswith="Send Message" endswith="Receive Message"
| eval duration=tostring(duration,"duration")
| table id duration

| stats range(_time) as duration by id
| eval duration=tostring(duration,"duration")
| table id duration

[indeed_2000]

thank you for answer, do you have any idea about id extraction?

[richgalloway]

If I've made the right assumptions about where the id field is then this should extract it for you.

| rex "\.\w+-\w+-(?<id>\d+)"
| stats range(_time) as duration by id
| eval duration=tostring(duration,"duration")
| table id duration

[indeed_2000]

thank you for answer, currently it return 00:00:00:119

because of second "Send Message" in middle of event

actually the main problem is detect start and end part of transaction

start: APP.InEE-p1-1234567 [AppListener] Receive Message

End: APP.InEE-P2-9876543_CLIENT.InEE-p1-1234567 [AaaPowerManager] Send Message

one thing that come to my mind is use this 9876543  to detect end of transaction 

this id create when server2 reply to server1

here is what happening, this app work like this:

this app locate beside two server, get packets from server1 and send to server2 and return reply to server1

Receive (request from server1)> Send(request to server2) > Receive(reply from server2) > Send (reply  to server1)

any idea?

thanks

[richgalloway]

It seems to me (not knowing anything about your application) that the transaction duration most interesting is that for AppListener since that appears to include the time spent by downstream servers.  If that's the case then you may be able to include only AppListener in the query.

[indeed_2000]

You right it is better to work with this items

2021-07-15 00:00:01,869 INFO APP.InEE-p1-1234567 [AppListener] Receive Message[A123]: Q[p1.APP], IID[null], Cookie[{"NODE":"0000aa000"}]
.
.
2021-07-15 00:00:01,988 INFO APP.InEE-p1-1234567 [AaaPowerManager] Send Message [X0000A0000] to [APP.p2] with IID[null], LTE[00000]
.
.
2021-07-15 00:00:11,714 INFO APP.InE-p2-9876543 [AppListener] Receive Message[Y000000Z00000]: Q[p2.APP], IID[null], Cookie[null]
.
.
2021-07-15 00:00:11,747 INFO APP.InEE-P2-9876543_CLIENT.InEE-p1-1234567 [AaaPowerManager] Send Message [A123] to [APP.p1] with IID[null], LTE[00000]

I change the color of them so with this condition, do you have any idea to grep start and end of transaction correctly?

currently result is:

id                        duration

1234567         00:00:00:119

9876543        00:00:00:033

expected result:

id                        duration

1234567       00:00:09:878

Thanks,