Parsing Epoch/Unix timestamp in Loki/Promtail

Grafana Loki
1

I’m trying to parse a log file containing Unix timestamps with Promtail, but am running into the following error:

level=info ts=2021-06-18T14:10:00.26531019Z caller=tailer.go:125 component=tailer msg=“tail routine: started” path=/path/to/testlog

ts=2021-06-18T14:10:00.265463196Z caller=log.go:124 level=info msg=“Seeked /path/to/testlog - &{Offset:0 Whence:0}”

level=debug ts=2021-06-18T14:10:00.266096682Z caller=timestamp.go:196 component=file_pipeline msg=“failed to parse time” err=“parsing time “1623180831.246”: month out of range” format=1136235845.000 value=1623180831.246

My config is as follows:

scrape_configs:

  • job_name: akamai
    static_configs:
    • labels:
      job: logs
      path: /path/to/testlog
      targets: localhost
      pipeline_stages:
    • match:
      selector: ‘{job=“logs”}’
      stages:
      • regex:
        expression: “(?s)^(?P\d{10}.{4})”
      • timestamp:
        source: time
        format: ‘1136235845.000’

I’ve tried multiple iterations of regex and config parameters and this combination appears to get me the closest, but I’ve run out of ideas. Golang appears to require Jan 2, 2006 at 3:04pm (MST) as a reference time, which I’ve converted to epoch with no luck.

Below is a sample log line for reference:

1623180831.246 192.168.0.1 POST TLSv1.2 /domain.com/java/somepath/anotherpath/en/somemodule/someservice.asmx 200 75201 76955 75201 - 5568 “-” “Java/1.8.0_281” “-” “domain.com” “text/xml” 0 153 69 “306dd6ab” - “miss” “origin” 1 1 192.168.0.1

2

Hi @emilechaiban.
The timestamp format you are using in your config looks bit weird, From the docs it should be one of the following.

# Determines how to parse the time string. Can use
# pre-defined formats by name: [ANSIC UnixDate RubyDate RFC822
# RFC822Z RFC850 RFC1123 RFC1123Z RFC3339 RFC3339Nano Unix
# UnixMs UnixUs UnixNs].
  format: <string>

From the log entries you shared, 1623180831.246 should be able to be parsed by Unix format. curious you tried that already?

3

Thanks for the reply. Yes, I did try that first actually. Below is the promtail debug output when using the following config.

I have no idea why it’s saying the entry is out of the order. The test log file I’m using contains only that single line and there are no other streams configured.

  • regex:
    expression: “(?s)^(?P\w{1,10}.\w{1,3})”
    - timestamp:
    source: time
    format: Unix

level=debug ts=2021-06-21T14:12:38.92202484Z caller=manager.go:195 component=discovery msg=“Starting provider” provider=static/0 subs=[akamai]

level=debug ts=2021-06-21T14:12:38.922363585Z caller=manager.go:213 component=discovery msg=“Discoverer channel closed” provider=static/0

level=info ts=2021-06-21T14:12:38.922662685Z caller=server.go:229 http=[::]:9080 grpc=[::]:41573 msg=“server listening on addresses”

level=info ts=2021-06-21T14:12:38.923093015Z caller=main.go:112 msg=“Starting Promtail” version="(version=2.2.1, branch=HEAD, revision=babea82e)"

level=debug ts=2021-06-21T14:12:43.922401114Z caller=filetargetmanager.go:200 msg=“new target” labels="{address=“localhost”}"

level=info ts=2021-06-21T14:12:43.922596842Z caller=filetargetmanager.go:254 msg=“Adding target” key="{job=“testlogs”, targets=“localhost”}"

level=debug ts=2021-06-21T14:12:43.931611874Z caller=filetarget.go:249 msg=“watching new directory” directory=/path/to/testlogs

level=debug ts=2021-06-21T14:12:43.931752535Z caller=filetarget.go:283 msg=“tailing new file” filename=/path/to/testlog

level=info ts=2021-06-21T14:12:43.93321626Z caller=tailer.go:125 component=tailer msg=“tail routine: started” path=/path/to/testlog

