search

binhex / arch-rtorrentvpn

Docker build script for Arch Linux base with ruTorrent, rTorrent, autodl-irssi, Privoxy and OpenVPN
GNU General Public License v3.0
239 stars 36 forks source link

Container hangs on startup after pulling latest image #154

Closed W3AXL closed 4 years ago

W3AXL commented 4 years ago

I've had a container running for a while, perfectly fine with few issues. Had to restart due to some connection weirdness with rtorrent, and decided I'd pull the latest version while I was at it.

Now it appears the container gets stuck after starting OpenVPN. It just sits there without even trying to start rtorrent, and will continually hit the ping restart timeout but do nothing else.

There's a couple fatal errors seen on startup as well, but again this same startup script and config was being used as of an hour ago with zero issues and nothing has been changed. It seems like the image is unable to load the "tun" kernel module for some reason.

Startup log, with debug enabled (sanitized):

Created by...
___.   .__       .__                   
\_ |__ |__| ____ |  |__   ____ ___  ___
 | __ \|  |/    \|  |  \_/ __ \\  \/  /
 | \_\ \  |   |  \   Y  \  ___/ >    < 
 |___  /__|___|  /___|  /\___  >__/\_ \
     \/        \/     \/     \/      \/
   https://hub.docker.com/u/binhex/

2020-05-18 09:04:35.344547 [info] System information Linux 22b14362247f 4.15.0-96-generic #97-Ubuntu SMP Wed Apr 1 03:25:46 UTC 2020 x86_64 GNU/Linux
2020-05-18 09:04:35.377736 [info] PUID defined as '1003'
2020-05-18 09:04:35.465195 [info] PGID defined as '1003'
2020-05-18 09:04:35.542341 [info] UMASK defined as '002'
2020-05-18 09:04:35.574449 [info] Permissions already set for volume mappings
2020-05-18 09:04:35.611134 [info] VPN_ENABLED defined as 'yes'
2020-05-18 09:04:35.653033 [info] OpenVPN config file (ovpn extension) is located at /config/openvpn/mullvad_ca_tor.ovpn
2020-05-18 09:04:35.720624 [info] VPN remote line defined as 'remote ca-tor-002.mullvad.net 1302'
2020-05-18 09:04:35.754851 [info] VPN_REMOTE defined as 'ca-tor-002.mullvad.net'
2020-05-18 09:04:35.791550 [info] VPN_PORT defined as '1302'
2020-05-18 09:04:35.833484 [info] VPN_PROTOCOL defined as 'udp'
2020-05-18 09:04:35.868493 [info] VPN_DEVICE_TYPE defined as 'tun0'
2020-05-18 09:04:35.904735 [info] VPN_PROV defined as 'custom'
2020-05-18 09:04:35.937292 [info] LAN_NETWORK defined as '192.168.0.0/24'
2020-05-18 09:04:35.971744 [info] NAME_SERVERS defined as '209.222.18.222,37.235.1.174,1.1.1.1,8.8.8.8,209.222.18.218,37.235.1.177,1.0.0.1,8.8.4.4'
2020-05-18 09:04:36.006795 [warn] VPN_USER not defined (via -e VPN_USER), assuming authentication via other method
2020-05-18 09:04:36.037623 [warn] VPN_PASS not defined (via -e VPN_PASS), assuming authentication via other method
2020-05-18 09:04:36.070592 [info] VPN_OPTIONS not defined (via -e VPN_OPTIONS)
2020-05-18 09:04:36.100931 [info] ENABLE_PRIVOXY defined as 'no'
2020-05-18 09:04:36.132942 [info] ADDITIONAL_PORTS not defined (via -e ADDITIONAL_PORTS), skipping allow for custom incoming ports
2020-05-18 09:04:36.163618 [info] ENABLE_AUTODL_IRSSI defined as 'no'
2020-05-18 09:04:36.194152 [info] ENABLE_RPC2 defined as 'yes'
2020-05-18 09:04:36.225727 [info] ENABLE_RPC2_AUTH defined as 'yes'
2020-05-18 09:04:36.255799 [info] RPC2_USER defined as 'papkee'
2020-05-18 09:04:36.285681 [info] RPC2_PASS defined as '..'
2020-05-18 09:04:36.315725 [info] ENABLE_WEBUI_AUTH defined as 'yes'
2020-05-18 09:04:36.344907 [info] WEBUI_USER defined as 'papkee'
2020-05-18 09:04:36.376084 [info] WEBUI_PASS defined as '..'
2020-05-18 09:04:56.504931 [info] Deleting files in /tmp (non recursive)...
2020-05-18 09:04:56.539429 [info] Starting Supervisor...
2020-05-18 09:04:56,724 INFO Included extra file "/etc/supervisor/conf.d/rtorrent.conf" during parsing
2020-05-18 09:04:56,724 INFO Set uid to user 0 succeeded
2020-05-18 09:04:56,727 INFO supervisord started with pid 7
2020-05-18 09:04:57,730 INFO spawned: 'logrotate-script' with pid 199
2020-05-18 09:04:57,732 INFO spawned: 'pyrocore-script' with pid 200
2020-05-18 09:04:57,735 INFO spawned: 'rutorrent-script' with pid 201
2020-05-18 09:04:57,738 INFO spawned: 'start-script' with pid 202
2020-05-18 09:04:57,740 INFO spawned: 'watchdog-script' with pid 203
2020-05-18 09:04:57,740 INFO reaped unknown pid 8
2020-05-18 09:04:57,748 DEBG 'start-script' stdout output:
[info] VPN is enabled, beginning configuration of VPN
[debug] Environment variables defined as follows
ADDITIONAL_PORTS=
APPLICATION=rtorrent
BASH=/bin/bash
BASHOPTS=checkwinsize:cmdhist:complete_fullquote:extquote:force_fignore:globasciiranges:hostcomplete:interactive_comments:progcomp:promptvars:sourcepath
BASH_ALIASES=()
BASH_ARGC=()
BASH_ARGV=()
BASH_CMDS=()
BASH_LINENO=([0]="0")
BASH_SOURCE=([0]="/root/start.sh")
BASH_VERSINFO=([0]="5" [1]="0" [2]="16" [3]="1" [4]="release" [5]="x86_64-pc-linux-gnu")
BASH_VERSION='5.0.16(1)-release'
DEBUG=true
DIRSTACK=()

