100% CPU usage and spawns process for host user

[nflaig]

Is there an existing issue for this?

• I have searched the existing issues

Version

3.0.1

Describe The Bug

Causes 100% CPU utilization 24/7 and spawns process for host user.

CPU usage

ps -p 3607138 -o %cpu,%mem,cmd
%CPU %MEM CMD
99.9  0.0 node index.mjs

User processes

ps -u <user>
    PID TTY          TIME CMD
3607110 ?        00:00:00 npm run start:p
3607137 ?        00:00:00 sh
3607138 ?        3-04:40:07 node
3607139 ?        00:00:00 node
3892167 ?        00:00:00 npm run start:p
3892187 ?        00:00:00 sh
3892188 ?        20:42:45 node
3892189 ?        00:00:00 node
3988157 ?        00:00:00 systemd
3988158 ?        00:00:00 (sd-pam)
3988302 ?        00:00:00 sshd
3988304 pts/0    00:00:00 bash
3992888 pts/0    00:00:00 ps

Steps To Reproduce

Run cloudflare-dds via docker, see https://github.com/eth-educators/eth-docker/blob/63b651d56e83d7b513d9350cd00eca3383eecfc0/traefik-cf.yml#L52

Expected Behavior

Should not spawn process for host user and cause 100% CPU utilization 24/7.

ENV Configuration

CF_DNS__CRON=*/5 * * * *
ZONE=
CF_DNS__LOG_LEVEL=info
USER=root
npm_config_user_agent=npm/9.5.1 node/v18.16.0 linux x64 workspaces/false
CF_DNS__DOMAINS_0__ZONE_NAME=<masked>
NODE_VERSION=18.16.0
YARN_VERSION=1.22.19
HOSTNAME=469acd70073b
npm_node_execpath=/usr/local/bin/node
SHLVL=4
npm_config_noproxy=
HOME=/root
OLDPWD=/root
CWD=/app
npm_package_json=/app/package.json
API=
npm_config_userconfig=/root/.npmrc
npm_config_local_prefix=/app
CF_DNS__DOMAINS_0__ZONE_ID=
CF_DNS__DOMAINS_0__CREATE=true
COLOR=0
npm_config_metrics_registry=https://registry.npmjs.org/
CF_DNS__DOMAINS_0__TYPE=A
LOGNAME=root
RUNONCE=
IPV6=
npm_config_cache=/home/node/.npm
npm_config_node_gyp=/usr/local/lib/node_modules/npm/node_modules/node-gyp/bin/node-gyp.js
PATH=/app/node_modules/.bin:/node_modules/.bin:/usr/local/lib/node_modules/npm/node_modules/@npmcli/run-script/lib/node-gyp-bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
PROXY=
EMAIL=
CF_DNS__DOMAINS_0__NAME=<masked>
NODE=/usr/local/bin/node
npm_package_name=cloudflare-ddns
CF_DNS__AUTH__SCOPED_TOKEN=<masked>
npm_lifecycle_script=node index.mjs | pino-pretty --translateTime yyyy-mm-dd'T'HH:MM:sso
HOST=
SHELL=/bin/ash
npm_package_version=3.0.1
npm_lifecycle_event=start:pretty
TTL=
NPM_CONFIG_UPDATE_NOTIFIER=false
FORCE_CREATE=
npm_config_globalconfig=/app/.npm/etc/npmrc
npm_config_init_module=/root/.npm-init.js
PWD=/app
npm_execpath=/usr/local/lib/node_modules/npm/bin/npm-cli.js
npm_config_global_prefix=/app/.npm
npm_command=run-script
NODE_ENV=production
CF_DNS__DOMAINS_0__PROXIED=true
CF_DNS_CONFIG=/app/config.yaml
NPM_CONFIG_PREFIX=/app/.npm
INIT_CWD=/app
EDITOR=vi

JS Configuration

No response

Relevant Output Log

No response

[joshuaavalon]

I cannot reproduce the issue. Can you provide the log?

Also, you do not need two containers for v4 and v6. The second config can be replace 0 with 1.

- CF_DNS__DOMAINS_0__ZONE_NAME=${DOMAIN}
- CF_DNS__DOMAINS_0__ZONE_ID=${CF_ZONE_ID:-}
- CF_DNS__DOMAINS_0__NAME=${DDNS_SUBDOMAIN}.${DOMAIN}
- CF_DNS__DOMAINS_0__PROXIED=${DDNS_PROXY}
- CF_DNS__DOMAINS_0__CREATE=true
- CF_DNS__DOMAINS_0__TYPE=A
- CF_DNS__DOMAINS_1__ZONE_NAME=${DOMAIN}
- CF_DNS__DOMAINS_1__ZONE_ID=${CF_ZONE_ID:-}
- CF_DNS__DOMAINS_1__NAME=${DDNS_SUBDOMAIN}.${DOMAIN}
- CF_DNS__DOMAINS_1__PROXIED=${DDNS_PROXY}
- CF_DNS__DOMAINS_1__CREATE=true
- CF_DNS__DOMAINS_1__TYPE=AAAA

[nflaig]

I cannot reproduce the issue. Can you provide the log?

