Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

implement use_incoming_timestamp #2780

Open
yosiasz opened this issue Feb 20, 2025 · 8 comments
Open

implement use_incoming_timestamp #2780

yosiasz opened this issue Feb 20, 2025 · 8 comments
Labels
enhancement New feature or request

Comments

@yosiasz
Copy link

yosiasz commented Feb 20, 2025

Request

greetings

would really be nice if use_incoming_timestamp could be implemented with stage.*
Currently, there seems to either be a bug or something else where in you cannot use timestamp coming from json logs.

logging {
  level  = "info"
  format = "logfmt"
}

loki.source.file "files" {
  targets    = [
    {__path__ = "/tmp/ts_where_are_you.log"},
  ]
  forward_to = [loki.process.process_logs.receiver]
}

loki.process "process_logs" {

	stage.json {
		expressions = {
			eventMessage = "",
			messageType  = "",
			ts    = "timestamp",
		}
	}

	stage.timestamp {
		source = "ts"
		format = "2006-01-02 15:04:05.999999-0700"
		action_on_failure = "fudge"
	}
	
	stage.template {
		source   = "messageType"
		template = `{{ Replace .Value "Default" "Notice" -1 | ToLower }}`
	}

	stage.labels {
		values = {
			level = "messageType",
		}
	}

	stage.output {
		source = "eventMessage"
	}
	forward_to = [loki.write.local_loki.receiver,loki.echo.debug.receiver]

}

loki.echo "debug" { }

loki.write "local_loki" {
    endpoint {
        url = "http://loki:3100/loki/api/v1/push"
    }
}

{"eventMessage":"This is my log message","messageType":"Default","timestamp":"2025-0-18 06:54:49.663652-0600"}
{"eventMessage":"This is my 2nd log message","messageType":"Notice","timestamp":"2025-02-19 06:55:49.663652-0600"}
{"eventMessage":"This is my 3rd message","messageType":"Default","timestamp":"2025-0-19 01:54:49.663652-0600"}
{"eventMessage":"This is my 4th log message","messageType":"Notice","timestamp":"2025-02-18 22:00:49.663652-0600"}

Thanks!

Use case

because I am not able to capture timestamp from log itself. Gracias
@yosiasz yosiasz added the enhancement New feature or request label Feb 20, 2025
@yosiasz
Copy link
Author

yosiasz commented Feb 20, 2025

same issue existed in promtail?

server:
  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: brodah
    pipeline_stages:
      - json:
          expressions:
            timestamp: ex_timestamp
            eventMessage: eventMessage
            messageType: messageType
      - labels:
          eventMessage:
          app_name:
          messageType:
          ex_timestamp:
      - timestamp:
          source: ex_timestamp
          format: RFC3339
    static_configs:
      - targets:
          - localhost
        labels:
          job: "jsonlogs"
          environment: "shawn.mack"
          __path__: /tmp/ts_where_are_you.log

@tonyswu
Copy link

tonyswu commented Feb 20, 2025

Any example log I can test with? I don't think I've had issue extracting timestamp from logs, JSON or otherwise.

@smaddock
Copy link

I commented with an example on #2393 that I haven’t been able to get working.

@yosiasz
Copy link
Author

yosiasz commented Feb 20, 2025 •
edited
Loading

Any example log I can test with? I don't think I've had issue extracting timestamp from logs, JSON or otherwise.

{"eventMessage":"This is my log message","messageType":"Default","timestamp":"2025-02-18 06:54:49.663652-0600"}
{"eventMessage":"This is my 2nd log message","messageType":"Notice","timestamp":"2025-02-19 06:55:49.663652-0600"}
{"eventMessage":"This is my 3rd message","messageType":"Default","timestamp":"2025-02-19 01:54:49.663652-0600"}
{"eventMessage":"This is my 4th log message","messageType":"Notice","timestamp":"2025-02-18 22:00:49.663652-0600"}

@smaddock
Copy link

smaddock commented Feb 21, 2025 •
edited
Loading

More examples, to show that it's not an issue with parsing the timestamp. (If you turn on debug output you can see the failures noted.) All of the log lines where the timestamps DO parse should have the timestamp of 2025-02-21T00:00:00.000000Z ... note that none of them do.

Config

loki.source.file "test" {
	forward_to = [loki.process.process_logs.receiver]
	targets    = [{"__path__" = "/test.log"}]
}

loki.process "process_logs" {
	forward_to = [loki.echo.debug.receiver, loki.write.default.receiver]

	stage.json {
		expressions = {
			extracted_ts = "timestamp",
		}
	}

	stage.timestamp {
		action_on_failure = "fudge"
		fallback_formats  = [
			"2006-01-02 15:04:05.000000-0700",
			"RFC3339Nano",
		]
		format = "2006-01-02 15:04:05.999999-0700"
		source = "extracted_ts"
	}
}

loki.echo "debug" { }

loki.write "default" {
	endpoint {
		url = "http://loki:3100/loki/api/v1/push"
	}
}

Log