2020-05-18 09:04:57,748 INFO success: logrotate-script entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-05-18 09:04:57,748 INFO success: pyrocore-script entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-05-18 09:04:57,748 INFO success: rutorrent-script entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-05-18 09:04:57,748 INFO success: start-script entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-05-18 09:04:57,748 INFO success: watchdog-script entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-05-18 09:04:57,748 DEBG 'start-script' stdout output:
ENABLE_AUTODL_IRSSI=no
ENABLE_PRIVOXY=no
ENABLE_RPC2=yes
ENABLE_RPC2_AUTH=yes
ENABLE_WEBUI_AUTH=yes
EUID=0
GROUPS=()
HOME=/home/nobody
HOSTNAME=22b14362247f
HOSTTYPE=x86_64
IFS=$' \t\n'
LANG=en_GB.UTF-8
LAN_NETWORK=192.168.0.0/24
MACHTYPE=x86_64-pc-linux-gnu
NAME_SERVERS=209.222.18.222,37.235.1.174,1.1.1.1,8.8.8.8,209.222.18.218,37.235.1.177,1.0.0.1,8.8.4.4
OPTERR=1
OPTIND=1
OSTYPE=linux-gnu
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/home/nobody/bin
PGID=1003
PHP_TZ=America/Chicago
PIPESTATUS=([0]="0")
PPID=7
PS4='+ '
PUID=1003
PWD=/
RPC2_PASS=..
RPC2_USER=papkee
SHELL=/bin/bash
SHELLOPTS=braceexpand:hashall:interactive-comments
SHLVL=1
STRICT_PORT_FORWARD=yes
SUPERVISOR_ENABLED=1
SUPERVISOR_GROUP_NAME=start-script
SUPERVISOR_PROCESS_NAME=start-script
TERM=xterm
UID=0
UMASK=002
VPN_CONFIG=/config/openvpn/mullvad_ca_tor.ovpn
VPN_DEVICE_TYPE=tun0
VPN_ENABLED=yes
VPN_OPTIONS=
VPN_PASS=
VPN_PORT=1302
VPN_PROTOCOL=udp
VPN_PROV=custom
VPN_REMOTE=ca-tor-002.mullvad.net
VPN_USER=
WEBUI_PASS=..
WEBUI_USER=papkee
_='[debug] Environment variables defined as follows'
[debug] Directory listing of files in /config/openvpn as follows

