Loki query to find difference between 2 timestamps

[prabalrakshit]

I am working on small Java application that writes logs as follows:
The first log represents a start time and the second and end time.

2023-08-28 09:50:12.414  INFO 1 --- [istener-1-0-C-1] .s.s.e.b.m.c.EventBrokerTemplateListener : Received message on outbound topic: from-mdsvc-sap-cic-plant-plant. internalUUID: 936bf1fa40813742254a980080dc345c, subaccountId: 093981df-e9e6-44f3-9515-d8e633a9e4ab
2023-08-28 09:50:12.787  INFO 1 --- [istener-1-0-C-1] c.s.s.e.b.m.api.eb.MessagePublisher      : Successfully invoked the Event Broker Publisher. internalUUID: 936bf1fa40813742254a980080dc345c, Response Code: 202 ACCEPTED

I would like an aggregated report that can provide, for a list of requests. The following:

internalUId | Start Time | End Time | Difference

internalUUID is not defined as a label for me now. Is there a way we can define it as a query time label?

[clevernessisamyth]

Hello,

Can you provide us with more logs?

For the second question, yes you can do it using pattern in the query.

[prabalrakshit]

Hello,

Thanks very much for your revert.

Here is a short snippet of the logs that are being pushed to Loki (have removed some unnecessary text)

2023-09-04 09:50:12.414 INFO 1 Received message on outbound topic: from-mdsvc-sap-cic-plant-plant. internalUUID: 936bf1fa40813742254a980080dc345c, subaccountId: 093981df-e9e6-44f3-9515-d8e633a9e4ab
2023-09-04 09:50:12.787 INFO 1 Successfully invoked the Event Broker Publisher. internalUUID: 936bf1fa40813742254a980080dc345c, Response Code: 202 ACCEPTED
2023-09-04 11:50:22.407 INFO 1 Received message on outbound topic: from-mdsvc-sap-cic-plant-plant. internalUUID: d565a8604bf811eea021325096b39f47, subaccountId: 093981df-e9e6-44f3-9515-d8e633a9e4ab
2023-09-04 11:50:22.597 INFO 1 Successfully invoked the Event Broker Publisher. internalUUID: d565a8604bf811eea021325096b39f47, Response Code: 202 ACCEPTED

The internalUUId is the key that ties the entry and exit logs.
What I would need is a chart like this:

internalUUID | Start Time | End Time | Duration (ms)
936bf1fa40813742254a980080dc345c | 2023-09-04 09:50:12.414 | 2023-09-04 09:50:12.787 | 373
d565a8604bf811eea021325096b39f47 | 2023-09-04 11:50:22.407 | 2023-09-04 11:50:22.597 | 190

internalUUID for me is not a static label, and possibly not a good candidate either. So I am wondering what my options are.

Regards,
Prabal

[clevernessisamyth]

I got it working:

Follow these steps:

I used pattern in the query to capture the values of DATE and internalUUID:

{logs="java"} | pattern `<DATE> INFO <_> internalUUID: <internalUUID>, <_>`

And then I did these transformations in order:

1. Extract the labels to fields.
2. Group by the interlanUUID and include all the values of DATE.
3. The resulted column is an Array containing the Start Time and End Time. Extract it to fields.
4. Organize the fields: Reorder the fields, rename the Time fields and hide the Array field.
5. Cast the fields to time to calculate the difference between the End Time and First Time.
6. Cast the fields back to string to display the fractions of the seconds.

*The time format used for both Casts is YYYY-MM-DD hh:mm:ss.SSS

[prabalrakshit]

Hi @clevernessisamyth
Thanks very much for your detailed reply. I could figure out the patterns on the log, and can see the additional labels as expected.
But I am unable to see an option to add transformations. As per the Grafana documentation Query and transform data | Grafana documentation this should be visible in a panel.
I have exported teh query results in a panel, but cannot see where to add a new transformation.
Do you think something needs to be configured on the panel explicitly?

[clevernessisamyth]

Hello,

Did you try the query in the Explore or in a panel in Dashboard?

[prabalrakshit]

Thanks! I was trying in a panel in the dashboard, but I could not figure out how to edit the panel and execute the transform. I could get this working now. Almost everything that you mentioned is working as expected.
One small hitch is that the final timestamps are not showing the milliseconds part. I could see you have added a convert field statement at the very end. Here you have a String that allows a date format. This is a bit different for me. However I will try to explore this more from my end.

[clevernessisamyth]

Yeah, for some reason, Grafana doesn’t display the milliseconds. I tried many things, but nothing seemed to work except changing the type from time to string with a specified format.

Besides that, did you get the result correct?