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)