2020-05-18 09:04:57,748 DEBG 'watchdog-script' stdout output:
[info] rTorrent config file already exists, skipping copy

2020-05-18 09:04:57,767 DEBG 'start-script' stdout output:
total 24
drwxrwxr-x 3 nobody users 4096 May 18 09:04 .
drwxrwxr-x 7 nobody users 4096 May 18 09:04 ..
-rwxrwxr-x 1 nobody users 2186 Mar 21 11:41 mullvad_ca.crt
-rwxrwxr-x 1 nobody users  350 May 18 09:04 mullvad_ca_tor.ovpn
-rwxrwxr-x 1 nobody users   19 Mar 21 11:41 mullvad_userpass.txt
drwxrwxr-x 2 nobody users 4096 Mar 21 04:00 .pia.old

2020-05-18 09:04:57,793 DEBG 'start-script' stdout output:
[debug] Contents of ovpn file /config/openvpn/mullvad_ca_tor.ovpn as follows...

2020-05-18 09:04:57,794 DEBG 'start-script' stdout output:
remote ca-tor-002.mullvad.net 1302
client
dev tun
resolv-retry infinite
nobind
persist-key
verb 3
remote-cert-tls server
ping 10
ping-restart 60
sndbuf 524288
rcvbuf 524288
cipher AES-256-CBC
tls-cipher TLS-DHE-RSA-WITH-AES-256-GCM-SHA384:TLS-DHE-RSA-WITH-AES-256-CBC-SHA
proto udp
auth-user-pass mullvad_userpass.txt
ca mullvad_ca.crt
remote-random

2020-05-18 09:04:57,804 DEBG 'start-script' stdout output:
[info] Default route for container is 172.17.0.1

2020-05-18 09:04:57,808 DEBG 'start-script' stdout output:
[info] Adding 209.222.18.222 to /etc/resolv.conf

2020-05-18 09:04:57,810 DEBG 'start-script' stdout output:
[info] Adding 37.235.1.174 to /etc/resolv.conf

2020-05-18 09:04:57,814 DEBG 'start-script' stdout output:
[info] Adding 1.1.1.1 to /etc/resolv.conf

2020-05-18 09:04:57,817 DEBG 'start-script' stdout output:
[info] Adding 8.8.8.8 to /etc/resolv.conf

2020-05-18 09:04:57,821 DEBG 'start-script' stdout output:
[info] Adding 209.222.18.218 to /etc/resolv.conf

2020-05-18 09:04:57,824 DEBG 'start-script' stdout output:
[info] Adding 37.235.1.177 to /etc/resolv.conf

2020-05-18 09:04:57,827 DEBG 'start-script' stdout output:
[info] Adding 1.0.0.1 to /etc/resolv.conf

2020-05-18 09:04:57,830 DEBG 'start-script' stdout output:
[info] Adding 8.8.4.4 to /etc/resolv.conf

2020-05-18 09:04:57,953 DEBG 'start-script' stdout output:
[info] Attempting to load tun kernel module...

2020-05-18 09:04:57,954 DEBG 'start-script' stderr output:
modprobe: FATAL: Module tun not found in directory /lib/modules/4.15.0-96-generic

2020-05-18 09:04:57,954 DEBG 'start-script' stdout output:
[warn] Unable to load tun kernel module using modprobe, trying insmod...

2020-05-18 09:04:57,955 DEBG 'start-script' stderr output:
insmod: ERROR: could not load module /lib/modules/tun.ko: No such file or directory

2020-05-18 09:04:57,956 DEBG 'start-script' stdout output:
[warn] Unable to load tun kernel module, assuming its dynamically loaded

2020-05-18 09:04:57,963 DEBG 'start-script' stdout output:
[info] Attempting to load iptable_mangle module...