I will dig into this later, just dropped issue yesterday because I thought maybe it is something obvious in the code.

Also, you do not need two containers for v4 and v6. The second config can be replace 0 with 1.

Thanks, this is good to know. Forwarded that information to eth-docker.

[nflaig]

I removed the container yesterday and restarted it today, so far I am not seeing any increase in system CPU usage. Will keep monitoring this..

Regarding, the process uid, this is likely due to s6-setuidgid but the strange thing is I am not seeing this anymore either.

docker-cloudflare/docker/root/app/cloudflare.sh

Line 8 in fcebb8a

exec s6-setuidgid node npm run --cache /home/node/.npm start:pretty;

Maybe was some strange behavior when updating from 3.0.0 to 3.0.1.

[nflaig]

OK, I start seeing it again, my system CPU spiked around 7pm, here are logs (socker hang up looks suspicious)

> cloudflare-ddns@3.0.1 start:pretty
> node index.mjs | pino-pretty --translateTime yyyy-mm-dd'T'HH:MM:sso

[2023-06-20P18:45:01+0000] INFO (4158): Cloudflare DDNS start
[2023-06-20P18:45:25+0000] ERROR (4158): Failed to update <masked>. (Client network socket disconnected before secure TLS connection was established)
[2023-06-20P18:45:25+0000] INFO (4158): Cloudflare DDNS end

> cloudflare-ddns@3.0.1 start:pretty
> node index.mjs | pino-pretty --translateTime yyyy-mm-dd'T'HH:MM:sso

[2023-06-20P18:50:01+0000] INFO (4192): Cloudflare DDNS start
[2023-06-20P18:50:23+0000] ERROR (4192): Failed to update <masked>. (socket hang up)
[2023-06-20P18:50:23+0000] INFO (4192): Cloudflare DDNS end

> cloudflare-ddns@3.0.1 start:pretty
> node index.mjs | pino-pretty --translateTime yyyy-mm-dd'T'HH:MM:sso

[2023-06-20P18:55:01+0000] INFO (4226): Cloudflare DDNS start
[2023-06-20P18:55:17+0000] INFO (4226): Skipped updating.
[2023-06-20P18:55:17+0000] INFO (4226): Updated <masked> with <masked>
[2023-06-20P18:55:17+0000] INFO (4226): Cloudflare DDNS end

> cloudflare-ddns@3.0.1 start:pretty
> node index.mjs | pino-pretty --translateTime yyyy-mm-dd'T'HH:MM:sso

[2023-06-20P19:00:01+0000] INFO (4262): Cloudflare DDNS start
[2023-06-20P19:00:10+0000] INFO (4262): Skipped updating.
[2023-06-20P19:00:10+0000] INFO (4262): Updated <masked> with <masked>
[2023-06-20P19:00:10+0000] INFO (4262): Cloudflare DDNS end

> cloudflare-ddns@3.0.1 start:pretty
> node index.mjs | pino-pretty --translateTime yyyy-mm-dd'T'HH:MM:sso

[2023-06-20P19:05:01+0000] INFO (4296): Cloudflare DDNS start
[2023-06-20P19:05:07+0000] INFO (4296): Skipped updating.
[2023-06-20P19:05:07+0000] INFO (4296): Updated <masked> with <masked>
[2023-06-20P19:05:07+0000] INFO (4296): Cloudflare DDNS end

This is the process that spawned for my host user that causes the CPU usage

> ps -p 4086735 -o pid,user,comm,lstart,etime,args

PID USER     COMMAND                          STARTED     ELAPSED COMMAND
4086735 nico     npm run start:p Tue Jun 20 16:54:59 2023    02:41:37 npm run start:pretty

---
> ps -p 4086747 -o pid,user,comm,lstart,etime,args

PID USER     COMMAND                          STARTED     ELAPSED COMMAND
4086747 nico     node            Tue Jun 20 16:55:00 2023    02:45:03 node index.mjs

---
> ps -p 4086747 -o %cpu,%mem,cmd

%CPU %MEM CMD
99.8  0.1 node index.mjs

[joshuaavalon]

Since I still cannot reproduce the issue, I would like to ask for your help.

1. Use ghcr.io/joshuaavalon/cloudflare-ddns:feat-detail-log. I added many debug log to different functions calls and a process id each time it starts.
2. Use CF_DNS__LOG_LEVEL=debug

You should able to see something like the following log

 [2023-06-21A02:51:01+0000] DEBUG (269): Start
     processId: "c2578ffe-5712-4b18-8ab6-328547696597"
    method: "requestWebhook"

or if you want to grep by processId, you can use CF_DNS__LOG_TYPE=json and it prints json log instead.

{"level":50,"time":1687315899968,"pid":235,"hostname":"5c04695bba47","processId":"78ef9502-75f6-4416-8f7f-df4014ad4f10","method":"updateDnsRecords","msg":"Failed to update"}

I would like to ask you to look for the log during the CPU spike and check the following things:

1. Use docker compose exec cf-ddns-v4 bash to enter the docker
   1. Does it have one or multiple processes running?
   2. What if you kill the process?
