Open 99hops opened 1 year ago
tonyswu
commented
1 year ago Are those actual Loki timestamps or part of your log string? Is your log pipeline configured properly to parse the timestamp? An example of actual query result or screenshot would be helpful.
99hops
commented
1 year ago Hello @tonyswu these come from data.result[n].values[0][0] where in data.result[n] I have stream with no timestamp inside (I see JSONParserErr - Value looks like object, but can't find closing '}' symbol)
Here I've added nanotime example
resultType=streams
11 Aug 2023, 15:13:40 1691766820169332614
11 Aug 2023, 15:13:40 1691766820435525603
11 Aug 2023, 15:13:39 1691766819825155202
11 Aug 2023, 15:13:39 1691766819582725772
11 Aug 2023, 15:13:40 1691766820045705994
11 Aug 2023, 15:13:39 1691766819806198242
11 Aug 2023, 15:13:40 1691766820159221090
11 Aug 2023, 15:13:46 1691766826174655910
11 Aug 2023, 15:13:40 1691766820435564727
11 Aug 2023, 15:13:42 1691766822435795813
11 Aug 2023, 15:13:44 1691766824435962634
11 Aug 2023, 15:13:46 1691766826436194556
11 Aug 2023, 15:13:48 1691766828436342405
11 Aug 2023, 15:13:50 1691766830436540900
11 Aug 2023, 15:13:52 1691766832436695196
11 Aug 2023, 15:13:40 1691766820435558165
11 Aug 2023, 15:13:42 1691766822435782888
11 Aug 2023, 15:13:44 1691766824435957675
11 Aug 2023, 15:13:46 1691766826436175019
11 Aug 2023, 15:13:48 1691766828436319832
11 Aug 2023, 15:13:50 1691766830436540898
11 Aug 2023, 15:13:52 1691766832436695194
11 Aug 2023, 15:13:41 1691766821435646461
11 Aug 2023, 15:13:43 1691766823435821189
11 Aug 2023, 15:13:45 1691766825436051760Thing is this is unsorted raw list of nanotime results received from Loki and it's visible by the timestamp that sorting is not correct or at least not what I expect to receive. I've checked the "raw" json response and I confirm I see the same order inside.
As for pipelines I've tried many different combinations with the same result, current settings
config:
snippets:
addScrapeJobLabel: true
pipelineStages:
- regex:
expression: '^(?P<timestamp>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{9}[+-]\d{2}:\d{2})'
- timestamp:
source: timestamp
format: UnixNs
action_on_failure: fudgeFiles in inside /var/log/pods have this timestamp format 2023-08-08T19:57:38.703032331+03:00 at the beggining of every line.
Here is a raw json response I just took from query
{
"status": "success",
"data": {
"resultType": "streams",
"result": [
{
"stream": {
"app": "station.dev",
"component": "kube-apiserver",
"container": "kube-apiserver",
"filename": "/var/log/pods/kube-system_kube-apiserver-station.dev_0008833fe05f2d297f9b4fa6c4bbba7b/kube-apiserver/5.log",
"job": "kube-system/station.dev",
"namespace": "kube-system",
"node_name": "station.dev",
"pod": "kube-apiserver-station.dev",
"scrape_job": "kubernetes-pods",
"stream": "stderr"
},
"values": [
[
"1691770767495706689",
"I0811 16:19:27.495639 1 handler.go:232] Adding GroupVersion metrics.k8s.io v1beta1 to ResourceManager"
]
]
},
{
"stream": {
"app": "station.dev",
"component": "kube-controller-manager",
"container": "kube-controller-manager",
"filename": "/var/log/pods/kube-system_kube-controller-manager-station.dev_595775d9eff7749351a2a5f0520d8888/kube-controller-manager/5.log",
"job": "kube-system/station.dev",
"namespace": "kube-system",
"node_name": "station.dev",
"pod": "kube-controller-manager-station.dev",
"scrape_job": "kubernetes-pods",
"stream": "stderr"
},
"values": [
[
"1691770763660082220",
"I0811 16:19:23.660012 1 event.go:307] \"Event occurred\" object=\"dev/data-loki-write-1\" fieldPath=\"\" kind=\"PersistentVolumeClaim\" apiVersion=\"v1\" type=\"Normal\" reason=\"FailedBinding\" message=\"no persistent volumes available for this claim and no storage class is set\""
],
[
"1691770763660190535",
"I0811 16:19:23.660163 1 event.go:307] \"Event occurred\" object=\"dev/data-loki-write-0\" fieldPath=\"\" kind=\"PersistentVolumeClaim\" apiVersion=\"v1\" type=\"Normal\" reason=\"FailedBinding\" message=\"no persistent volumes available for this claim and no storage class is set\""
],
[
"1691770763660376498",
"I0811 16:19:23.660344 1 event.go:307] \"Event occurred\" object=\"dev/data-loki-write-2\" fieldPath=\"\" kind=\"PersistentVolumeClaim\" apiVersion=\"v1\" type=\"Normal\" reason=\"FailedBinding\" message=\"no persistent volumes available for this claim and no storage class is set\""
],
[
"1691770778660816238",
"I0811 16:19:38.660700 1 event.go:307] \"Event occurred\" object=\"dev/data-loki-write-2\" fieldPath=\"\" kind=\"PersistentVolumeClaim\" apiVersion=\"v1\" type=\"Normal\" reason=\"FailedBinding\" message=\"no persistent volumes available for this claim and no storage class is set\""
],
[
"1691770778660954961",
"I0811 16:19:38.660914 1 event.go:307] \"Event occurred\" object=\"dev/data-loki-write-1\" fieldPath=\"\" kind=\"PersistentVolumeClaim\" apiVersion=\"v1\" type=\"Normal\" reason=\"FailedBinding\" message=\"no persistent volumes available for this claim and no storage class is set\""
],
[
"1691770778661104464",
"I0811 16:19:38.661074 1 event.go:307] \"Event occurred\" object=\"dev/data-loki-write-0\" fieldPath=\"\" kind=\"PersistentVolumeClaim\" apiVersion=\"v1\" type=\"Normal\" reason=\"FailedBinding\" message=\"no persistent volumes available for this claim and no storage class is set\""
]
]
}
],
"stats": {
"summary": {
"bytesProcessedPerSecond": 1820485,
"linesProcessedPerSecond": 7353,
"totalBytesProcessed": 1733,
"totalLinesProcessed": 7,
"execTime": 0.000952,
"queueTime": 0.000022,
"subqueries": 0,
"totalEntriesReturned": 7,
"splits": 0,
"shards": 0
},
"querier": {
"store": {
"totalChunksRef": 0,
"totalChunksDownloaded": 0,
"chunksDownloadTime": 0,
"chunk": {
"headChunkBytes": 0,
"headChunkLines": 0,
"decompressedBytes": 0,
"decompressedLines": 0,
"compressedBytes": 0,
"totalDuplicates": 0
}
}
},
"ingester": {
"totalReached": 1,
"totalChunksMatched": 2,
"totalBatches": 1,
"totalLinesSent": 7,
"store": {
"totalChunksRef": 0,
"totalChunksDownloaded": 0,
"chunksDownloadTime": 0,
"chunk": {
"headChunkBytes": 1733,
"headChunkLines": 7,
"decompressedBytes": 0,
"decompressedLines": 0,
"compressedBytes": 0,
"totalDuplicates": 0
}
}
},
"cache": {
"chunk": {
"entriesFound": 0,
"entriesRequested": 0,
"entriesStored": 0,
"bytesReceived": 0,
"bytesSent": 0,
"requests": 0,
"downloadTime": 0
},
"index": {
"entriesFound": 0,
"entriesRequested": 0,
"entriesStored": 0,
"bytesReceived": 0,
"bytesSent": 0,
"requests": 0,
"downloadTime": 0
},
"result": {
"entriesFound": 0,
"entriesRequested": 0,
"entriesStored": 0,
"bytesReceived": 0,
"bytesSent": 0,
"requests": 0,
"downloadTime": 0
}
}
}
}
}And this is the "human-readable" representation of this json timestamps for '{namespace="kube-system"}' query
11 Aug 2023, 16:19:27 1691770767495706689
11 Aug 2023, 16:19:23 1691770763660082220
11 Aug 2023, 16:19:23 1691770763660190535
11 Aug 2023, 16:19:23 1691770763660376498
11 Aug 2023, 16:19:38 1691770778660816238
11 Aug 2023, 16:19:38 1691770778660954961
11 Aug 2023, 16:19:38 1691770778661104464From your raw json return, the logs seem to be in order from 1691770763660082220 to 1691770778661104464. Also, just want to point this out, Loki query result can contain multiple stream, and each stream has its own order. Make sure you aren't joining all streams together at once. See more here https://grafana.com/docs/loki/latest/api/.
If you have Grafana in front of Loki it would be good to see some screenshots as well.
chamini2
commented
1 year ago Loki query result can contain multiple stream, and each stream has its own order. Make sure you aren't joining all streams together at once. See more here https://grafana.com/docs/loki/latest/api/.
For me this was the key to finding the issue. I thought since I was filtering by the loki stream, there should never be more than one stream in the response. But what happens is when you parse json, the generated labels ARE CONSIDERED for the stream separation.
In my case, that meant each log line was in it's own separate stream.
I had to add a keep labels expression to only get a stream based on the original stream.
in my example, that is:
{my_main_label="somevalue"} | json | json_label="otherfilter" | keep my_main_labeland that would return a single stream with all the logs correctly ordered!
nickzelei
commented
7 months ago Loki query result can contain multiple stream, and each stream has its own order. Make sure you aren't joining all streams together at once. See more here https://grafana.com/docs/loki/latest/api/.
For me this was the key to finding the issue. I thought since I was filtering by the loki stream, there should never be more than one stream in the response. But what happens is when you parse json, the generated labels ARE CONSIDERED for the stream separation.
In my case, that meant each log line was in it's own separate stream.
I had to add a keep labels expression to only get a stream based on the original stream.
in my example, that is:
{my_main_label="somevalue"} | json | json_label="otherfilter" | keep my_main_labeland that would return a single stream with all the logs correctly ordered!
Your comment saved me.
I've been banging my head against the wall until finding this comment, which seems to have fixed my ordering woes. I looked up the keepdocs and all of the examples are specific to json. Wish it was more evident this was the cause when adding json parsing to log queries.
thank you!!
I am observing something abnormal in the results ordering returned by
/query_rangeI see no reason for this behavior with defaultdirection(backward). This is a snapshot of results order where you can see the timestamps are not ordered in desc order based on timestamp.Loki is fed by promtail reading from /var/log/pods with default heml configuration for both (Loki and promtail)
Loki and promtail use the latest helm versions. Kubernetes v1.27.4