2020-05-18 09:04:57,964 DEBG 'start-script' stderr output:
modprobe: FATAL: Module iptable_mangle not found in directory /lib/modules/4.15.0-96-generic

2020-05-18 09:04:57,964 DEBG 'start-script' stdout output:
[warn] Unable to load iptable_mangle module using modprobe, trying insmod...

2020-05-18 09:04:57,965 DEBG 'start-script' stderr output:
insmod: ERROR: could not load module /lib/modules/iptable_mangle.ko: No such file or directory

2020-05-18 09:04:57,965 DEBG 'start-script' stdout output:
[warn] Unable to load iptable_mangle module, you will not be able to connect to the applications Web UI or Privoxy outside of your LAN
[info] unRAID/Ubuntu users: Please attempt to load the module by executing the following on your host: '/sbin/modprobe iptable_mangle'
[info] Synology users: Please attempt to load the module by executing the following on your host: 'insmod /lib/modules/iptable_mangle.ko'

2020-05-18 09:04:57,965 DEBG 'start-script' stdout output:
[debug] Show name servers defined for container

2020-05-18 09:04:57,966 DEBG 'start-script' stdout output:
nameserver 209.222.18.222
nameserver 37.235.1.174
nameserver 1.1.1.1
nameserver 8.8.8.8
nameserver 209.222.18.218
nameserver 37.235.1.177
nameserver 1.0.0.1
nameserver 8.8.4.4

2020-05-18 09:04:57,966 DEBG 'start-script' stdout output:
[debug] Show name resolution for VPN endpoint ca-tor-002.mullvad.net

2020-05-18 09:04:57,979 DEBG fd 11 closed, stopped monitoring <POutputDispatcher at 139726265909200 for <Subprocess at 139726266528816 with name pyrocore-script in state RUNNING> (stdout)>
2020-05-18 09:04:57,979 DEBG fd 15 closed, stopped monitoring <POutputDispatcher at 139726265970800 for <Subprocess at 139726266528816 with name pyrocore-script in state RUNNING> (stderr)>
2020-05-18 09:04:57,979 INFO exited: pyrocore-script (exit status 0; expected)
2020-05-18 09:04:57,979 DEBG received SIGCHLD indicating a child quit
2020-05-18 09:04:58,089 DEBG 'start-script' stdout output:
;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 35476
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 
;; QUESTION SECTION:
;; ca-tor-002.mullvad.net.  IN  A

;; ANSWER SECTION:
ca-tor-002.mullvad.net. 3600    IN  A   162.219.176.250

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 121 msec
;; SERVER: 209.222.18.218
;; WHEN: Mon May 18 09:04:57 2020
;; MSG SIZE  rcvd: 56

2020-05-18 09:04:58,089 DEBG 'start-script' stdout output:
[debug] Show contents of hosts file

2020-05-18 09:04:58,090 DEBG 'start-script' stdout output:
127.0.0.1   localhost
::1 localhost ip6-localhost ip6-loopback
fe00::0 ip6-localnet
ff00::0 ip6-mcastprefix
ff02::1 ip6-allnodes
ff02::2 ip6-allrouters
172.17.0.2  22b14362247f
162.219.176.250 ca-tor-002.mullvad.net

2020-05-18 09:04:58,097 DEBG 'start-script' stdout output:
[debug] Docker interface defined as eth0

2020-05-18 09:04:58,102 DEBG 'start-script' stdout output:
[debug] Docker IP defined as 172.17.0.2

2020-05-18 09:04:58,108 DEBG 'start-script' stdout output:
[debug] Docker netmask defined as 255.255.0.0

2020-05-18 09:04:58,120 DEBG 'start-script' stdout output:
[info] Docker network defined as    172.17.0.0/16

2020-05-18 09:04:58,126 DEBG 'start-script' stdout output:
[info] Adding 192.168.0.0/24 as route via docker eth0

2020-05-18 09:04:58,128 DEBG 'start-script' stdout output:
[info] ip route defined as follows...
--------------------

2020-05-18 09:04:58,130 DEBG 'start-script' stdout output:
default via 172.17.0.1 dev eth0 
172.17.0.0/16 dev eth0 proto kernel scope link src 172.17.0.2 
192.168.0.0/24 via 172.17.0.1 dev eth0 

