Prometheus keep restarting following WAL replay completion

[indrajithgihan]

What did you do?
We have been running prom/prometheus:v2.29.2 as a docker container and after running it for few hours it started keep restarting. Attached logs for the same. Need to know how to get rid of this issue.

What did you expect to see?
Prometheus container up and running without any restarts

What did you see instead? Under which circumstances?
Prometheus container keep restarting

Environment
prometheus running as a docker container
NAME="Red Hat Enterprise Linux Server"
VERSION="7.8 (Maipo)"

• System information:

  Linux 3.10.0-1127.19.1.el7.x86_64 x86_64

• Prometheus version:

  2.29.2

• Logs:

level=info ts=2021-09-21T06:01:22.399Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3008 maxSegment=3040
level=info ts=2021-09-21T06:01:22.399Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3009 maxSegment=3040
level=info ts=2021-09-21T06:01:22.399Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3010 maxSegment=3040
level=info ts=2021-09-21T06:01:22.400Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3011 maxSegment=3040
level=info ts=2021-09-21T06:01:22.400Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3012 maxSegment=3040
level=info ts=2021-09-21T06:01:22.400Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3013 maxSegment=3040
level=info ts=2021-09-21T06:01:22.400Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3014 maxSegment=3040
level=info ts=2021-09-21T06:01:22.400Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3015 maxSegment=3040
level=info ts=2021-09-21T06:01:22.401Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3016 maxSegment=3040
level=info ts=2021-09-21T06:01:22.401Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3017 maxSegment=3040
level=info ts=2021-09-21T06:01:22.401Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3018 maxSegment=3040
level=info ts=2021-09-21T06:01:22.402Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3019 maxSegment=3040
level=info ts=2021-09-21T06:01:22.402Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3020 maxSegment=3040
level=info ts=2021-09-21T06:01:22.402Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3021 maxSegment=3040
level=info ts=2021-09-21T06:01:22.402Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3022 maxSegment=3040
level=info ts=2021-09-21T06:01:22.402Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3023 maxSegment=3040
level=info ts=2021-09-21T06:01:22.403Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3024 maxSegment=3040
level=info ts=2021-09-21T06:01:22.403Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3025 maxSegment=3040
level=info ts=2021-09-21T06:01:22.403Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3026 maxSegment=3040
level=info ts=2021-09-21T06:01:22.403Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3027 maxSegment=3040
level=info ts=2021-09-21T06:01:22.404Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3028 maxSegment=3040
level=info ts=2021-09-21T06:01:22.404Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3029 maxSegment=3040
level=info ts=2021-09-21T06:01:22.404Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3030 maxSegment=3040
level=info ts=2021-09-21T06:01:22.405Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3031 maxSegment=3040
level=info ts=2021-09-21T06:01:22.405Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3032 maxSegment=3040
level=info ts=2021-09-21T06:01:22.405Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3033 maxSegment=3040
level=info ts=2021-09-21T06:01:22.405Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3034 maxSegment=3040
level=info ts=2021-09-21T06:01:22.405Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3035 maxSegment=3040
level=info ts=2021-09-21T06:01:22.406Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3036 maxSegment=3040
level=info ts=2021-09-21T06:01:22.406Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3037 maxSegment=3040
level=info ts=2021-09-21T06:01:22.406Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3038 maxSegment=3040
level=info ts=2021-09-21T06:01:22.407Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3039 maxSegment=3040
level=info ts=2021-09-21T06:01:22.407Z caller=head.go:893 component=tsdb msg="WAL segment loaded" segment=3040 maxSegment=3040
level=info ts=2021-09-21T06:01:22.407Z caller=head.go:899 component=tsdb msg="WAL replay completed" checkpoint_replay_duration=15.221258451s wal_replay_duration=3m15.211752204s total_replay_duration=3m34.548390307s
{"log":"level=info ts=2021-09-21T06:01:22.407Z caller=head.go:899 component=tsdb msg=\"WAL replay completed\" checkpoint_replay_duration=15.449597079s wal_replay_duration=3m20.133755183s total_replay_duration=3m39.549256163s\n","stream":"stderr","time":"2021-09-21T06:01:24.179210884Z"}
{"log":"level=info ts=2021-09-21T06:01:31.106Z caller=main.go:428 msg=\"Starting Prometheus\" version=\"(version=2.29.2, branch=HEAD, revision=752c4f11ae86effa9a46f017f2feb66730c67ed8)\"\n","stream":"stderr","time":"2021-09-21T06:01:31.106747607Z"}
{"log":"level=info ts=2021-09-21T06:01:31.106Z caller=main.go:433 build_context=\"(go=go1.16.7, user=root@61bcc9848ade, date=20210827-09:44:22)\"\n","stream":"stderr","time":"2021-09-21T06:01:31.106785268Z"}
{"log":"level=info ts=2021-09-21T06:01:31.106Z caller=main.go:434 host_details=\"(Linux 3.10.0-1127.19.1.el7.x86_64 #1 SMP Tue Aug 11 19:12:04 EDT 2020 x86_64 28a39ca5f5ec (none))\"\n","stream":"stderr","time":"2021-09-21T06:01:31.106793212Z"}
{"log":"level=info ts=2021-09-21T06:01:31.106Z caller=main.go:435 fd_limits=\"(soft=65536, hard=65536)\"\n","stream":"stderr","time":"2021-09-21T06:01:31.106799401Z"}
{"log":"level=info ts=2021-09-21T06:01:31.106Z caller=main.go:436 vm_limits=\"(soft=unlimited, hard=unlimited)\"\n","stream":"stderr","time":"2021-09-21T06:01:31.106805132Z"}
{"log":"level=info ts=2021-09-21T06:01:31.109Z caller=web.go:541 component=web msg=\"Start listening for connections\" address=0.0.0.0:9090\n","stream":"stderr","time":"2021-09-21T06:01:31.109603007Z"}
{"log":"level=info ts=2021-09-21T06:01:31.116Z caller=main.go:812 msg=\"Starting TSDB ...\"\n","stream":"stderr","time":"2021-09-21T06:01:31.116284554Z"}
{"log":"level=info ts=2021-09-21T06:01:31.117Z caller=tls_config.go:191 component=web msg=\"TLS is disabled.\" http2=false\n","stream":"stderr","time":"2021-09-21T06:01:31.117678342Z"}
{"log":"level=info ts=2021-09-21T06:01:31.117Z caller=repair.go:57 component=tsdb msg=\"Found healthy block\" mint=1631268667737 maxt=1631275200000 ulid=01FF7XAKJ6XQSEWKS7JW6P7QH9\n","stream":"stderr","time":"2021-09-21T06:01:31.117694685Z"}
{"log":"level=info ts=2021-09-21T06:01:31.118Z caller=repair.go:57 component=tsdb msg=\"Found healthy block\" mint=1631275200002 maxt=1631340000000 ulid=01FFA88Q9HEG5672GZEJTV2Q2Q\n","stream":"stderr","time":"2021-09-21T06:01:31.118345848Z"}
{"log":"level=info ts=2021-09-21T06:01:31.118Z caller=repair.go:57 component=tsdb msg=\"Found healthy block\" mint=1631340000005 maxt=1631404800000 ulid=01FFC62DW3772S1KRFVB3671W0\n","stream":"stderr","time":"2021-09-21T06:01:31.118987727Z"}
{"log":"level=info ts=2021-09-21T06:01:31.119Z caller=repair.go:57 component=tsdb msg=\"Found healthy block\" mint=1631404800000 maxt=1631469600000 ulid=01FFDX1HS61K2EGB2M37370VWR\n","stream":"stderr","time":"2021-09-21T06:01:31.119761767Z"}
{"log":"level=info ts=2021-09-21T06:01:31.120Z caller=repair.go:57 component=tsdb msg=\"Found healthy block\" mint=1631469600001 maxt=1631534400000 

[roidelapluie]

is that where the docker logs end? do you see an Out of Memory error in dmesg? I assume that prometheus is probably killed because you do not have enough memory on the system.

[indrajithgihan]

prometheus.zip
The log ends with "level=info ts=2021-09-21T06:01:22.407Z caller=head.go:899 component=tsdb msg="WAL replay completed" checkpoint_replay_duration=15.221258451s wal_replay_duration=3m15.211752204s total_replay_duration=3m34.548390307s" and then started with {"log":"level=info ts=2021-09-20T15:56:31.106Z caller=main.go:428 msg="Starting Prometheus" version="(version=2.29.2, branch=HEAD, revision=752c4f11ae86effa9a46f017f2feb66730c67ed8)"\n","stream":"stderr","time":"2021-09-20T15:56:31.106747607Z"}. This keep happening continuously. I don't see OOM Killed when the restart happens and the container is not excessively using memory. It is consuming around 8GB of memory. I suspect that this is due to a corruption of a file. Problem is this keeps happening more often. Attached complete log file.

[roidelapluie]

Did you check the docker daemon logs as well? Can you provide us a screenshot of this dashboard https://grafana.com/grafana/dashboards/12054 when restart happens?

[roidelapluie]

@codesome do you have an idea of what is going on here?

[codesome]

Any file corruption should have been logged, and it would not cause a restart. Looks like a OOM kill to me.

[indrajithgihan]

I have applied the grafana dashboard and will share the finding when reoccur. The reason why I suspect that this is due to file corruption is that sometime the docker container is able to be running when I remove wal directory from the Prometheus data mount and restart the docker.

[roidelapluie]

do you have another prometheus monitoring that one? otherwise you will not get the metrics upon restart