ts=2021-06-21T14:12:43.933389812Z caller=log.go:124 level=info msg=“Seeked /path/to/testlog - &{Offset:0 Whence:0}”

level=debug ts=2021-06-21T14:12:43.934859994Z caller=regex.go:120 component=file_pipeline component=stage type=regex msg=“regex did not match” input= regex=(?s)^(?P\d{10}.{4})

level=debug ts=2021-06-21T14:12:43.934993351Z caller=timestamp.go:176 component=file_pipeline msg=“extracted data did not contain a timestamp”

level=error ts=2021-06-21T14:12:45.02712119Z caller=client.go:334 component=client host=localhost:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-06-08 19:33:51.246 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {filename=”/path/to/testlog", job=“testlogs”, targets=“localhost”},"

4

Thanks for more details :slight_smile:

I think I found the issue. I guess there may be two problems with your promtail config.

  1. The regex expression you are using ((?s)^(?P\w{1,10}.\w{1,3})) doesn’t contain time to extract it. So that you can use it in your timestamp stage with source time.

The right expression for your log entries would be something similar to "^(?s)(?P<time>\\S+?) (?P<ip>\\S+?) (?P<content>.*)$" (notice we extract time from your log entry as named group)

  1. There may be indentation error with your pipeline_stages. regexp and timestamp should be on the same level and those stages should be direct child of pipeline_stages (in your first config I see you put it under match.stages which is wrong).

Also another interesting thing is you can validate your config via promtail's flag -dry-run and -stdin to check your configs + log entries without actually sending to Loki servers.

Example (with your log entries)

my promtail.yaml config

  http_listen_port: 9080
  grpc_listen_port: 0

positions:
  filename: /tmp/positions.yaml

clients:
  - url: http://localhost:3100/loki/api/v1/push

scrape_configs:
- job_name: system
  pipeline_stages:
    - regex:
        expression: "^(?s)(?P<time>\\S+?) (?P<ip>\\S+?) (?P<content>.*)$"
    - timestamp:
        source: time
        format: Unix
  static_configs:
  - targets:
      - localhost
    labels:
      job: varlogs
      __path__: /var/log/*log

You log entries

-bash5.0$ /bin/cat logs.txt
1623180831.246 192.168.0.1 POST TLSv1.2 /domain.com/java/somepath/anotherpath/en/somemodule/someservice.asmx 200 75201 76955 75201 - 5568 “-” “Java/1.8.0_281” “-” “domain.com” “text/xml” 0 153 69 “306dd6ab” - “miss” “origin” 1 1 192.168.0.1

Now you can check your timestamp parsing via

-bash5.0$ cat logs.txt | ./clients/cmd/promtail/promtail -stdin -dry-run -config.file ./clients/cmd/promtail/promtail-local-config.yaml -log.level=error
Clients configured:
----------------------
url: http://localhost:3100/loki/api/v1/push
batchwait: 1s
batchsize: 1048576
follow_redirects: false
backoff_config:
  min_period: 500ms
  max_period: 5m0s
  max_retries: 10
timeout: 10s
tenant_id: ""

2021-06-08T21:33:51+0200	{__path__="/var/log/*log", job="varlogs"}	1623180831.246 192.168.0.1 POST TLSv1.2 /domain.com/java/somepath/anotherpath/en/somemodule/someservice.asmx 200 75201 76955 75201 - 5568 “-” “Java/1.8.0_281” “-” “domain.com” “text/xml” 0 153 69 “306dd6ab” - “miss” “origin” 1 1 192.168.0.1

You see your timestamp 1623180831.246 is parsed correctly as 2021-06-08T21:33:51+0200.

Hope this helps :slight_smile:

5

Thank you! This gets me much closer. You were right, the indentation in my config was incorrect. Below is what my current config looks like. Note that I modified the regex slightly.

scrape_configs:
- job_name: testlog
  pipeline_stages:
    - regex:
        expression: '^(?s)(?P<time>\S+?)\s+(?P<ip>\S+?)\s+(?P<content>.*?)$'
    - timestamp:
        source: time
        format: Unix
  static_configs:
  - targets:
      - localhost
    labels:
      job: testlog
      __path__: /path/to/testlog

And below is the dry-run output, correctly parsing the timestamp:

user@server: promtail$ cat /path/to/testlog3 | ./promtail-linux-amd64 -stdin -dry-run -config.file config.yml -log.level=error
Clients configured:
----------------------
url: http://localhost:3100/loki/api/v1/push
batchwait: 1s
batchsize: 1048576
backoff_config:
  min_period: 500ms
  max_period: 5m0s
  max_retries: 10
timeout: 10s
tenant_id: ""

2021-06-08T19:33:53	{__path__="/path/to/testlog", job="testlog"}	1623180833.246  192.168.0.1 POST    TLSv1.2 /domain.com/java/somepath/anotherpath/en/somemodule/someservice.asmx   200     75201   76955   75201   -       5568    "-"     "Java/1.8.0_281"        "-"     "domain.com"       "text/xml"      0       153     69      "306dd6ab"      -       "miss"  "origin"        1       1       192.168.0.1

However, when I try and run promtail normally to send the output to Loki, I get the following error:

user@server: promtail$ ./promtail-linux-amd64 -config.file config.yml -log.level=debug
level=debug ts=2021-06-22T13:44:56.220217215Z caller=manager.go:195 component=discovery msg="Starting provider" provider=static/0 subs=[akamai]
level=debug ts=2021-06-22T13:44:56.220840763Z caller=manager.go:213 component=discovery msg="Discoverer channel closed" provider=static/0
level=info ts=2021-06-22T13:44:56.221195206Z caller=server.go:229 http=[::]:9080 grpc=[::]:33180 msg="server listening on addresses"
level=info ts=2021-06-22T13:44:56.221634417Z caller=main.go:112 msg="Starting Promtail" version="(version=2.2.1, branch=HEAD, revision=babea82e)"
level=debug ts=2021-06-22T13:45:01.220737727Z caller=filetargetmanager.go:200 msg="new target" labels="{__address__=\"localhost\"}"
level=info ts=2021-06-22T13:45:01.22091242Z caller=filetargetmanager.go:254 msg="Adding target" key="{job=\"testlog\"}"
level=debug ts=2021-06-22T13:45:01.222368146Z caller=filetarget.go:249 msg="watching new directory" directory=/path/to
level=debug ts=2021-06-22T13:45:01.222481723Z caller=filetarget.go:283 msg="tailing new file" filename=/path/to/testlog
level=info ts=2021-06-22T13:45:01.223837845Z caller=tailer.go:125 component=tailer msg="tail routine: started" path=/path/to/testlog
ts=2021-06-22T13:45:01.224043881Z caller=log.go:124 level=info msg="Seeked /path/to/testlog - &{Offset:0 Whence:0}"
level=debug ts=2021-06-22T13:45:01.227060234Z caller=regex.go:120 component=file_pipeline component=stage type=regex msg="regex did not match" input= regex=^(?s)(?P<time>\S+?)\s+(?P<ip>\S+?)\s+(?P<content>.*?)$
level=debug ts=2021-06-22T13:45:01.227166565Z caller=timestamp.go:176 component=file_pipeline msg="extracted data did not contain a timestamp"
level=error ts=2021-06-22T13:45:02.326382001Z caller=client.go:334 component=client host=localhost:3100 msg="final error sending batch" status=400 error="server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-06-08 19:33:51.246 +0000 UTC ignored, reason: 'entry out of order' for stream: {filename=\"/path/to/testlog\", job=\"testlog\"},"

Any ideas as to why this is happening? Again, really appreciate the help.

6

Clearing out Loki directories and the positions file fixed the issue and promtail is no longer throwing any errors.

1 Like
7

@emilechaiban Glad it worked :slight_smile:
Just a small note about the last error message I see in your logs.

error="server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-06-08 19:33:51.246 +0000 UTC ignored, reason: 'entry out of order' for stream: {filename=\"/path/to/testlog\", job=\"testlog\"},"

This happens, when you send logs (with same label set) but with older timestamp. Loki doesn’t support it and it rejects it.

More information here Best practices | Grafana Labs

If you think the issue is fixed, can you mark it as resolved? Thanks :slight_smile:

8

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.