2. Does the problem persist after you restart the container?
3. Does the spike happen during fixed time period?
4. What is the last logged message for the process? Is it always the same? (Assume if it stops at some places)
5. Does it still happen if you use CF_DNS__LOG_TYPE=json?

[nflaig]

Since I still cannot reproduce the issue

So either this only happens because I am running 2 containers (which would still be a bug) or this is related to the socket hangup which makes it hard to reproduce.

I would like to ask for your help

Glad to help debug this, thanks for providing the image. I deployed it now with the configs you mentioned,

check the following things

Let's wait and see, will report back here once issue happens again

[nflaig]

Issue happened again, I don't see anything suspicious in the logs though.

Regarding your questions:

Does it have one or multiple processes running?

These are the processes inside the container

PID   USER     TIME  COMMAND
    1 root      0:00 s6-svscan -t0 /var/run/s6/services
   35 root      0:00 s6-supervise s6-fdholderd
  207 root      0:00 s6-supervise cloudflare-ddns
  210 root      0:00 sh ./run
  247 root      0:00 crond -f
 1975 node      0:00 npm run start:json
 1986 node      5h25 node index.mjs
 3432 root      0:00 bash
 3439 root      0:00 ps

What if you kill the process?

Killing the process (1986) fixes the issue

Does the problem persist after you restart the container?

No, I tested this multiple times, it is fixed for a while but then happens again.

Does the spike happen during fixed time period?

It happens 24/7 until process is killed.

What is the last logged message for the process? Is it always the same? (Assume if it stops at some places)

No suspicious log found

Does it still happen if you use CF_DNS__LOG_TYPE=json?

yes

---

Those answers are probably not that helpful, I will try to find out what the process does using some others tools.

[joshuaavalon]

Does it happen to IPv4 or IPv6?
May be you can change out the default ip service?

The default for IPv4 are

• https://1.1.1.1/cdn-cgi/trace
• https://api.ipify.org?format=json

IPv6

• https://[2606:4700:4700::1111]/cdn-cgi/trace
• https://api6.ipify.org?format=json

[nflaig]

Does it happen to IPv4 or IPv6?

Happens on both, when I initially reported it there were 2 processes.

Since I killed the process it didn't happen again, it has been 24h.

[yorickdowne]

I have this reproduced with two containers. Restarting with one, let's see how it does.

It took one entire core, but no more.

"Two services" may not be related. On another box I've been up for 8 days with two services and it doesn't take a full core.

[nflaig]

Collected a bit more information on what the process is doing using perf + inferno (see ChainSafe/lodestar#5604 (comment) for full instructions) but the results or not that helpful either. Would have to add --perf-basic-prof flag to node to get more details on the [unknown].

A few guesses on what could be the issue:

• the yellow/orange [unknown] might be functions that are throwing (loop retrying something), probably index.mjs and main, would have to add --perf-basic-prof to get more details
• there are mutex's involved so its something at the native layer that is getting accessed repeatedly, perhaps the socket
• possibly an uncaught exception due to network error or something transient that gets called recursively
• could be this function call but haven't looked further into it

  docker-cloudflare/packages/app/src/index.ts

  Line 58 in fcebb8a

  await requestWebhook(ctx, webhook?.failure, failureMessage);

[joshuaavalon]

@nflaig That function should not run if you did not define any webhook

docker-cloudflare/packages/app/src/index.ts

Lines 28 to 50 in 5b4fd91

	const requestWebhook = async (
	ctx: Context,
	url?: string,
	data?: unknown
	): Promise<void> => {
	const logger = ctx.logger.child({ method: "requestWebhook" });
	logger.debug("Start", { url, data });
	if (!url) {
	logger.debug("End");
	return;
	}
	try {
	if (data) {
	await axios.post(url, data);
	} else {
	await axios.get(url);
	}
	} catch (err) {
	logger.warn("Fail to request webhook", { err, url, data });
	} finally {
	logger.debug("End");
	}
	};

If you are using ghcr.io/joshuaavalon/cloudflare-ddns:feat-detail-log, you should able to see the url that it is requesting in the debug log.

[nflaig]

That function should not run if you did not define any webhook

You might be right, I haven't looked further into it if this is really the case.

eth-docker now just uses 1 container for both ipv4 and ipv6 (traefik-cf.yml#L51) but I am still seeing this issue. Disabled the container for now on my end.

I might take another look at it over the weekend if I find the time.

[Fr33loader]

I'm having the same issue: sudden and continued CPU usage of 300%. I restarted the container and it went back to normal, until it went to 100% again the next day (again for a continued period) until I restarted.

No anomalies in the logs that I could find, just an endless repetition of:

> cloudflare-ddns@3.0.0 start:pretty
> node index.mjs | pino-pretty --translateTime yyyy-mm-dd'T'HH:MM:sso

[2023-07-04A07:45:01+0000] INFO (273): Cloudflare DDNS start
[2023-07-04A07:45:10+0000] INFO (273): Skipped updating.
[2023-07-04A07:45:10+0000] INFO (273): Updated [mydomain] with [my IP]
[2023-07-04A07:45:10+0000] INFO (273): Cloudflare DDNS end