Missing log lines when using json parser and label filter on a loki data source

[wallrj]

I (sometimes) notice that when I add a matching filter to a loki log query, matching log lines are not shown in the results.
When I remove the filter, all the log lines are shown.

With filter

Without filter

I expected all three log lines to be shown in both these queries.

I have sometimes noted that simply adding the json processor to the pipeline results in log lines missing from the results.

The newest line is the one that remains.

Environment:
Grafana Cloud: Grafana v7.3.7 (1e261642f4)

[ivanahuckova]

Hello @wallrj, would you mind sharing with us response from query inspector to see if problem is on grafana's side or loki's. Also, it doesn't seem to be related to this issue, but in 7.4.0 release we have removed redundant deduplication of logs which was sometimes cause of not showing all received logs. However, this was related to the logs that have the same content and same nanoseconds timestamp, which isn't your case.

[wallrj]

Thanks for investigating @ivanahuckova

Here's the query inspector output, with and without the json parser in the query:

Without json filter - 3 log lines

Query: {job="systemd-journal",unit="dl-cr.service", hostname=~"${hostname}"} |= "\"event\": \"access\""

Response:

{
  "request": {
    "url": "api/datasources/proxy/3/loki/api/v1/query_range?direction=BACKWARD&limit=1000&query=%7Bjob%3D%22systemd-journal%22%2Cunit%3D%22dl-cr.service%22%2C%20hostname%3D~%22%5Ba-z0-9-%5D%2B%22%7D%20%7C%3D%20%22%5C%22event%5C%22%3A%20%5C%22access%5C%22%22%20&start=1613451219000000000&end=1613462020000000000&step=5",
    "hideFromInspector": false
  },
  "response": {
    "status": "success",
    "data": {
      "resultType": "streams",
      "result": [
        {
          "stream": {
            "hostname": "dxxxxxxxxn",
            "job": "systemd-journal",
            "unit": "dl-cr.service"
          },
          "values": [
            [
              "1613460586552426000",
              "{\"controller\": \"audit\", \"card_id\": 1xxxxxxxx0, \"direction\": \"in\", \"age\": 0.18706742300128099, \"created\": 129362.2029871647, \"result\": \"allowed\", \"AUTHORIZED\": 0.009545845998218283, \"CHECKED\": 0.172847976005869, \"UNLOCKED\": 0.18133648799266666, \"AUDIT\": 0.1875413249945268, \"event\": \"access\", \"logger\": \"dl.controllers._audit\", \"level\": \"info\", \"timestamp\": \"2021-02-16T07:29:46.550657Z\"}"
            ],
            [
              "1613459434192164000",
              "{\"controller\": \"audit\", \"card_id\": 1xxxxxxxxxxx6, \"direction\": \"in\", \"age\": 0.17201277799904346, \"created\": 128209.8579910587, \"result\": \"allowed\", \"AUTHORIZED\": 0.01272779400460422, \"CHECKED\": 0.1574746359983692, \"UNLOCKED\": 0.16606799099827185, \"AUDIT\": 0.172217515995726, \"event\": \"access\", \"logger\": \"dl.controllers._audit\", \"level\": \"info\", \"timestamp\": \"2021-02-16T07:10:34.190371Z\"}"
            ],
            [
              "1613457976262614000",
              "{\"controller\": \"audit\", \"card_id\": 1xxxxxxxxxxx0, \"direction\": \"in\", \"age\": 0.34728201999678276, \"created\": 126751.7536492737, \"result\": \"allowed\", \"AUTHORIZED\": 0.006319991996861063, \"CHECKED\": 0.331661181000527, \"UNLOCKED\": 0.33897246500418987, \"BEEP\": 0.3412512969953241, \"AUDIT\": 0.3475083200028166, \"event\": \"access\", \"logger\": \"dl.controllers._audit\", \"level\": \"info\", \"timestamp\": \"2021-02-16T06:46:16.260961Z\"}"
            ]
          ]
        }
      ],
      "stats": {
        "summary": {
          "bytesProcessedPerSecond": 2493501,
          "linesProcessedPerSecond": 8515,
          "totalBytesProcessed": 17277,
          "totalLinesProcessed": 59,
          "execTime": 0.00692881
        },
        "store": {
          "totalChunksRef": 5,
          "totalChunksDownloaded": 5,
          "chunksDownloadTime": 0.002173225,
          "headChunkBytes": 0,
          "headChunkLines": 0,
          "decompressedBytes": 1050,
          "decompressedLines": 5,
          "compressedBytes": 1095,
          "totalDuplicates": 6
        },
        "ingester": {
          "totalReached": 210,
          "totalChunksMatched": 21,
          "totalBatches": 0,
          "totalLinesSent": 0,
          "headChunkBytes": 16227,
          "headChunkLines": 54,
          "decompressedBytes": 0,
          "decompressedLines": 0,
          "compressedBytes": 0,
          "totalDuplicates": 0
        }
      }
    }
  }
}