2020-05-18 09:04:58,130 DEBG 'start-script' stdout output:
--------------------
[debug] Modules currently loaded for kernel

2020-05-18 09:04:58,134 DEBG 'start-script' stdout output:
Module                  Size  Used by
sctp                  311296  4
cpuid                  16384  0
nf_conntrack_ipv6      20480  0
nf_defrag_ipv6         20480  1 nf_conntrack_ipv6
ip6table_filter        16384  0
ip6_tables             28672  1 ip6table_filter
xt_recent              20480  0
ufs                    77824  0
qnx4                   16384  0
hfsplus               106496  0
hfs                    57344  0
minix                  32768  0
ntfs                  102400  0
msdos                  20480  0
jfs                   188416  0
xfs                  1204224  0
xt_nat                 16384  3
xt_tcpudp              16384  9
veth                   16384  0
xt_conntrack           16384  1
ipt_MASQUERADE         16384  4
nf_nat_masquerade_ipv4    16384  1 ipt_MASQUERADE
nf_conntrack_netlink    40960  0
nfnetlink              16384  2 nf_conntrack_netlink
xfrm_user              32768  1
xfrm_algo              16384  1 xfrm_user
xt_addrtype            16384  2
iptable_filter         16384  1
iptable_nat            16384  1
nf_conntrack_ipv4      16384  9
nf_defrag_ipv4         16384  1 nf_conntrack_ipv4
nf_nat_ipv4            16384  1 iptable_nat
nf_nat                 32768  3 nf_nat_masquerade_ipv4,nf_nat_ipv4,xt_nat
nf_conntrack          131072  9 xt_conntrack,nf_nat_masquerade_ipv4,nf_conntrack_ipv6,nf_conntrack_ipv4,nf_nat,ipt_MASQUERADE,nf_nat_ipv4,xt_nat,nf_conntrack_netlink
br_netfilter           24576  0
bridge                155648  1 br_netfilter
stp                    16384  1 bridge
llc                    16384  2 bridge,stp
aufs                  241664  0
overlay                77824  1
ipmi_ssif              32768  0
intel_rapl             20480  0
x86_pkg_temp_thermal    16384  0
intel_powerclamp       16384  0
kvm_intel             217088  0
kvm                   610304  1 kvm_intel
irqbypass              16384  1 kvm
joydev                 24576  0
input_leds             16384  0
intel_cstate           20480  0
intel_rapl_perf        16384  0
shpchp                 36864  0
mac_hid                16384  0
ipmi_si                57344  0
lpc_ich                24576  0
ie31200_edac           16384  0
ipmi_devintf           20480  0
ipmi_msghandler        53248  3 ipmi_devintf,ipmi_si,ipmi_ssif
sch_fq_codel           20480  3
ib_iser                49152  0
rdma_cm                61440  1 ib_iser
iw_cm                  45056  1 rdma_cm
ib_cm                  53248  1 rdma_cm
ib_core               221184  4 rdma_cm,iw_cm,ib_iser,ib_cm
iscsi_tcp              20480  0
libiscsi_tcp           20480  1 iscsi_tcp
libiscsi               53248  3 libiscsi_tcp,iscsi_tcp,ib_iser
scsi_transport_iscsi    98304  3 iscsi_tcp,ib_iser,libiscsi
nct6775                57344  0
w83627ehf              45056  0
hwmon_vid              16384  2 w83627ehf,nct6775
jc42                   16384  0
coretemp               16384  0
ip_tables              28672  2 iptable_filter,iptable_nat
x_tables               40960  10 ip6table_filter,xt_conntrack,iptable_filter,xt_tcpudp,ipt_MASQUERADE,xt_addrtype,xt_recent,xt_nat,ip6_tables,ip_tables
autofs4                40960  2
btrfs                1134592  0
zstd_compress         163840  1 btrfs
raid10                 53248  0
raid456               147456  0
async_raid6_recov      20480  1 raid456
async_memcpy           16384  2 raid456,async_raid6_recov
async_pq               16384  2 raid456,async_raid6_recov
async_xor              16384  3 async_pq,raid456,async_raid6_recov
async_tx               16384  5 async_pq,async_memcpy,async_xor,raid456,async_raid6_recov
xor                    24576  2 async_xor,btrfs
raid6_pq              114688  4 async_pq,btrfs,raid456,async_raid6_recov
libcrc32c              16384  5 nf_conntrack,nf_nat,xfs,raid456,sctp
raid0                  20480  0
multipath              16384  0
linear                 16384  0
raid1                  40960  4
mgag200                45056  1
i2c_algo_bit           16384  1 mgag200
ttm                   106496  1 mgag200
crct10dif_pclmul       16384  0
drm_kms_helper        172032  1 mgag200
hid_generic            1
2020-05-18 09:04:58,134 DEBG 'start-script' stdout output:
6384  0
crc32_pclmul           16384  0
e1000e                249856  0
syscopyarea            16384  1 drm_kms_helper
sysfillrect            16384  1 drm_kms_helper
sysimgblt              16384  1 drm_kms_helper
fb_sys_fops            16384  1 drm_kms_helper
ghash_clmulni_intel    16384  0
usbhid                 49152  0
ahci                   40960  9
ptp                    20480  1 e1000e
hid                   118784  2 usbhid,hid_generic
drm                   401408  4 drm_kms_helper,mgag200,ttm
cryptd                 24576  1 ghash_clmulni_intel
libahci                32768  1 ahci
pps_core               20480  1 ptp
video                  45056  0

