docker containers reported as unhealthy due to slow eturnalctl status response

[oliverjkb]

Please consider this more as a question.

The docker container's health check is setup to call eturnalctl status once a minute and timout after 5 seconds.

I have just recently setup two instances of eturnal on docker, both of which take about 15 seconds to report status, hence being reported as unhealthy.

Comand run inside the container:

~ $ time eturnalctl status
eturnal is running
real	0m 15.10s
user	0m 0.03s
sys	0m 0.06s

The outcome is the same on AMD Epyc (~2.4GHz) and Intel Xeon (~2.1GHz) hosts, with next to no cpu usage in total.
I can fix this by adding custom healthcheck parameters in my docker-compose.yml so that's not an issue.

I do wonder though, if the discrepancy between the default 5 seconds and the experienced 15 seconds are a problem on my end, and if so, how to possibly debug and mitigate.

Best regards!

[sando38]

I think we did some changes "recently" on this check. Can you shortly tell us which version you use? I am tempted for a while already to remove this part of the Dockerfile entirely.

[oliverjkb]

The containers are both running on ghrc.io/processone/eturnal:latest.

~ $ eturnalctl version
1.12.1

Interestingly, even the version command takes about 10 seconds to complete.

[sando38]

Hm.. I cannot really reproduce it.

saarko@DESKTOP-5EP0JF1:~$ docker run --rm -d --name eturnal eturnal/eturnal:1.12.1
40fda4023a93c5a414cd0573782977a099d755118b2ef30f6f7bb16248a5532b
saarko@DESKTOP-5EP0JF1:~$ docker logs eturnal
run.sh: Start init script ...
run.sh: Container runs eturnal vsn 1.12.1 ...
run.sh: Documentation on https://eturnal.net ...
run.sh: Source code on https://github.com/processone/eturnal ...
run.sh: Read secrets defined as "Docker secrets" - if any ...
Cannot query stun.conversations.im:3478: non-existing domain
Exec: /opt/eturnal/erts-15.1.2/bin/erlexec -noinput +Bd -boot /opt/eturnal/releases/1.12.1/start -mode embedded -boot_var SYSTEM_LIB_DIR /opt/eturnal/lib -config /opt/eturnal/releases/1.12.1/sys.config -args_file /opt/eturnal/releases/1.12.1/vm.args -erl_epmd_port 3470 -start_epmd false -- foreground
Root: /opt/eturnal
/opt/eturnal
2025-04-25 20:34:42.096435+00:00 [notice] Starting eturnal 1.12.1 on Erlang/OTP 27 (ERTS 15.1.2)
2025-04-25 20:34:42.096532+00:00 [info] Got no NOTIFY_SOCKET, notifications disabled
2025-04-25 20:34:42.096576+00:00 [info] Relay IPv4 address: 212.30.36.187 (port range: 49152-65535)
2025-04-25 20:34:42.096627+00:00 [info] Relay IPv6 address not configured
2025-04-25 20:34:42.096685+00:00 [info] Listening on 127.0.0.1:3470 (tcp) (Erlang protocol version 5)
2025-04-25 20:34:42.096903+00:00 [info] Started mod_log_stun
2025-04-25 20:34:42.097524+00:00 [info] Listening on [::]:3478 (udp) (STUN/TURN)
2025-04-25 20:34:42.097748+00:00 [info] Listening on [::]:3478 (tcp) (STUN/TURN)
saarko@DESKTOP-5EP0JF1:~$ time docker exec eturnal eturnalctl status
eturnal is running

real    0m0.103s
user    0m0.015s
sys     0m0.010s
saarko@DESKTOP-5EP0JF1:~$ time docker exec eturnal eturnalctl version
1.12.1

real    0m0.104s
user    0m0.025s
sys     0m0.000s

Would you be so kind to try to reproduce with the above steps I used? And maybe you send me your docker-compose.yml as well, then I try on my end with your config. Please also paste your eturnal.yml configuration file (without secrets of course ;) )

[oliverjkb]

Sure. Just ran the same commands as per your example, and the outcome is pretty much the same:

root@turn:~# docker run --rm -d --name eturnal eturnal/eturnal:1.12.1
Unable to find image 'eturnal/eturnal:1.12.1' locally
1.12.1: Pulling from eturnal/eturnal
Digest: sha256:b2954dbfb6fea4bccaa4c60cb51db371713edb29cf70b58820ae0d166d3f5ae8
Status: Downloaded newer image for eturnal/eturnal:1.12.1
28bd1bd55615b329094556f3dbe174b54c01d9b49e3165fa5ac7f69c39b22772
root@turn:~# docker logs eturnal
run.sh: Start init script ...
run.sh: Container runs eturnal vsn 1.12.1 ...
run.sh: Documentation on https://eturnal.net ...
run.sh: Source code on https://github.com/processone/eturnal ...
run.sh: Read secrets defined as "Docker secrets" - if any ...
Cannot query stun.conversations.im:3478: network is unreachable
Exec: /opt/eturnal/erts-15.1.2/bin/erlexec -noinput +Bd -boot /opt/eturnal/releases/1.12.1/start -mode embedded -boot_var SYSTEM_LIB_DIR /opt/eturnal/lib -config /opt/eturnal/releases/1.12.1/sys.config -args_file /opt/eturnal/releases/1.12.1/vm.args -erl_epmd_port 3470 -start_epmd false -- foreground
Root: /opt/eturnal
/opt/eturnal
2025-04-26 08:34:39.110736+00:00 [notice] Starting eturnal 1.12.1 on Erlang/OTP 27 (ERTS 15.1.2)
2025-04-26 08:34:39.111029+00:00 [info] Got no NOTIFY_SOCKET, notifications disabled
2025-04-26 08:34:39.111133+00:00 [info] Relay IPv4 address: xxx.xxx.xxx.xxx (port range: 49152-65535)
2025-04-26 08:34:39.111280+00:00 [info] Relay IPv6 address not configured
2025-04-26 08:34:39.111406+00:00 [info] Listening on 127.0.0.1:3470 (tcp) (Erlang protocol version 5)
2025-04-26 08:34:39.112074+00:00 [info] Started mod_log_stun
2025-04-26 08:34:39.112703+00:00 [info] Listening on [::]:3478 (udp) (STUN/TURN)
2025-04-26 08:34:39.113107+00:00 [info] Listening on [::]:3478 (tcp) (STUN/TURN)

root@turn:~# time docker exec eturnal eturnalctl status
eturnal is running

real	0m0.197s
user	0m0.025s
sys     0m0.025s

root@turn:~# time docker exec eturnal eturnalctl version
1.12.1

real	0m0.239s
user	0m0.036s
sys     0m0.020s

When I run it from my docker compose file (see attached), the Service itself runs quite fast. I tested connectivity and that seems to work fine:

root@turn:~# docker compose logs
eturnal  | run.sh: Start init script ...
eturnal  | run.sh: Container runs eturnal vsn 1.12.1 ...
eturnal  | run.sh: Documentation on https://eturnal.net ...
eturnal  | run.sh: Source code on https://github.com/processone/eturnal ...
eturnal  | run.sh: Read secrets defined as "Docker secrets" - if any ...
eturnal  | Exec: /opt/eturnal/erts-15.1.2/bin/erlexec -noinput +Bd -boot /opt/eturnal/releases/1.12.1/start -mode embedded -boot_var SYSTEM_LIB_DIR /opt/eturnal/lib -config /opt/eturnal/releases/1.12.1/sys.config -args_file /opt/eturnal/releases/1.12.1/vm.args -erl_epmd_port 3470 -start_epmd false -- foreground
eturnal  | Root: /opt/eturnal
eturnal  | /opt/eturnal
eturnal  | 2025-04-26 08:41:29.676507+00:00 [notice] Starting eturnal 1.12.1 on Erlang/OTP 27 (ERTS 15.1.2)
eturnal  | 2025-04-26 08:46:08.662016+00:00 [notice] Creating TURN allocation (lifetime: 600 seconds) [TLS, session 9ve3g9wsn2x9, user 1745657468:turn-test-user, client my.ho.me.ip:32953, relay my.ser.ver.ip:49275]
eturnal  | 2025-04-26 08:46:08.667478+00:00 [notice] Creating TURN allocation (lifetime: 600 seconds) [TLS, session v5skklp80knl, user 1745657468:turn-test-user, client my.ho.me.ip:21408, relay my.ser.ver.ip:49203]
eturnal  | 2025-04-26 08:46:08.670656+00:00 [notice] Creating TURN allocation (lifetime: 599 seconds) [TLS, session myn8w6x693f4, user 1745657468:turn-test-user, client my.ho.me.ip:61471, relay my.ser.ver.ip:49241]
eturnal  | 2025-04-26 08:46:08.685328+00:00 [notice] Creating TURN allocation (lifetime: 600 seconds) [TLS, session e73nwy8uxgim, user 1745657468:turn-test-user, client my.ho.me.ip:39595, relay my.ser.ver.ip:49414]
eturnal  | 2025-04-26 08:46:08.693293+00:00 [notice] Relayed 0 KiB (in 0 B / 0 packets, out 0 B / 0 packets), duration: 0 seconds [TLS, session 9ve3g9wsn2x9, user 1745657468:turn-test-user, client my.ho.me.ip:32953, relay my.ser.ver.ip:49275]
eturnal  | 2025-04-26 08:46:08.693156+00:00 [notice] Relayed 0 KiB (in 0 B / 0 packets, out 0 B / 0 packets), duration: 0 seconds [TLS, session e73nwy8uxgim, user 1745657468:turn-test-user, client my.ho.me.ip:39595, relay my.ser.ver.ip:49414]
eturnal  | 2025-04-26 08:46:08.693827+00:00 [notice] Relayed 0 KiB (in 0 B / 0 packets, out 0 B / 0 packets), duration: 0 seconds [TLS, session myn8w6x693f4, user 1745657468:turn-test-user, client my.ho.me.ip:61471, relay my.ser.ver.ip:49241]
eturnal  | 2025-04-26 08:46:08.693793+00:00 [notice] Relayed 0 KiB (in 0 B / 0 packets, out 0 B / 0 packets), duration: 0 seconds [TLS, session v5skklp80knl, user 1745657468:turn-test-user, client my.ho.me.ip:21408, relay my.ser.ver.ip:49203]

