Cannot use row time as start/end query parameter #597

dprokop · 2019-05-17T09:15:35Z

Describe the bug
When querying logs with a given start timestamp, the response contains log lines preceding the timestamp or duplicates of the original log line.

Expected behaviour
Response should contain logs with timestamp > start

Screenshots, promtail config, or terminal output

Here I have requested logs with a start parameter = timestamp of the log line at the bottom. See the log lines in the result
Same situation as described above. The result contains the original log line and the log that preceded it:

The text was updated successfully, but these errors were encountered:

gouthamve · 2019-05-17T09:16:53Z

This is expected behaviour, we expect you to add a nanosecond to the previous timestamp for the results.

dprokop · 2019-05-17T09:38:58Z

@gouthamve ok, that makes sense (ignored JS precision when doing calculations). But what about the second situation, where a log line that happened before the original one was included?

gouthamve · 2019-05-17T09:52:54Z

That might be a bug. We should parse the timestamp from docker if I am not wrong. /cc @slim-bean @Kuqd

cyriltovena · 2019-05-17T12:42:08Z

yes we are now !

dprokop · 2019-05-21T15:45:38Z

I've been playing with the log context a little bit more, and seems like the problem still occurs, see image for details:

All logs in the "after" context happened before actually.

The timestamp of the original log row, for which the context is shown is 1558451701326000000ns, (2019-05-21T15:15:01.3269129Z)

The request payload I'm sending to retrieve the "after" context for that log is:

{
  limit: 10,
  query: {filename="/var/log/docker.log",job="varlogs"},
  direction: FORWARD,
  start: 1558451701326000000,
  end: 1558458901326000000,
}

The response is:

{  
   "streams":[  
      {  
         "labels":"{filename=\"/var/log/docker.log\", job=\"varlogs\"}",
         "entries":[  
            {  
               "ts":"2019-05-21T15:15:01.3260533Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.921280100Z\" level=debug msg=\"event published\" ns=moby topic=\"/tasks/create\" type=containerd.events.TaskCreate "
            },
            {  
               "ts":"2019-05-21T15:15:01.3260651Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.921637800Z\" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/create"
            },
            {  
               "ts":"2019-05-21T15:15:01.3261947Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.939596400Z\" level=debug msg=\"event published\" ns=moby topic=\"/tasks/start\" type=containerd.events.TaskStart "
            },
            {  
               "ts":"2019-05-21T15:15:01.3262071Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.939978900Z\" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/start"
            },
            {  
               "ts":"2019-05-21T15:15:01.3263312Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.952712500Z\" level=debug msg=\"Calling GET /v1.24/containers/36c115a96c0dd33831fa0c72f5b5b74990a9964a897dc9b8652d59a255b42a1c/json\""
            },
            {  
               "ts":"2019-05-21T15:15:01.3263505Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.955750700Z\" level=debug msg=\"Calling DELETE /v1.22/containers/9311a2e603b4cc816d91b101b5d00119b8d8167b40fcb6bc9d9cafebf0270043?v=False\u0026link=False\u0026force=False\""
            },
            {  
               "ts":"2019-05-21T15:15:01.3264721Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.970318700Z\" level=debug msg=\"Name To resolve: localhost.\""
            },
            {  
               "ts":"2019-05-21T15:15:01.3264844Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.970480000Z\" level=debug msg=\"[resolver] query localhost. (A) from 172.19.0.3:39569, forwarding to udp:192.168.65.1\""
            },
            {  
               "ts":"2019-05-21T15:15:01.3266311Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.970645400Z\" level=debug msg=\"Name To resolve: localhost.\""
            },
            {  
               "ts":"2019-05-21T15:15:01.3266427Z",
               "line":"2019-05-21T15:14:50Z docker time=\"2019-05-21T15:14:50.970793000Z\" level=debug msg=\"[resolver] query localhost. (AAAA) from 172.19.0.3:36178, forwarding to udp:192.168.65.1\""
            }
         ]
      }
   ]
}

I assume this might be related to precision loss in Explore when we convert log's timestamp to ms, which is later converted to ns when requesting context:

