Time in loki is scrape time not log time

[craftzneko]

What's wrong?

Setting this up for first time so probably missing something obvious but i cant get any logs to use the time in the log not the time scrapped. In grafana explore they appear like this

In alloy i have it configured like this

loki.process "add_static_label" {
      forward_to = [loki.write.grafana_loki.receiver]

  stage.regex {
    expression = "(?P<time>\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2},\\d{3}) \\[(?P<code>\\d+)\\] (?P<type>INFO|ERROR) (?P<message>.+)"
  }

  stage.replace {
  source = "time"
  expression = "(?P<time>\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2}),(\\d{3})"
  replace = "{{ regexReplaceAll \",\" .time \".\" }}"
}

  stage.static_labels {
      values = {
        logs = "expressapi",
        env = "production",
      }
  }

  stage.timestamp {
    source = "time"
    location = "Europe/London"
    format = "2006-01-02 15:04:05.000"
}

my log files appear like this

2024-07-04 00:00:17,530 [4] INFO Test log entry

The timestamp is first set in the map as time then i replace the comma for a full stop and save it back as time, have i missed something here. The event log seems fine for entries

ts=2024-07-04T14:50:21.3669977Z level=debug msg="extracted data debug in replace stage" component_path=/ component_id=loki.process.add_static_label component=stage type=replace "extracted data"="map[code:18 filename:C:\test\logs\XpressRegisterChecker_20240212.log message:Test Log entry\r time:2024-02-12 05:51:01.317 type:INFO]"

Steps to reproduce

As above

System information

No response

Software version

No response

Configuration

No response

Logs

No response

[hainenber]

Looks like you're trying to have Loki ingesting out-of-order and older logs. Maybe this guide from Loki can help?

[craftzneko]

I am ingesting older logs but after reading that guide it doesnt seem to be a problem doing this by default. As far as i can see my log timestamps have a comma for milliseconds so i use a replace to change that to a full stop, then set a timestamp block. It appears that this doesnt change the timestamp

[craftzneko]

It would help if there was a way to see what is actually happening at each stage but the client http://localhost:12345/component/ just repeats whats in the config file, it doesnt actually show me how it processes each stage which would actually be usefull. Live debugging when turned on following the guide doesnt work the service just wont start.

[hainenber]

Yep, was premature of me suggesting issue with out-of-order logs since they would be rejected by Loki.

[craftzneko]

@hainenber no worries, was something i was not aware of so interesting read anyway

[craftzneko]

Ok some further info. I cleared Loki and Alloy and started fresh with a single log file containing a hundred entries. The log entries that appear do not have the correct timestamp applied. I do see an event log error in windows which states

ts=2024-07-12T09:52:56.9713188Z level=error msg="final error sending batch" component_path=/ component_id=loki.write.grafana_loki component=client host=task02.cardiff.gov.uk:3100 status=400 tenant="" error="server returned HTTP status 400 Bad Request (400): entry with timestamp 2024-02-14 00:00:20.549 +0000 UTC ignored, reason: 'entry too far behind, oldest acceptable timestamp is: 2024-07-12T08:52:55Z',"

However i also have this in my loki config

  reject_old_samples: false
  reject_old_samples_max_age: 43800h

So why does loki think it can only ingest entries from up to an hour ago?

My logs are ordered by time, i am not sure if i need to do something with my alloy config to make sure they are passed to loki in time order, seems that grafana make both so I would hope this is by default.

A sample of the logs

  2024-02-14 00:00:20,549 [19] INFO System.Net.Http.HttpClient.signed.LogicalHandler - End processing HTTP request after 34.6075ms - 400
2024-02-14 00:00:20,549 [19] WARN HTTP Status Code: 400
2024-02-14 00:00:20,549 [19] WARN FAIL - {"timestamp":"2024-02-14T00:00:20.542Z","status":400,"error":"Bad Request","message":"Validation failed for object='registerCheckResultRequest'. Error count: 1","validationErrors":["Error on field 'registerCheckMatches[0]': rejected value [], size must be between 1 and 10"]}
2024-02-14 00:00:20,549 [19] INFO XpressRegisterChecker - Adding UnsuccessfulPostResponse: f88ae707-41b4-41c6-8a70-69ba6f019955

It does show that these logs have the SAME timestamp as they occurred at the same time, could that be the problem? If so how am i meant to handle this

[github-actions]

This issue has not had any activity in the past 30 days, so the needs-attention label has been added to it.
If the opened issue is a bug, check to see if a newer release fixed your issue. If it is no longer relevant, please feel free to close this issue.
The needs-attention label signals to maintainers that something has fallen through the cracks. No action is needed by you; your issue will be kept open and you do not have to respond to this comment. The label will be removed the next time this job runs if there is new activity.
Thank you for your contributions!