Metrics stuck / deadlock on some kernel versions

[nevgin]

Host operating system: output of uname -a

Linux host 5.4.211-1.el8.elrepo.x86_64 #1 SMP Wed Aug 24 08:50:28 EDT 2022 x86_64 x86_64 x86_64 GNU/Linux

node_exporter version: output of node_exporter --version

node_exporter, version 1.4.0 (branch: HEAD, revision: 7da1321)
build user: root@83d90983e89c
build date: 20220926-12:32:56
go version: go1.19.1
platform: linux/amd64

node_exporter command line flags

--no-collector.cpufreq --no-collector.systemd --collector.sockstat --no-collector.logind --collector.textfile.directory=/var/lib/prometheus

Are you running node_exporter in Docker?

No

What did you do that produced an error?

after 2-24 hour, randomized

What did you expect to see?

Not stuck node_exporter

What did you see instead?

Stuck node exporter after random time.
After run strace -f -p pgrep node_exporter
node exporter unstuck
Out pprof:
debug1.txt
debug2.txt

Responce > 1 minute

[discordianfish]

So it stops responding to requests?
Can you please attach the log?

[nevgin]

So.
node_exporter.tar.gz

[discordianfish]

Have you tried using e.g curl to retrieve the metrics? Might be an issue on the networking/prometheus server side.
There is also an unexpected number of irq/idle counter jumps..

[stephrdev]

I can confirm the same issue, even a curl running against localhost:9100 is hanging until the exporter is restarted. After some undefined time the exporter responds again.

I noticed this first after a recent kernel update but I'm not able to specify the exact kernel version when the issues came up first. I can also confirm that this happend with a quite old node exporter version and also with the latest 1.4.0.

After trying to find out more about the issue using log.level=debug I can say that the log didn't showed any helpful information.

[nevgin]

Yes of course

[nevgin]

Issue same on all system with kernel version 5.4.211, 5.4.212

[ventifus]

Is it intentional that the system is getting scraped 24 times per second? 60 seconds to scrape /metrics is unusually long probably caused by kernel-level rate limits. It would mean you have 1440 concurrent scrapes at any given time. I usually see scrape intervals of 10 or 15 seconds.

egrep 'ts=2022-10-05T13:47:59.*name=uname' ~/Downloads/node_exporter/tmp/node_exporter Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.349Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=2.9704e-05
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.355Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.004351489
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.357Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.000320838
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.360Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.00315381
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.364Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.009627007
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.354Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.002329661
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.367Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.00543363
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.370Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.008927494
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.372Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.011827477
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.376Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.014796259
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.380Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=6.984e-06
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.381Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=4.1388e-05
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.381Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=4.2767e-05
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.383Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.028515173
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.389Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.000264836
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.389Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=1.9946e-05
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.373Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.000142291
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.386Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.000344837
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.397Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.017266906
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.398Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=1.0905e-05
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.401Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.000125761
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.404Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.000226375
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.410Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=7.172e-06
Oct 05 16:47:59 host.net node_exporter[2947760]: ts=2022-10-05T13:47:59.415Z caller=collector.go:173 level=debug msg="collector succeeded" name=uname duration_seconds=0.019929624

[nevgin]

Metrics are collected by the exporter_exporter. He stupidly scrapes metrics, regardless of whether he gave the metrics or not. Here is the moment at which the node_exporter began to respond and fulfilled all requests.

[nevgin]

Scrapping every 5seconds.
Log:
node_exporter.log

[discordianfish]

Can you attach the binary pprof profiles? e.g:

for p in goroutine block mutex profile; do
  curl -O localhost:9100/debug/pprof/$p
done

[nevgin]

Yes of course.
out.tar.gz

[nadavgolden]

Any news on this?

[discordianfish]

@nevgin This is from when it was stuck? Do you use the systemd collector? If so, can you try disabling it and see if it still gets stuck?

[nevgin]

I turned off all collectors that debug showed slow. The effect was insignificant - returned
While I live with a restart in the cron node_exporter

[nevgin]

Go profiles with disabled systemd, logind:
out(1).tar.gz

[tyrken]

Similar issue on Amazon Linux 2 5.4.214-120 whereas 5.4.209-116 works - just hangs with nothing in logs & not responding to probes/healthchecks, so gets restarted by Kubernetes. Hence can't debug much either...

[lluczaj]

We have exactly the same issue. After upgrading to 5.4.214-120 we suffer many random node-exporter restarts in Kubernetes (Amazon Linux 2). Nothing suspicious in logs/metrics, we just see the following message in pod description:

Readiness probe failed: Get "http://XXXX:9100/": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
Liveness probe failed: Get "http://XXXX:9100/": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

It worked without any problems on kernel-5.4.209-116

[joaosilva15]

Also happening to us. We changed from Amazon Linux 2 version kernel-5.4.209-116 to 5.4.217-126 and we see the same behaviour

[psyhomb]

Anything new on this, we have exactly the same problem on Amazon Linux 2 kernel version: 5.4.217-126.408.amzn2.x86_64?

[discordianfish]

It might be dbus related indeed but tbh, since I can only work on this in my free time I can't say when I find time to get to the root of it:

It would help if we could reproduce this reliably, e.g in a VM.

[lluczaj]

It seems that there are plenty of issues with Kernel 5.4.214-120 and higher. For those of you who use EKS and Amazon AMIs - they decided to pin to the 5.4.209-116.367 because of some instability until they discover what exactly is the problem.

awslabs/amazon-eks-ami#1072

[psyhomb]

I can confirm that with an old kernel version (5.4.209-116.367.amzn2.x86_64) in the latest EKS 1.22 AMI, everything is working without issues.

