implement use_incoming_timestamp #2780

yosiasz · 2025-02-20T15:48:45Z

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

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

yosiasz · 2025-02-20T19:14:01Z

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 · 2025-02-20T20:32:21Z

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

smaddock · 2025-02-20T20:53:23Z

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

yosiasz · 2025-02-20T20:58:19Z

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 · 2025-02-21T01:32:02Z

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 · 2025-02-21T04:20:49Z

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 · 2025-02-21T06:47:17Z

@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 · 2025-02-21T15:50:10Z

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.

smaddock · 2025-02-21T21:16:03Z

My issue is resolved. I was proxying through another instance of Alloy and did not have use_incoming_timestamp set on the loki.source.api.

smaddock · 2025-02-23T15:32:02Z

@yosiasz Is this still a valid FR or did we resolve the issues we were having?

yosiasz · 2025-02-23T21:23:34Z

Would be cool if it was implemented then one can bypass stage.timestamp? What do you think?

smaddock · 2025-02-23T22:17:16Z

Where would the “incoming timestamp” come from? If it’s not parsed from the message, wouldn’t that just be the scrape time?

yosiasz added the enhancement New feature or request label Feb 20, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

implement use_incoming_timestamp #2780

implement use_incoming_timestamp #2780

yosiasz commented Feb 20, 2025

yosiasz commented Feb 20, 2025

tonyswu commented Feb 20, 2025

smaddock commented Feb 20, 2025

yosiasz commented Feb 20, 2025 •

edited

Loading

smaddock commented Feb 21, 2025 •

edited

Loading

dehaansa commented Feb 21, 2025

tonyswu commented Feb 21, 2025

smaddock commented Feb 21, 2025

smaddock commented Feb 21, 2025

smaddock commented Feb 23, 2025

yosiasz commented Feb 23, 2025

smaddock commented Feb 23, 2025

implement use_incoming_timestamp #2780

implement use_incoming_timestamp #2780

Comments

yosiasz commented Feb 20, 2025

Request

Use case

yosiasz commented Feb 20, 2025

tonyswu commented Feb 20, 2025

smaddock commented Feb 20, 2025

yosiasz commented Feb 20, 2025 • edited Loading

smaddock commented Feb 21, 2025 • edited Loading

Config

Log

loki.echo Output

loki.write Output (via Grafana)

dehaansa commented Feb 21, 2025

tonyswu commented Feb 21, 2025

smaddock commented Feb 21, 2025

smaddock commented Feb 21, 2025

smaddock commented Feb 23, 2025

yosiasz commented Feb 23, 2025

smaddock commented Feb 23, 2025

yosiasz commented Feb 20, 2025 •

edited

Loading

smaddock commented Feb 21, 2025 •

edited

Loading