Start of script hangs for 20 minutes after WEBUI_PORT notation, then eventually starts

[travelvice]

Just an odditiy that I thought I'd document here since I don't see any other hits like it. This has been manifesting in TrueNAS Scale for most of the year. It wasn't like this always, just thought it pretty weird.

2024-09-20T21:22:18.797798984-05:00 Created by...
2024-09-20T21:22:18.797832235-05:00 ___.   .__       .__
2024-09-20T21:22:18.797844187-05:00 \_ |__ |__| ____ |  |__   ____ ___  ___
2024-09-20T21:22:18.797849506-05:00  | __ \|  |/    \|  |  \_/ __ \\  \/  /
2024-09-20T21:22:18.797853554-05:00  | \_\ \  |   |  \   Y  \  ___/ >    <
2024-09-20T21:22:18.797857601-05:00  |___  /__|___|  /___|  /\___  >__/\_ \
2024-09-20T21:22:18.797861657-05:00      \/        \/     \/     \/      \/
2024-09-20T21:22:18.797870038-05:00    https://hub.docker.com/u/binhex/
2024-09-20T21:22:18.797874219-05:00 
2024-09-20T21:22:21.641689519-05:00 2024-09-20 21:22:21.253205 [info] System information: Linux qbittorrentvpn-ix-chart-85b9f6f7ff-2qhqc 6.1.74-production+truenas #2 SMP PREEMPT_DYNAMIC Wed Feb 21 20:30:38 UTC 2024 x86_64 GNU/Linux
2024-09-20T21:22:21.666662070-05:00 2024-09-20 21:22:21.666543 [info] Image tags: INT_RELEASE_TAG=2024073001,IMAGE_RELEASE_TAG=4.6.7-1-01
2024-09-20T21:22:21.862397024-05:00 2024-09-20 21:22:21.862252 [info] PUID defined as '568'
2024-09-20T21:22:47.837147155-05:00 2024-09-20 21:22:47.837005 [info] PGID defined as '568'
2024-09-20T21:22:50.484815644-05:00 2024-09-20 21:22:50.484726 [info] UMASK defined as '000'
2024-09-20T21:22:50.565478158-05:00 2024-09-20 21:22:50.565387 [info] Permissions already set for '/config'
2024-09-20T21:22:51.286147806-05:00 2024-09-20 21:22:51.285966 [info] Deleting files in /tmp (non recursive)...
2024-09-20T21:22:51.660302453-05:00 2024-09-20 21:22:51.660217 [info] VPN_ENABLED defined as 'yes'
2024-09-20T21:22:51.680138571-05:00 2024-09-20 21:22:51.680027 [info] VPN_CLIENT defined as 'wireguard'
2024-09-20T21:22:51.700011917-05:00 2024-09-20 21:22:51.699894 [info] VPN_PROV defined as 'pia'
2024-09-20T21:22:51.860678602-05:00 2024-09-20 21:22:51.860566 [info] WireGuard config file (conf extension) is located at /config/wireguard/wg0.conf
2024-09-20T21:22:52.163049850-05:00 2024-09-20 21:22:52.162930 [info] VPN_REMOTE_SERVER defined as 'ca-toronto.privacy.network'
2024-09-20T21:22:52.182845535-05:00 2024-09-20 21:22:52.182727 [info] VPN_REMOTE_PORT defined as '1337'
2024-09-20T21:22:52.200969844-05:00 2024-09-20 21:22:52.200848 [info] VPN_DEVICE_TYPE defined as 'wg0'
2024-09-20T21:22:52.219156599-05:00 2024-09-20 21:22:52.219040 [info] VPN_REMOTE_PROTOCOL defined as 'udp'
2024-09-20T21:22:52.238242697-05:00 2024-09-20 21:22:52.238151 [info] USERSPACE_WIREGUARD not defined (via -e USERSPACE_WIREGUARD), defaulting to 'no'
2024-09-20T21:22:52.256986552-05:00 2024-09-20 21:22:52.256904 [info] NAME_SERVERS defined as '84.200.69.80,37.235.1.174,1.1.1.1,37.235.1.177,84.200.70.40,1.0.0.1'
2024-09-20T21:22:52.579454992-05:00 2024-09-20 21:22:52.579330 [debug] iptables default policies available, setting policy to drop...
2024-09-20T21:22:53.318785440-05:00 modprobe: FATAL: Module ip6_tables not found in directory /lib/modules/6.1.74-production+truenas
2024-09-20T21:22:53.319318286-05:00 ip6tables v1.8.10 (legacy): can't initialize ip6tables table `filter': Table does not exist (do you need to insmod?)
2024-09-20T21:22:53.319377932-05:00 Perhaps ip6tables or your kernel needs to be upgraded.
2024-09-20T21:22:53.343091435-05:00 2024-09-20 21:22:53.342983 [warn] ip6tables default policies not available, skipping ip6tables drops
2024-09-20T21:22:55.695401113-05:00 2024-09-20 21:22:55.695316 [debug] DNS operational, we can resolve name 'ca-toronto.privacy.network' to address '179.61.197.179 191.96.36.53 191.96.36.239'
2024-09-20T21:22:56.087069660-05:00 2024-09-20 21:22:56.086890 [debug] DNS operational, we can resolve name 'www.privateinternetaccess.com' to address '104.18.23.75 104.18.22.75'
2024-09-20T21:22:56.137819502-05:00 2024-09-20 21:22:56.137698 [debug] DNS operational, we can resolve name 'serverlist.piaservers.net' to address '104.18.159.201 104.19.240.167'
2024-09-20T21:22:56.164086788-05:00 2024-09-20 21:22:56.163995 [debug] Showing name servers in '/etc/resolv.conf' before overwrite from NAME_SERVERS...
2024-09-20T21:22:56.181824455-05:00 2024-09-20 21:22:56.181694 [debug] nameserver 10.123.0.1
2024-09-20T21:22:56.206311630-05:00 2024-09-20 21:22:56.206197 [debug] Showing name servers in '/etc/resolv.conf' after overwrite from NAME_SERVERS...
2024-09-20T21:22:56.224281773-05:00 2024-09-20 21:22:56.224166 [debug] nameserver 84.200.69.80
2024-09-20T21:22:56.224305575-05:00 2024-09-20 21:22:56.224208 [debug] nameserver 37.235.1.174
2024-09-20T21:22:56.224310808-05:00 2024-09-20 21:22:56.224215 [debug] nameserver 1.1.1.1
2024-09-20T21:22:56.224314701-05:00 2024-09-20 21:22:56.224219 [debug] nameserver 37.235.1.177
2024-09-20T21:22:56.224318588-05:00 2024-09-20 21:22:56.224222 [debug] nameserver 84.200.70.40
2024-09-20T21:22:56.224322352-05:00 2024-09-20 21:22:56.224225 [debug] nameserver 1.0.0.1
2024-09-20T21:22:57.918354870-05:00 2024-09-20 21:22:57.918205 [debug] Docker interface name, Gateway interface name, Gateway IP, Docker interface IP, Subnet mask and CIDR are defined as 'eth0,eth0,172.16.0.1,172.16.0.116,255.255.0.0,172.16.0.0/16'
2024-09-20T21:22:57.965988973-05:00 2024-09-20 21:22:57.965869 [info] LAN_NETWORK defined as '10.0.0.0/8'
2024-09-20T21:22:57.987712609-05:00 2024-09-20 21:22:57.987591 [info] LAN_NETWORK exported as '10.0.0.0/8'
2024-09-20T21:22:58.007166380-05:00 2024-09-20 21:22:58.007072 [info] VPN_USER defined as 'REDACTED'
2024-09-20T21:22:58.026944297-05:00 2024-09-20 21:22:58.026761 [info] VPN_PASS defined as 'REDACTED'
2024-09-20T21:22:58.046139264-05:00 2024-09-20 21:22:58.045992 [info] STRICT_PORT_FORWARD defined as 'yes'
2024-09-20T21:22:58.066328733-05:00 2024-09-20 21:22:58.066158 [info] VPN_INPUT_PORTS defined as '1234'
2024-09-20T21:22:58.085262458-05:00 2024-09-20 21:22:58.085103 [info] VPN_OUTPUT_PORTS defined as '5678'
2024-09-20T21:22:58.104250196-05:00 2024-09-20 21:22:58.104142 [info] ENABLE_STARTUP_SCRIPTS not defined (via -e ENABLE_STARTUP_SCRIPTS), defaulting to 'no'
2024-09-20T21:22:58.123526916-05:00 2024-09-20 21:22:58.123434 [warn] ENABLE_SOCKS not defined (via -e ENABLE_SOCKS), defaulting to 'no'
2024-09-20T21:22:58.143114887-05:00 2024-09-20 21:22:58.142978 [info] ENABLE_PRIVOXY defined as 'yes'
2024-09-20T21:22:58.162904837-05:00 2024-09-20 21:22:58.162775 [info] WEBUI_PORT defined as '13337'
2024-09-20T21:43:28.215142712-05:00 2024-09-20 21:43:28.214949 [info] SHARED_NETWORK not defined (via -e SHARED_NETWORK), defaulting to 'no'
2024-09-20T21:43:28.234068715-05:00 2024-09-20 21:43:28.233948 [info] Starting Supervisor...
2024-09-20T21:43:34.220207162-05:00 2024-09-20 21:43:34,220 INFO Included extra file "/etc/supervisor/conf.d/qbittorrent.conf" during parsing
2024-09-20T21:43:34.220249950-05:00 2024-09-20 21:43:34,220 INFO Set uid to user 0 succeeded
2024-09-20T21:43:34.249804748-05:00 2024-09-20 21:43:34,249 INFO supervisord started with pid 7
2024-09-20T21:43:35.254802389-05:00 2024-09-20 21:43:35,254 INFO spawned: 'start-script' with pid 376
2024-09-20T21:43:35.258420439-05:00 2024-09-20 21:43:35,258 INFO spawned: 'watchdog-script' with pid 377
2024-09-20T21:43:35.258910513-05:00 2024-09-20 21:43:35,258 INFO reaped unknown pid 8 (exit status 0)
2024-09-20T21:43:35.302801309-05:00 2024-09-20 21:43:35,302 DEBG 'start-script' stdout output:
2024-09-20T21:43:35.302843212-05:00 [info] VPN is enabled, beginning configuration of VPN
2024-09-20T21:43:35.302864391-05:00 [debug] Environment variables defined as follows
2024-09-20T21:43:35.302883945-05:00 
2024-09-20T21:43:35.302914745-05:00 2024-09-20 21:43:35,302 INFO success: start-script entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2024-09-20T21:43:35.302975084-05:00 2024-09-20 21:43:35,302 INFO success: watchdog-script entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)

