Promtail throws entry out of order

Hi All,

I have recently onboarded promtail for log export via Loki,
promtail is throwing below errors while sending the logs to loki

level=error ts=2021-08-03T08:54:29.108262315Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-03 08:54:28.045712756 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/x_mongos/mongodb.log", host=“eu-west-1a-mongos-01”},"

level=error ts=2021-08-03T08:54:30.394298123Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-03 08:54:29.298853134 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/x_mongos/mongodb.log", host=“eu-west-1a-mongos-00”},"

level=error ts=2021-08-03T08:54:31.589429757Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-03 08:54:30.551714686 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/x_mongos/mongodb.log", host=“eu-west-1a-mongos-01”},"

level=error ts=2021-08-03T08:54:32.89161879Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-03 08:54:31.806009793 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/x_mongos/mongodb.log", host=“MongoS-2”},"

level=error ts=2021-08-03T08:54:36.090443113Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-03 08:54:33.060058347 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/x_mongos/mongodb.log", host=“MongoS-2”},"

level=error ts=2021-08-03T08:54:37.197457106Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-03 08:54:34.313817414 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/x_mongos/mongodb.log", host=“MongoS-1”},"

level=error ts=2021-08-03T08:54:38.391665969Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-03 08:54:37.32240859 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/x_mongos/mongodb.log", host=“eu-west-1a-mongos-01”},"

Could you send me any reference to fix these errs.

Thanks in advance,
Regards,
Naveen

Hi

Loki requires entries in the same stream to be in order:

This requirement will be lifted in the coming months, but for now you either need to ensure your logs are sent in order, or to set the action_on_failure to “fudge”:

Thanks Danny for quick response with the reference links.

As advised, i made the stream unique by adding extra label IP to stream, and also i have added the timestamp stage as below:
server:
http_listen_port: 9080
grpc_listen_port: 0

positions:
filename: /tmp/positions.yaml

client:
url: http://prometheus.qa.abc.info:3100/api/prom/push

scrape_configs:

  • job_name: mongos
    ec2_sd_configs:
    • region: eu-west-1
      port: 9080
    • region: eu-west-2
      port: 9080
    • region: eu-central-1
      port: 9080
      relabel_configs:
    • source_labels: [__meta_ec2_tag_Component]
      regex: ‘MongoS’
      action: keep
    • source_labels: [__meta_ec2_tag_Component]
      target_label: component
    • source_labels: [__meta_ec2_private_ip]
      target_label: ip
    • source_labels: [__meta_ec2_tag_Name]
      target_label: host
      action: replace
    • action: replace
      replacement: /var/log/mongodb/abcqa_mongos/*.log
      target_label: path
      pipeline_stages:
    • match:
      selector: ‘{component=“MongoS”}’
      stages:
      • timestamp:
        format: RFC3339Nano
        source: timestamp
        action_on_failure: skip

Yet, i could see the same errors:

level=error ts=2021-08-04T02:31:20.949072467Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-04 02:31:19.855020736 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/abcqa_mongos/mongodb.log", host=“MongoS-1”, ip=“100.15.4.1152”},"

level=error ts=2021-08-04T02:31:27.149881272Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-04 02:31:26.11992693 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/abcqa_mongos/mongodb.log", host=“eu-west-1a-mongos-00”, ip=“101.15.156.1139”},"

level=error ts=2021-08-04T02:31:28.45046003Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-04 02:31:27.371254099 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/abcqa_mongos/mongodb.log", host=“eu-west-1a-mongos-00”, ip=“101.15.156.1139”},"

level=error ts=2021-08-04T02:31:33.945877242Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-04 02:31:32.886411298 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/abcqa_mongos/mongodb.log", host=“MongoS-2”, ip=“101.15.4.2247”},"

level=error ts=2021-08-04T02:31:35.149798738Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-04 02:31:34.140259905 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/abcqa_mongos/mongodb.log", host=“MongoS-2”, ip=“101.15.4.2247”},"

level=error ts=2021-08-04T02:31:36.449153672Z caller=client.go:355 component=client host=prometheus.qa.abc.info:3100 msg=“final error sending batch” status=400 error=“server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-08-04 02:31:35.393918736 +0000 UTC ignored, reason: ‘entry out of order’ for stream: {component=“MongoS”, filename=”/var/log/mongodb/abcqa_mongos/mongodb.log", host=“eu-west-1a-mongos-00”, ip=“101.15.156.1139”},"

I have promtail deployed as a docker container on 5 MongoS hosts with above config, and as advised i have added the timestamp stage action_on_failure: skip

Appreciate your time on replying to this.

Thanks,
Naveen.

Hi Naveen

As advised, i made the stream unique by adding extra label IP to stream

Note I didn’t advise this; adding another label won’t solve the issue as it’ll just create another stream in which this error could occur.

as advised i have added the timestamp stage action_on_failure: skip

I actually advised:

set the action_on_failure to “fudge”

But thinking about this some more, you should actually drop your timestamp field and let Promtail generate the timestamp on scrape, since your log source is not producing logs in order it seems.

Thanks Danny, if i read correctly, fudge is the default setting for action_on_failure, i will give a try set this and see how it reacts.

Hi Danny,

A quick question from your reply, what do you mean
This requirement will be lifted in the coming months Is the requirement for logs that should be in increasing time order per stream will be gone?

More details here:

1 Like

Thanks Danny, appreciate it, am still not able to fix it. i will try upgrade loki and see if its of any luck.
am pushing mongdb logs to loki via promtail, am pretty sure, mongodb logs are always in increasing order. i read some where, each server should have its own independent stream, but mongos runs in a cluster and they all will send same stream of data, its tough to configure each node with independent stream.
i will update here, if some how i will get it fixed for sure.
Thanks for reference.

1 Like