1558451701326000000ns !== 2019-05-21T15:15:01.3269129Z, isn't it?

cc @davkal

davkal · 2019-05-30T17:22:54Z

Grafana is using the row ts as a cursor to load more logs for context or pagination requests. Currently this is not accurately possible since we're losing the nano precision when processing log rows (converting the row ts to a number). JS cannot process nanos very well, and native support is a while off.

Can we change the query API to be able to use ISO date strings for start and end (in effect Grafana would be using the raw ts values)?

steven-sheehy · 2019-05-31T21:11:07Z

Looking at the code, it should be possible for Loki to support both ns and string. It can first attempt integer conversion and if that fails to fallback to string (or vice versa). The string format should be in RFC3339Nano format.

cyriltovena · 2019-06-11T12:59:06Z

@dprokop We've merged the new iso string parameter. Does that fix the issue ?

cyriltovena · 2019-06-17T15:53:16Z

@dprokop gentle bump :)

dprokop · 2019-06-27T12:03:32Z

@Kuqd thanks, haven't checked yet, we haven't prioritized the fix yet. @hugohaggmark is on it today, so let's see ltr.

hugohaggmark · 2019-06-27T13:50:30Z

@Kuqd so I'm a complete newb as to the Loki API but I think I still can find a discrepancy.

The following request to the Loki API:

{
  limit: 10,
  query: {filename="/var/log/docker.log",job="varlogs"},
  direction: BACKWARD,
  start: 1561633582707000000,
  end: 2019-06-27T13:06:22.707812623Z,
}

Returns the following data:

{
   "streams":[
      {
         "labels":"{filename=\"/var/log/docker.log\", job=\"varlogs\"}",
         "entries":[
            {
               "ts":"2019-06-27T13:06:22.707747196Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.808905537Z\" level=debug msg=\"[resolver] received AAAA record \\\"::1\\\" for \\\"localhost.\\\" from udp:192.168.65.1\""
            },
            {
               "ts":"2019-06-27T13:06:22.707746107Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.808807197Z\" level=debug msg=\"[resolver] received A record \\\"127.0.0.1\\\" for \\\"localhost.\\\" from udp:192.168.65.1\""
            },
            {
               "ts":"2019-06-27T13:06:22.707694961Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.808381019Z\" level=debug msg=\"[resolver] query localhost. (AAAA) from 172.18.0.2:34072, forwarding to udp:192.168.65.1\""
            },
            {
               "ts":"2019-06-27T13:06:22.707687376Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.808228634Z\" level=debug msg=\"[resolver] query localhost. (A) from 172.18.0.2:38615, forwarding to udp:192.168.65.1\""
            },
            {
               "ts":"2019-06-27T13:06:22.707686517Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.807582337Z\" level=debug msg=\"Name To resolve: localhost.\""
            },
            {
               "ts":"2019-06-27T13:06:22.707661805Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.807582176Z\" level=debug msg=\"Name To resolve: localhost.\""
            },
            {
               "ts":"2019-06-27T13:06:22.70766095Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.680900856Z\" level=debug msg=\"Calling GET /v1.24/containers/39bd7d679c9f6e9dc625b4ec7ab0ae5786b65f9f466a16ab2cc26cb83e6d295b/json\""
            },
            {
               "ts":"2019-06-27T13:06:22.707609948Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.676668753Z\" level=debug msg=\"Calling GET /v1.24/containers/e58a2ae3ef5aa7a6da638683e624c4683460455b3323f9b658f64821abd8beaf/json\""
            },
            {
               "ts":"2019-06-27T13:06:22.707609035Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.658462754Z\" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/start"
            },
            {
               "ts":"2019-06-27T13:06:22.707556352Z",
               "line":"2019-06-27T13:06:15Z docker time=\"2019-06-27T13:06:15.658359222Z\" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/start"
            }
         ]
      }
   ]
}

Notice how there is no entry with the ts = 2019-06-27T13:06:22.707812623Z

When I instead do this request:

{
  limit: 10,
  query: {filename="/var/log/docker.log",job="varlogs"},
  direction: FORWARD,
  start: 2019-06-27T13:06:22.707812623Z,
  end: 1561647982707000000,
}