It's only the eturnalctl commands that are quite slow.. 🤔

docker-compose.yml.txt

eturnal.yml.txt

[sando38]

hmm.. so I tested it on my end.
When I run this command on my local machine using your eturnal.yml:

docker run --rm -d --name eturnal --network host -v $PWD/eturnal.yml:/etc/eturnal.yml eturnal/eturnal:1.12.1

it works. When I use the docker-compose.yml and network: host. It takes forever to start and also never reports healthy. But, this is only an issue on my local machine. I tested it on two other remote machines (arm64 and amd64) and it worked without any issues... Question, when you start with docker compose up without the -d does it also take a long time to start? Also, can you try to remove the network: host option in the compose file and see if that improves the situation?

Thank you.

[oliverjkb]

with docker proxy:

It takes about 22 Seconds to start, eturnalctl answers near immediately.

root@ turn $ date && docker compose up
Sun May  4 07:30:16 PM UTC 2025
[+] Running 2/2
 ✔ Network turn_default  Created                                                                                                       0.1s 
 ✔ Container eturnal                Created                                                                                                       0.2s 
Attaching to eturnal
eturnal  | run.sh: Start init script ...
eturnal  | run.sh: Container runs eturnal vsn 1.12.1 ...
eturnal  | run.sh: Documentation on https://eturnal.net ...
eturnal  | run.sh: Source code on https://github.com/processone/eturnal ...
eturnal  | run.sh: Read secrets defined as "Docker secrets" - if any ...
eturnal  | Cannot query stun.conversations.im:3478: network is unreachable
eturnal  | Exec: /opt/eturnal/erts-15.1.2/bin/erlexec -noinput +Bd -boot /opt/eturnal/releases/1.12.1/start -mode embedded -boot_var SYSTEM_LIB_DIR /opt/eturnal/lib -config /opt/eturnal/releases/1.12.1/sys.config -args_file /opt/eturnal/releases/1.12.1/vm.args -erl_epmd_port 3470 -start_epmd false -- foreground
eturnal  | Root: /opt/eturnal
eturnal  | /opt/eturnal
eturnal  | 2025-05-04 19:30:38.023252+00:00 [notice] Starting eturnal 1.12.1 on Erlang/OTP 27 (ERTS 15.1.2)


root@turn $ date && docker compose exec eturnal eturnalctl status && date
Sun May  4 07:3049 PM UTC 2025
eturnal is running
Sun May  4 07:30:50 PM UTC 2025

In comparsion, with attaching to host network:

Takes about 22 seconds to startup as well, but 15 for eturnalctl to answer.

root@turn $ date && docker compose up
Sun May  4 07:34:46 PM UTC 2025
[+] Running 1/1
 ✔ Container eturnal  Recreated                                                                                                                   0.1s 
Attaching to eturnal
eturnal  | run.sh: Start init script ...
eturnal  | run.sh: Container runs eturnal vsn 1.12.1 ...
eturnal  | run.sh: Documentation on https://eturnal.net ...
eturnal  | run.sh: Source code on https://github.com/processone/eturnal ...
eturnal  | run.sh: Read secrets defined as "Docker secrets" - if any ...
eturnal  | Exec: /opt/eturnal/erts-15.1.2/bin/erlexec -noinput +Bd -boot /opt/eturnal/releases/1.12.1/start -mode embedded -boot_var SYSTEM_LIB_DIR /opt/eturnal/lib -config /opt/eturnal/releases/1.12.1/sys.config -args_file /opt/eturnal/releases/1.12.1/vm.args -erl_epmd_port 3470 -start_epmd false -- foreground
eturnal  | Root: /opt/eturnal
eturnal  | /opt/eturnal
eturnal  | 2025-05-04 19:35:08.330289+00:00 [notice] Starting eturnal 1.12.1 on Erlang/OTP 27 (ERTS 15.1.2)


root@turn $ date && docker compose exec eturnal eturnalctl status && date
Sun May  4 07:35:43 PM UTC 2025
eturnal is running
Sun May  4 07:35:58 PM UTC 2025


EDIT: 
I just stopped running the container and installed eturnal via extrepo.
Service startup and eturnalctl response times are both below 1 second.

EDIT 2: 
Interestingly, when attached to the host network, container shutdown takes as much as 28 seconds, when attached via docker network, it only takes about 1-2 seconds. 

[sando38]

Regarding to your "edit 2" comment, I saw the same behavior on my local machine. But could not verify it on the two server instances I have as well. I will keep this issue open, to investigate or if others may have an idea. Thanks.