2020-05-18 09:04:58,355 DEBG 'start-script' stdout output:
[info] iptables defined as follows...
--------------------

2020-05-18 09:04:58,357 DEBG 'start-script' stdout output:
-P INPUT DROP
-P FORWARD DROP
-P OUTPUT DROP
-A INPUT -s 172.17.0.0/16 -d 172.17.0.0/16 -j ACCEPT
-A INPUT -i eth0 -p udp -m udp --sport 1302 -j ACCEPT
-A INPUT -i eth0 -p tcp -m tcp --dport 9080 -j ACCEPT
-A INPUT -i eth0 -p tcp -m tcp --sport 9080 -j ACCEPT
-A INPUT -i eth0 -p tcp -m tcp --dport 9443 -j ACCEPT
-A INPUT -i eth0 -p tcp -m tcp --sport 9443 -j ACCEPT
-A INPUT -s 192.168.0.0/24 -i eth0 -p tcp -m tcp --dport 5000 -j ACCEPT
-A INPUT -p icmp -m icmp --icmp-type 0 -j ACCEPT
-A INPUT -i lo -j ACCEPT
-A INPUT -i tun0 -j ACCEPT
-A OUTPUT -s 172.17.0.0/16 -d 172.17.0.0/16 -j ACCEPT
-A OUTPUT -o eth0 -p udp -m udp --dport 1302 -j ACCEPT
-A OUTPUT -o eth0 -p tcp -m tcp --dport 9080 -j ACCEPT
-A OUTPUT -o eth0 -p tcp -m tcp --sport 9080 -j ACCEPT
-A OUTPUT -o eth0 -p tcp -m tcp --dport 9443 -j ACCEPT
-A OUTPUT -o eth0 -p tcp -m tcp --sport 9443 -j ACCEPT
-A OUTPUT -d 192.168.0.0/24 -o eth0 -p tcp -m tcp --sport 5000 -j ACCEPT
-A OUTPUT -p icmp -m icmp --icmp-type 8 -j ACCEPT
-A OUTPUT -o lo -j ACCEPT
-A OUTPUT -o tun0 -j ACCEPT

2020-05-18 09:04:58,359 DEBG 'start-script' stdout output:
--------------------

2020-05-18 09:04:58,360 DEBG 'start-script' stdout output:
[debug] OpenVPN command line:- /usr/bin/openvpn --daemon --reneg-sec 0 --mute-replay-warnings --auth-nocache --setenv VPN_PROV 'custom' --setenv DEBUG 'true' --setenv VPN_DEVICE_TYPE 'tun0' --setenv VPN_ENABLED 'yes' --setenv VPN_REMOTE 'ca-tor-002.mullvad.net' --setenv APPLICATION 'rtorrent' --script-security 2 --writepid /root/openvpn.pid --remap-usr1 SIGHUP --log-append /dev/stdout --pull-filter ignore 'up' --pull-filter ignore 'down' --pull-filter ignore 'route-ipv6' --pull-filter ignore 'ifconfig-ipv6' --pull-filter ignore 'tun-ipv6' --pull-filter ignore 'persist-tun' --pull-filter ignore 'reneg-sec' --up /root/openvpnup.sh --up-delay --up-restart --remote 162.219.176.250 1302 udp --remote-random --cd /config/openvpn --config '/config/openvpn/mullvad_ca_tor.ovpn'
[info] Starting OpenVPN...