Returns the following data:

{
   "streams":[
      {
         "labels":"{filename=\"/var/log/docker.log\", job=\"varlogs\"}",
         "entries":[
            {
               "ts":"2019-06-27T13:06:22.707812623Z",
               "line":"2019-06-27T13:06:20Z docker time=\"2019-06-27T13:06:20.973573343Z\" level=debug msg=\"Name To resolve: loki.\""
            },
            {
               "ts":"2019-06-27T13:06:22.707813544Z",
               "line":"2019-06-27T13:06:20Z docker time=\"2019-06-27T13:06:20.973625876Z\" level=debug msg=\"[resolver] lookup for loki.: IP [172.18.0.2]\""
            },
            {
               "ts":"2019-06-27T13:06:22.707867255Z",
               "line":"2019-06-27T13:06:20Z docker time=\"2019-06-27T13:06:20.973593795Z\" level=debug msg=\"Name To resolve: loki.\""
            },
            {
               "ts":"2019-06-27T13:06:22.707868097Z",
               "line":"2019-06-27T13:06:20Z docker time=\"2019-06-27T13:06:20.973727199Z\" level=debug msg=\"[resolver] lookup name loki. present without IPv6 address\""
            },
            {
               "ts":"2019-06-27T13:07:16.017786401Z",
               "line":"2019-06-27T13:07:15Z docker time=\"2019-06-27T13:07:15.811294344Z\" level=debug msg=\"Name To resolve: localhost.\""
            },
            {
               "ts":"2019-06-27T13:07:16.017840662Z",
               "line":"2019-06-27T13:07:15Z docker time=\"2019-06-27T13:07:15.811556502Z\" level=debug msg=\"[resolver] query localhost. (AAAA) from 172.18.0.2:38715, forwarding to udp:192.168.65.1\""
            },
            {
               "ts":"2019-06-27T13:07:16.017904857Z",
               "line":"2019-06-27T13:07:15Z docker time=\"2019-06-27T13:07:15.811192361Z\" level=debug msg=\"Name To resolve: localhost.\""
            },
            {
               "ts":"2019-06-27T13:07:16.017944772Z",
               "line":"2019-06-27T13:07:15Z docker time=\"2019-06-27T13:07:15.811805280Z\" level=debug msg=\"[resolver] query localhost. (A) from 172.18.0.2:51778, forwarding to udp:192.168.65.1\""
            },
            {
               "ts":"2019-06-27T13:07:16.017946614Z",
               "line":"2019-06-27T13:07:15Z docker time=\"2019-06-27T13:07:15.812185465Z\" level=debug msg=\"[resolver] received A record \\\"127.0.0.1\\\" for \\\"localhost.\\\" from udp:192.168.65.1\""
            },
            {
               "ts":"2019-06-27T13:07:16.017964181Z",
               "line":"2019-06-27T13:07:15Z docker time=\"2019-06-27T13:07:15.812319067Z\" level=debug msg=\"[resolver] received AAAA record \\\"::1\\\" for \\\"localhost.\\\" from udp:192.168.65.1\""
            }
         ]
      }
   ]
}

Notice that the first entry has ts =2019-06-27T13:06:22.707812623Z

As a newb I expect the API to either return the 2019-06-27T13:06:22.707812623Z entry in both requests or in none of them. Is this a bug or is this by design?

cyriltovena · 2019-06-27T16:03:44Z

@hugohaggmark yes this is normal, the end is exclusive but the start is inclusive. You don't have to feel like a newb this is not documented properly.

Does that make sense ? let's keep that issue open to improve the doc around that behaviour.

stale · 2019-09-03T15:11:04Z

This issue has been automatically marked as stale because it has not had any activity in the past 30 days. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

aocenas · 2020-01-23T16:49:34Z

@cyriltovena

the end is exclusive but the start is inclusive

Is this still true? Trying some requests and what I see:

request with start=1579792992203968000