[gaines]

I just set up qbittorrentvpn and sabnzbdvpn containers on my TrueNAS Scale server for the first time and noticed that both of them take 18-20 minutes before supervisor starts and launches the qBittorrent or SABnzbd service.

[3lis-e]

same behavior here, truenas scale too.

[binhex]

Hmm i have seen a similar issue years ago on another system and if i remember correctly it was due to a weirdess with the docker driver being used, this is the code that is executing after WEBUI_PORT:-

# if first run (no puid or pgid files in /tmp) or the PUID or PGID env vars are different
# from the previous run then re-apply chown with current PUID and PGID values.
if [[ ! -f "/root/puid" || ! -f "/root/pgid" || "${previous_puid}" != "${PUID}" || "${previous_pgid}" != "${PGID}" ]]; then

        # set permissions inside container - Do NOT double quote variable for install_paths otherwise this will wrap space separated paths as a single string
        chown -R "${PUID}":"${PGID}" /etc/privoxy /home/nobody

fi

My bet is that the chown is causing the issue here, it shouldn't do as its changing ownership on a very small number of files inside the container but i bet that's it.

I would assume that after the first run it's ok though right?, the chown should not be run unless it's either the first run or you have changed the values for PUID and/or PGID.

[binhex]

I'm assuming you guys are all running Docker Storage Driver 'overlay2' right?, take a look at the following:-

docker/for-linux#388
linuxserver/docker-bookstack#60

[blounolito]

Just got the same problem on a fresh pull (Truenas scale Dragonfish-24.04.2.2).
I tried to kill the PID for chown with sudo kill -9 , not very wise as the container restarted
I let it run 20mins+, containers restart for an unknown reason, I can't access its logs.
Tried privileged mode, setting root/568/1000 PUID/PGID on share, using or not SMB, no success.