2020-05-18 09:04:58,384 DEBG 'start-script' stdout output:
Mon May 18 09:04:58 2020 WARNING: file 'mullvad_userpass.txt' is group or others accessible
Mon May 18 09:04:58 2020 OpenVPN 2.4.8 [git:makepkg/3976acda9bf10b5e+] x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jan  3 2020
Mon May 18 09:04:58 2020 library versions: OpenSSL 1.1.1d  10 Sep 2019, LZO 2.10

2020-05-18 09:04:58,385 DEBG 'start-script' stdout output:
[info] OpenVPN started

2020-05-18 09:04:58,385 DEBG 'start-script' stdout output:
Mon May 18 09:04:58 2020 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts

2020-05-18 09:04:58,386 DEBG 'start-script' stdout output:
Mon May 18 09:04:58 2020 TCP/UDP: Preserving recently used remote address: [AF_INET]162.219.176.250:1302

2020-05-18 09:04:58,387 DEBG 'start-script' stdout output:
Mon May 18 09:04:58 2020 Socket Buffers: R=[212992->425984] S=[212992->425984]
Mon May 18 09:04:58 2020 UDP link local: (not bound)
Mon May 18 09:04:58 2020 UDP link remote: [AF_INET]162.219.176.250:1302

2020-05-18 09:05:58,843 DEBG 'start-script' stdout output:
Mon May 18 09:05:58 2020 [UNDEF] Inactivity timeout (--ping-restart), restarting

2020-05-18 09:05:58,843 DEBG 'start-script' stdout output:
Mon May 18 09:05:58 2020 SIGHUP[soft,ping-restart] received, process restarting

2020-05-18 09:05:58,844 DEBG 'start-script' stdout output:
Mon May 18 09:05:58 2020 WARNING: file 'mullvad_userpass.txt' is group or others accessible
Mon May 18 09:05:58 2020 OpenVPN 2.4.8 [git:makepkg/3976acda9bf10b5e+] x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jan  3 2020
Mon May 18 09:05:58 2020 library versions: OpenSSL 1.1.1d  10 Sep 2019, LZO 2.10
Mon May 18 09:05:58 2020 Restart pause, 5 second(s)

2020-05-18 09:06:03,844 DEBG 'start-script' stdout output:
Mon May 18 09:06:03 2020 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts

2020-05-18 09:06:03,844 DEBG 'start-script' stdout output:
Mon May 18 09:06:03 2020 TCP/UDP: Preserving recently used remote address: [AF_INET]162.219.176.250:1302

2020-05-18 09:06:03,845 DEBG 'start-script' stdout output:
Mon May 18 09:06:03 2020 Socket Buffers: R=[212992->425984] S=[212992->425984]
Mon May 18 09:06:03 2020 UDP link local: (not bound)
Mon May 18 09:06:03 2020 UDP link remote: [AF_INET]162.219.176.250:1302