With json filter - 1 log line

Query: {job="systemd-journal",unit="dl-cr.service", hostname=~"${hostname}"} |= "\"event\": \"access\"" | json

Response:

{
  "request": {
    "url": "api/datasources/proxy/3/loki/api/v1/query_range?direction=BACKWARD&limit=1000&query=%7Bjob%3D%22systemd-journal%22%2Cunit%3D%22dl-cr.service%22%2C%20hostname%3D~%22%5Ba-z0-9-%5D%2B%22%7D%20%7C%3D%20%22%5C%22event%5C%22%3A%20%5C%22access%5C%22%22%20%7C%20json&start=1613451354000000000&end=1613462155000000000&step=5",
    "hideFromInspector": false
  },
  "response": {
    "status": "success",
    "data": {
      "resultType": "streams",
      "result": [
        {
          "stream": {
            "AUDIT": "0.1875413249945268",
            "UNLOCKED": "0.18133648799266666",
            "job": "systemd-journal",
            "result": "allowed",
            "AUTHORIZED": "0.009545845998218283",
            "age": "0.18706742300128099",
            "logger": "dl.controllers._audit",
            "unit": "dl-cr.service",
            "event": "access",
            "timestamp": "2021-02-16T07:29:46.550657Z",
            "CHECKED": "0.172847976005869",
            "card_id": "1xxxxxxxxxxxx0",
            "controller": "audit",
            "created": "129362.2029871647",
            "direction": "in",
            "hostname": "dxxxxxxn",
            "level": "info"
          },
          "values": [
            [
              "1xxxxxxxxxxx0",
              "{\"controller\": \"audit\", \"card_id\": 1xxxxxxxxxxx0, \"direction\": \"in\", \"age\": 0.18706742300128099, \"created\": 129362.2029871647, \"result\": \"allowed\", \"AUTHORIZED\": 0.009545845998218283, \"CHECKED\": 0.172847976005869, \"UNLOCKED\": 0.18133648799266666, \"AUDIT\": 0.1875413249945268, \"event\": \"access\", \"logger\": \"dl.controllers._audit\", \"level\": \"info\", \"timestamp\": \"2021-02-16T07:29:46.550657Z\"}"
            ]
          ]
        }
      ],
      "stats": {
        "summary": {
          "bytesProcessedPerSecond": 2964779,
          "linesProcessedPerSecond": 10254,
          "totalBytesProcessed": 17637,
          "totalLinesProcessed": 61,
          "execTime": 0.00594884
        },
        "store": {
          "totalChunksRef": 4,
          "totalChunksDownloaded": 4,
          "chunksDownloadTime": 0.0010863090000000001,
          "headChunkBytes": 0,
          "headChunkLines": 0,
          "decompressedBytes": 840,
          "decompressedLines": 4,
          "compressedBytes": 876,
          "totalDuplicates": 2
        },
        "ingester": {
          "totalReached": 210,
          "totalChunksMatched": 42,
          "totalBatches": 0,
          "totalLinesSent": 0,
          "headChunkBytes": 16797,
          "headChunkLines": 57,
          "decompressedBytes": 0,
          "decompressedLines": 0,
          "compressedBytes": 0,
          "totalDuplicates": 0
        }
      }
    }
  }
}

[ivanahuckova]

@wallrj thanks for sharing this! I have transferred this to grafana/loki repo as it seems like a problem on Loki side and not Grafana.

[cyriltovena]

Hey @wallrj,

Do you see this issue for anything else than fresh data ? Or this mostly happening when querying recent data ? Can reproduce this over and over ?

Trying to gather more information to pinpoint the issue.

[wallrj]

Hi @cyriltovena

Thanks for investigating.

Do you see this issue for anything else than fresh data ? Or this mostly happening when querying recent data ? Can reproduce this over and over ?

It seems to only be when querying recent data.
When I zoom back in on the three log lines above, between 0645 and 0730 this morning, I now see all three log lines, even with the json filter.

And also worth noting that the three log events showed up in the loki based graphs, even for recent data, and those also use the json filter.
I have a dashboard showing: graph (checkin / checkout per hour), graph(checkin duration), and a logs panel showing the log lines.

Let me know if you need any other info.

[cyriltovena]

I'm chasing this one, I think it's a duplicate of #3208.

[loganmc10]

I think I'm running into a similar issue, I feel like I'm losing my mind. I have JSON data going into Loki, and sometimes when I query it, not all the lines show up. If I fiddle with my selectors, and wait for a bit, it seems to fix itself, and the missing lines reappear.

It seems to be more based on the time than anything, since after they reappear, the original query works.

I'm on Grafana Cloud (7.4.3 currently), it's a very hard thing to pin down, but it's definitely happening

[cyriltovena]

@loganmc10 @wallrj A fix is on its way, finally found it. Thank you for your patience.