{"message":"This matches my actual logs and parses","timestamp":"2025-02-21 00:00:00.000000-0000"}
{"message":"This fails to parse",                   "timestamp":"2025-02-21 00:00:00.000000-00:00"}
{"message":"This fails to parse",                   "timestamp":"2025-02-21 00:00:00.000000Z"}
{"message":"This parses",                           "timestamp":"2025-02-21 00:00:00.000000000-0000"}
{"message":"This fails to parse",                   "timestamp":"2025-02-21 00:00:00.000000000-00:00"}
{"message":"This fails to parse",                   "timestamp":"2025-02-21 00:00:00.000000000Z"}
{"message":"This fails to parse",                   "timestamp":"2025-02-21T00:00:00.000000-0000"}
{"message":"This parses",                           "timestamp":"2025-02-21T00:00:00.000000-00:00"}
{"message":"This parses",                           "timestamp":"2025-02-21T00:00:00.000000Z"}
{"message":"This fails to parse",                   "timestamp":"2025-02-21T00:00:00.000000000-0000"}
{"message":"This matches RFC3339Nano and parses",   "timestamp":"2025-02-21T00:00:00.000000000-00:00"}
{"message":"This parses",                           "timestamp":"2025-02-21T00:00:00.000000000Z"}

loki.echo Output

ts=2025-02-21T01:26:45.745401Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This matches my actual logs and parses\",\"timestamp\":\"2025-02-21 00:00:00.000000-0000\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.745664Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This fails to parse\",                   \"timestamp\":\"2025-02-21 00:00:00.000000-00:00\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.745824Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This fails to parse\",                   \"timestamp\":\"2025-02-21 00:00:00.000000Z\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.745957Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This parses\",                           \"timestamp\":\"2025-02-21 00:00:00.000000000-0000\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.746017Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This fails to parse\",                   \"timestamp\":\"2025-02-21 00:00:00.000000000-00:00\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.746101Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This fails to parse\",                   \"timestamp\":\"2025-02-21 00:00:00.000000000Z\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.746141Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This fails to parse\",                   \"timestamp\":\"2025-02-21T00:00:00.000000-0000\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.746169Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This parses\",                           \"timestamp\":\"2025-02-21T00:00:00.000000-00:00\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.746196Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This parses\",                           \"timestamp\":\"2025-02-21T00:00:00.000000Z\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.746226Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This fails to parse\",                   \"timestamp\":\"2025-02-21T00:00:00.000000000-0000\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.746256Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This matches RFC3339Nano and parses\",   \"timestamp\":\"2025-02-21T00:00:00.000000000-00:00\"}" labels="{filename=\"/test.log\"}"
ts=2025-02-21T01:26:45.746285Z level=info component_path=/ component_id=loki.echo.debug receiver=loki.echo.debug entry="{\"message\":\"This parses\",                           \"timestamp\":\"2025-02-21T00:00:00.000000000Z\"}" labels="{filename=\"/test.log\"}"

loki.write Output (via Grafana)

2025-02-20 19:26:47.210	{"message":"This parses",                           "timestamp":"2025-02-21T00:00:00.000000000Z"}
2025-02-20 19:26:47.210	{"message":"This matches RFC3339Nano and parses",   "timestamp":"2025-02-21T00:00:00.000000000-00:00"}
2025-02-20 19:26:47.210	{"message":"This fails to parse",                   "timestamp":"2025-02-21T00:00:00.000000000-0000"}
2025-02-20 19:26:47.210	{"message":"This parses",                           "timestamp":"2025-02-21T00:00:00.000000Z"}
2025-02-20 19:26:47.210	{"message":"This parses",                           "timestamp":"2025-02-21T00:00:00.000000-00:00"}
2025-02-20 19:26:47.210	{"message":"This fails to parse",                   "timestamp":"2025-02-21T00:00:00.000000-0000"}
2025-02-20 19:26:47.210	{"message":"This fails to parse",                   "timestamp":"2025-02-21 00:00:00.000000000Z"}
2025-02-20 19:26:47.210	{"message":"This fails to parse",                   "timestamp":"2025-02-21 00:00:00.000000000-00:00"}
2025-02-20 19:26:47.210	{"message":"This parses",                           "timestamp":"2025-02-21 00:00:00.000000000-0000"}
2025-02-20 19:26:47.210	{"message":"This fails to parse",                   "timestamp":"2025-02-21 00:00:00.000000Z"}
2025-02-20 19:26:47.210	{"message":"This fails to parse",                   "timestamp":"2025-02-21 00:00:00.000000-00:00"}
2025-02-20 19:26:47.210	{"message":"This matches my actual logs and parses","timestamp":"2025-02-21 00:00:00.000000-0000"}

@dehaansa
Copy link
Contributor

I tested both the configurations in #2780 (comment) and in the original post, and in both cases I saw proper timestamp parsing.

The loki.echo output is not logging the entry timestamp. The ts field is the time of the logger function call, and the "timestamp" field within the entry is not modified, so it should not change. I modified loki.echo on my local development environment and saw the expected timestamp values (the parsed value. of the JSON timestamp field)

Can you help me understand what causes you to say that the field is not being parsed/used?

@tonyswu
Copy link

tonyswu commented Feb 21, 2025

@dehaansa if you look at the example closely, the timestamp of the four log lines are not in order, and I suspect that might've been the issue.

@smaddock
Copy link

I updated my example to have the timestamps be one second apart, in order, and within a minute of the scrape. Still getting the same results in Grafana. Going to try building #2798 to see if I can test with loki.echo and get different results.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
enhancement New feature or request
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@smaddock @dehaansa @yosiasz @tonyswu