[paragor]

has reproduced locally on ubuntu (vagrant box https://app.vagrantup.com/bento/boxes/ubuntu-20.04/versions/202206.03.0 with needed kernel https://kernel.ubuntu.com/~kernel-ppa/mainline/v5.4.214/amd64/)

# uname -a
Linux vagrant 5.4.214-0504214-generic #202209200739 SMP Tue Sep 20 11:46:49 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux 
# uptime
13:15:18 up  5:47,  5 users,  load average: 0.18, 0.35, 0.52

command:

node_exporter --collector.disable-defaults --web.max-requests=0 --collector.netclass

and it need to start load test via vegeta (vegeta)

echo 'GET http://localhost:9100/metrics' |  vegeta attack -rate 50 | vegeta report -every 1s

bug will show up after ~1-2 minutes

cant reproduce without collector.netclass (cmd node_exporter --web.max-requests=0 --no-collector.netclass) in 20 minutes test

so i think bug is near collector.netclass

[paragor]

reproduce script

main.go

package main

import (
	"fmt"
	"github.com/prometheus/procfs/sysfs"
	"log"
	"net/http"
)

func main() {

	fs, err := sysfs.NewFS("/sys")
	if err != nil {
		panic(err)
	}
	netDevices, err := fs.NetClassDevices()

	http.HandleFunc("/", func(writer http.ResponseWriter, request *http.Request) {
		for _, device := range netDevices {
			_, err := fs.NetClassByIface(device)
			if err != nil {
				panic(err)
			}
		}
		fmt.Printf(". ")
		writer.WriteHeader(200)
		writer.Write([]byte("ok"))
	})
	log.Fatal(http.ListenAndServe(":9100", nil))
}

go.mod

module app

go 1.19

require (
	github.com/prometheus/procfs v0.8.0 // indirect
	golang.org/x/sync v0.0.0-20220601150217-0de741cfad7f // indirect
)

just run script:

go run main.go &
for i in {0..10000} ; do curl localhost:9100/metrics ; done

after ~1 minutes script stucks

[tyrken]

FWIW I got a hang on the second try of the for loop from @paragor above with kernel 5.4.214-120 on Amazon Linux 2, but after upgrading to 5.4.219-126.411.amzn2.x86_64 it's survived over 20 runs without issues.

[sooslaca]

Sharing our poor man's docker-compose solution for the restarts until this issue resolved

    healthcheck:
      test: ["CMD-SHELL", "wget -O /dev/null --no-check-certificate -T 2 https://127.0.0.1:9100 2>&1 | grep -q 'timed out' && killall -TERM node_exporter && exit 1 || true"]
      interval: 10s
      timeout: 5s
      retries: 2

note: change to http if you don't do tls

[SuperQ]

I have published node_exporter v1.5.0 which now defaults GOMAXPROCS to 1.

It also has a new collector feature, --collector.netclass.netlink that enables gathering metrics via netlink rather than sysfs. This is much more effficient, but lacks a couple metrics that are available in sysfs. (node_network_address_assign_type, node_network_device_id, and node_network_name_assign_type)

This new feature is not enabled by default, so you will need to include it in your deployment.

[hrak]

Ubuntu just released a new kernel package linux: 5.4.0-135.152 that supposedly fixes this issue:

This bug was fixed in the package linux - 5.4.0-135.152

---------------
linux (5.4.0-135.152) focal; urgency=medium

  * focal/linux: 5.4.0-135.152 -proposed tracker (LP: [#1997412](https://bugs.launchpad.net/bugs/1997412))

  * containerd sporadic timeouts (LP: [#1996678](https://bugs.launchpad.net/bugs/1996678))
    - epoll: call final ep_events_available() check under the lock
    - epoll: check for events when removing a timed out thread from the wait queue
    - Revert "fs: check FMODE_LSEEK to control internal pipe splicing"
    
    [...]

See https://bugs.launchpad.net/ubuntu/+source/containerd/+bug/1996678/comments/28

[metanull-operator]

FWIW, I am still seeing this problem under 1.5.0. Symptoms are the same as with earlier versions. node_exporter metrics often take too long to respond, Prometheus times out, no data is recorded. Presently running kernel 5.4.0-132, but will be trying 5.4.0-135 soon.

[kj]

The 5.4.0-135 kernel seems to have fixed this issue for me. More than 24 hours now without issue.

[jerryrelmore]

Same for 5.4.0-1082-kvm kernel across about 40 systems currently.

[Tibo75]

Also stable with 5.4.0-1092-aws (ubuntu 18 EC2).
10+ instances running for 24 hours without issues.

[cedvan]

Same here, the 5.4.0-135 kernel have fixed this issue for my nodes with Ubuntu 18.04.

[matthewtorr-msft]

For those relying on upstream:

According to https://lore.kernel.org/lkml/Y38h9oe4ZEGNd7Zx@quatroqueijos.cascardo.eti.br/T/, the regression in 5.4 was caused because not all the necessary patches were backported. It claims that backporting "289caf5d8f6c61c6d2b7fd752a7f483cd153f182 (epoll: check for events when removing a timed out thread from the wait queue)" will fix the issue.

Accoding to https://lore.kernel.org/lkml/20221206124054.310184563@linuxfoundation.org/, that patch is planned to be backported to 5.4.226.

I haven't tested this yet but if anyone intrepid feels like installing the release candidate, feel free :)

[SuperQ]

Thanks all, it seems like the upstream kernel issues have been identified and fixed. I'm going to call this one solved.