2020-05-18 09:06:48,898 WARN received SIGTERM indicating exit request
2020-05-18 09:06:48,898 DEBG killing watchdog-script (pid 203) with signal SIGTERM
2020-05-18 09:06:48,898 INFO waiting for logrotate-script, rutorrent-script, start-script, watchdog-script to die
2020-05-18 09:06:48,947 DEBG fd 26 closed, stopped monitoring <POutputDispatcher at 139726265908672 for <Subprocess at 139726265908624 with name watchdog-script in state STOPPING> (stdout)>
2020-05-18 09:06:48,947 DEBG fd 30 closed, stopped monitoring <POutputDispatcher at 139726265972096 for <Subprocess at 139726265908624 with name watchdog-script in state STOPPING> (stderr)>
2020-05-18 09:06:48,947 INFO stopped: watchdog-script (terminated by SIGTERM)
2020-05-18 09:06:48,947 DEBG received SIGCHLD indicating a child quit
2020-05-18 09:06:48,947 DEBG killing start-script (pid 202) with signal SIGTERM
2020-05-18 09:06:49,949 DEBG fd 21 closed, stopped monitoring <POutputDispatcher at 139726265908480 for <Subprocess at 139726265908432 with name start-script in state STOPPING> (stdout)>
2020-05-18 09:06:49,949 DEBG fd 25 closed, stopped monitoring <POutputDispatcher at 139726265971520 for <Subprocess at 139726265908432 with name start-script in state STOPPING> (stderr)>
2020-05-18 09:06:49,949 INFO stopped: start-script (terminated by SIGTERM)
2020-05-18 09:06:49,949 DEBG received SIGCHLD indicating a child quit
2020-05-18 09:06:49,949 DEBG killing rutorrent-script (pid 201) with signal SIGTERM
2020-05-18 09:06:50,015 DEBG fd 16 closed, stopped monitoring <POutputDispatcher at 139726265908288 for <Subprocess at 139726265908240 with name rutorrent-script in state STOPPING> (stdout)>
2020-05-18 09:06:50,015 DEBG fd 20 closed, stopped monitoring <POutputDispatcher at 139726265971232 for <Subprocess at 139726265908240 with name rutorrent-script in state STOPPING> (stderr)>
2020-05-18 09:06:50,015 INFO stopped: rutorrent-script (terminated by SIGTERM)
2020-05-18 09:06:50,015 DEBG received SIGCHLD indicating a child quit
2020-05-18 09:06:51,017 DEBG killing logrotate-script (pid 199) with signal SIGTERM
2020-05-18 09:06:51,097 DEBG fd 8 closed, stopped monitoring <POutputDispatcher at 139726266378224 for <Subprocess at 139726266378800 with name logrotate-script in state STOPPING> (stdout)>
2020-05-18 09:06:51,098 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 139726265908816 for <Subprocess at 139726266378800 with name logrotate-script in state STOPPING> (stderr)>
2020-05-18 09:06:51,098 INFO stopped: logrotate-script (terminated by SIGTERM)
2020-05-18 09:06:51,098 DEBG received SIGCHLD indicating a child quit

It just sits there, restarting after the timeout, but does nothing else.

The command I'm using to start the container:

docker run -d \
    --restart unless-stopped \
    --cap-add=NET_ADMIN \
    -p 7080:9080 \
    -p 7443:9443 \
    -p 8118:8118 \
    --name=tdrs-rt \
    -v /media/RomeoBravo/tdrs-rt:/data \
    -v /home/papkee/docker-seedbox/rtorrent/config:/config \
    -v /home/papkee/docker-seedbox/rtorrent/themes:/usr/share/webapps/rutorrent/plugins/theme/themes \
    -v /etc/localtime:/etc/localtime:ro \
    -e VPN_ENABLED=yes \
    -e VPN_PROV=custom \
    -e STRICT_PORT_FORWARD=yes \
    -e ENABLE_PRIVOXY=no \
    -e ENABLE_AUTODL_IRSSI=no \
    -e ENABLE_RPC2=yes \
    -e ENABLE_RPC2_AUTH=yes \
    -e ENABLE_WEBUI_AUTH=yes \
    -e RPC2_USER=<redacted> \
    -e RPC2_PASS=<redacted> \
    -e WEBUI_USER=<redacted> \
    -e WEBUI_PASS=<redacted> \
    -e LAN_NETWORK=192.168.0.0/24 \
    -e NAME_SERVERS=209.222.18.222,37.235.1.174,1.1.1.1,8.8.8.8,209.222.18.218,37.235.1.177,1.0.0.1,8.8.4.4 \
    -e DEBUG=false\
    -e PHP_TZ=America/Chicago \
    -e UMASK=002 \
    -e PUID=1003 \
    -e PGID=1003 \
    binhex/arch-rtorrentvpn
W3AXL commented 4 years ago

Redownloaded my Mullvad openvpn config, and made sure permissions were consistent across all files included in the rtorrent/config directory (same uid and gid as the ones specified when starting the container). Container seems to start fine now.