http://localhost:3000/api/datasources/proxy/28/loki/api/v1/query_range?limit=11&query=%7Bjob%3D%22log%22%2Cjob_name%3D%22run_log%22%2Csource%3D%22test_application%22%7D&expr=%7Bjob%3D%22log%22%2Cjob_name%3D%22run_log%22%2Csource%3D%22test_application%22%7D&direction=FORWARD&start=1579792992203968000&end=1579800192203000000

{"status":"success","data":{"resultType":"streams","result":[]}}

Same request just start=1579792992203967000 (minus 1us)

http://localhost:3000/api/datasources/proxy/28/loki/api/v1/query_range?limit=11&query=%7Bjob%3D%22log%22%2Cjob_name%3D%22run_log%22%2Csource%3D%22test_application%22%7D&expr=%7Bjob%3D%22log%22%2Cjob_name%3D%22run_log%22%2Csource%3D%22test_application%22%7D&direction=FORWARD&start=1579792992203967000&end=1579800192203000000

{"status":"success","data":{"resultType":"streams","result":[{"stream":{"job":"log","job_name":"run_log","source":"test_application"},"values":[["1579792992203968000","Info: message=\"error\""],["1579792992203968000","Info: message=\"after\""]]}]}}

This returned data with ts = 1579792992203968000 which is the start time of the first request

davkal changed the title ~~Query does not respect start parameter~~ Cannot use row time as start/end query parameter May 30, 2019

dprokop mentioned this issue Jun 3, 2019

Log row context: use raw timestamp instead of nanosecond epoch when querying context grafana/grafana#17406

Closed

cyriltovena mentioned this issue Jun 7, 2019

add support for RFC3339Nano in query timestamps #656

Merged

hugohaggmark mentioned this issue Jun 28, 2019

Explore: Uses RFC3339Nano string to retrieve LogRow contexts from Loki API grafana/grafana#17813

Merged

This was referenced Jul 3, 2019

Loki: Adds comment explaining usage of RFC3339Nano string grafana/grafana#17872

Merged

Loki: Show context in Explore doesn't work grafana/grafana#17862

Closed

candlerb mentioned this issue Jul 9, 2019

Consistent use of timestamps in API #522

Closed

stale bot added the stale A stale issue or PR that will automatically be closed. label Sep 3, 2019

stale bot closed this as completed Sep 10, 2019

cyriltovena mentioned this issue Jan 23, 2020

Request start and end inclusivity/exclusivity #1570

Closed

jgehrcke mentioned this issue May 25, 2020

Query start is not always inclusive #2124

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cannot use row time as start/end query parameter #597

Cannot use row time as start/end query parameter #597

dprokop commented May 17, 2019

gouthamve commented May 17, 2019

dprokop commented May 17, 2019

gouthamve commented May 17, 2019

cyriltovena commented May 17, 2019

dprokop commented May 21, 2019 •

edited

Loading

davkal commented May 30, 2019

steven-sheehy commented May 31, 2019

cyriltovena commented Jun 11, 2019

cyriltovena commented Jun 17, 2019

dprokop commented Jun 27, 2019

hugohaggmark commented Jun 27, 2019

cyriltovena commented Jun 27, 2019 •

edited

Loading

stale bot commented Sep 3, 2019

aocenas commented Jan 23, 2020

Cannot use row time as start/end query parameter #597

Cannot use row time as start/end query parameter #597

Comments

dprokop commented May 17, 2019

gouthamve commented May 17, 2019

dprokop commented May 17, 2019

gouthamve commented May 17, 2019

cyriltovena commented May 17, 2019

dprokop commented May 21, 2019 • edited Loading

davkal commented May 30, 2019

steven-sheehy commented May 31, 2019

cyriltovena commented Jun 11, 2019

cyriltovena commented Jun 17, 2019

dprokop commented Jun 27, 2019

hugohaggmark commented Jun 27, 2019

cyriltovena commented Jun 27, 2019 • edited Loading

stale bot commented Sep 3, 2019

aocenas commented Jan 23, 2020

dprokop commented May 21, 2019 •

edited

Loading

cyriltovena commented Jun 27, 2019 •

edited

Loading