I am having a hard time trying to understand a certain behavior of OpenVPN:
I have a raspberry pi (host13 in the logs) where openvpn is installed (client) connected to an ubuntu server (IP: 97.98.99.100).
It happens that sometimes when I restart the openvpn service (sudo systemctl restart openvpn), a second interface (tun1) is created. Using "ps" command, I can see that I have 2 processes (each one responsible for one interface).
If we go through the logs:
- line 1: I stop the vpn service. host13 receives a SIGTERM (from the systemctl restart command) at line 11 --> It restarts the openvpn process
- line 17: process ovpn with ID [19767] is spawned, and reads the client config
- line 20: the process [19767] ends and spawns? process [19773] which will open interface tun0 (line 80)
In parallel:
- line 30: another ovpn process [19772] is spawned and reads the client config
- line 33: this process ends, but spawns? process [19774] which is responsible for opening interface tun1 (line 140)
Things even get worse when I restart the openvpn service again (it creates tun2, and so forth)
This behavior is NOT systematic. But when it happens, it causes the clients to lose connection with the server.
My question: is this a normal behavior? can someone explain how does it happen? and more importantly, is there an option that we can put in the server/client conf files that can prevent it?
Thanks for your help
I am using OpenVPN 2.4.7 on server, and 2.4.0 on clients
logs
Jul 20 16:44:51 host13 systemd[1]: Stopping LSB: Openvpn VPN service...
Jul 20 16:44:51 host13 systemd[1]: Stopping OpenVPN connection to host13...
Jul 20 16:44:51 host13 ovpn-host13[19658]: event_wait : Interrupted system call (code=4)
Jul 20 16:44:51 host13 ovpn-host13[19658]: SIGTERM received, sending exit notification to peer
Jul 20 16:44:51 host13 ovpn-host13[19658]: event_wait : Interrupted system call (code=4)
Jul 20 16:44:51 host13 ovpn-host13[19658]: /sbin/ip route del 97.98.99.100/32
Jul 20 16:44:51 host13 ovpn-host13[19658]: /sbin/ip route del 0.0.0.0/1
Jul 20 16:44:51 host13 ovpn-host13[19658]: /sbin/ip route del 128.0.0.0/1
Jul 20 16:44:51 host13 ovpn-host13[19658]: Closing TUN/TAP interface
Jul 20 16:44:51 host13 ovpn-host13[19658]: /sbin/ip addr del dev tun0 10.8.0.26/24
Jul 20 16:44:51 host13 ovpn-host13[19658]: SIGTERM[hard,] received, process exiting
Jul 20 16:44:51 host13 openvpn[19737]: Stopping virtual private network daemon: host13.
Jul 20 16:44:51 host13 systemd[1]: Stopped LSB: Openvpn VPN service.
Jul 20 16:44:51 host13 systemd[1]: Starting LSB: Openvpn VPN service...
Jul 20 16:44:51 host13 systemd[1]: Stopped OpenVPN connection to host13.
Jul 20 16:44:51 host13 systemd[1]: Starting OpenVPN connection to host13...
Jul 20 16:44:52 host13 ovpn-host13[19767]: Unrecognized option or missing or extra parameter(s) in /etc/openvpn/host13.conf:19: block-outside-dns (2.4.0)
Jul 20 16:44:52 host13 ovpn-host13[19767]: OpenVPN 2.4.0 arm-unknown-linux-gnueabihf [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 29 2022
Jul 20 16:44:52 host13 ovpn-host13[19767]: library versions: OpenSSL 1.0.2u 20 Dec 2019, LZO 2.08
Jul 20 16:44:52 host13 systemd[1]: openvpn@host13.service: PID file /run/openvpn/host13.pid not readable (yet?) after start: No such file or directory
Jul 20 16:44:52 host13 ovpn-host13[19773]: Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 20 16:44:52 host13 ovpn-host13[19773]: Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 20 16:44:52 host13 ovpn-host13[19773]: Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 20 16:44:52 host13 ovpn-host13[19773]: Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 20 16:44:52 host13 ovpn-host13[19773]: TCP/UDP: Preserving recently used remote address: [AF_INET]97.98.99.100:1194
Jul 20 16:44:52 host13 ovpn-host13[19773]: Socket Buffers: R=[163840->163840] S=[163840->163840]
Jul 20 16:44:52 host13 ovpn-host13[19773]: UDP link local: (not bound)
Jul 20 16:44:52 host13 ovpn-host13[19773]: UDP link remote: [AF_INET]97.98.99.100:1194
Jul 20 16:44:52 host13 openvpn[19756]: Starting virtual private network daemon: host13.
Jul 20 16:44:52 host13 ovpn-host13[19772]: Unrecognized option or missing or extra parameter(s) in /etc/openvpn/host13.conf:19: block-outside-dns (2.4.0)
Jul 20 16:44:52 host13 ovpn-host13[19772]: OpenVPN 2.4.0 arm-unknown-linux-gnueabihf [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 29 2022
Jul 20 16:44:52 host13 ovpn-host13[19772]: library versions: OpenSSL 1.0.2u 20 Dec 2019, LZO 2.08
Jul 20 16:44:52 host13 ovpn-host13[19774]: Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 20 16:44:52 host13 ovpn-host13[19774]: Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 20 16:44:52 host13 ovpn-host13[19774]: Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 20 16:44:52 host13 ovpn-host13[19774]: Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 20 16:44:52 host13 ovpn-host13[19774]: TCP/UDP: Preserving recently used remote address: [AF_INET]97.98.99.100:1194
Jul 20 16:44:52 host13 ovpn-host13[19774]: Socket Buffers: R=[163840->163840] S=[163840->163840]
Jul 20 16:44:52 host13 ovpn-host13[19774]: UDP link local: (not bound)
Jul 20 16:44:52 host13 ovpn-host13[19774]: UDP link remote: [AF_INET]97.98.99.100:1194
Jul 20 16:44:52 host13 systemd[1]: Started OpenVPN connection to host13.
Jul 20 16:44:52 host13 systemd[1]: Started LSB: Openvpn VPN service.
Jul 20 16:44:52 host13 ovpn-host13[19773]: TLS: Initial packet from [AF_INET]97.98.99.100:1194, sid=4577d9dc 7cb06a6d
Jul 20 16:44:52 host13 ovpn-host13[19774]: TLS: Initial packet from [AF_INET]97.98.99.100:1194, sid=7b6acf4c 934a0316
Jul 20 16:44:52 host13 ovpn-host13[19774]: VERIFY OK: depth=1, CN=cn_taUIhV5xJA90gpW2
Jul 20 16:44:52 host13 ovpn-host13[19773]: VERIFY OK: depth=1, CN=cn_taUIhV5xJA90gpW2
Jul 20 16:44:52 host13 ovpn-host13[19774]: Validating certificate key usage
Jul 20 16:44:52 host13 ovpn-host13[19774]: ++ Certificate has key usage 00a0, expects 00a0
Jul 20 16:44:52 host13 ovpn-host13[19774]: VERIFY KU OK
Jul 20 16:44:52 host13 ovpn-host13[19774]: Validating certificate extended key usage
Jul 20 16:44:52 host13 ovpn-host13[19774]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Jul 20 16:44:52 host13 ovpn-host13[19774]: VERIFY EKU OK
Jul 20 16:44:52 host13 ovpn-host13[19774]: VERIFY X509NAME OK: CN=server_ckfc0jZ77S88Saot
Jul 20 16:44:52 host13 ovpn-host13[19774]: VERIFY OK: depth=0, CN=server_ckfc0jZ77S88Saot
Jul 20 16:44:52 host13 ovpn-host13[19773]: Validating certificate key usage
Jul 20 16:44:52 host13 ovpn-host13[19773]: ++ Certificate has key usage 00a0, expects 00a0
Jul 20 16:44:52 host13 ovpn-host13[19773]: VERIFY KU OK
Jul 20 16:44:52 host13 ovpn-host13[19773]: Validating certificate extended key usage
Jul 20 16:44:52 host13 ovpn-host13[19773]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Jul 20 16:44:52 host13 ovpn-host13[19773]: VERIFY EKU OK
Jul 20 16:44:52 host13 ovpn-host13[19773]: VERIFY X509NAME OK: CN=server_ckfc0jZ77S88Saot
Jul 20 16:44:52 host13 ovpn-host13[19773]: VERIFY OK: depth=0, CN=server_ckfc0jZ77S88Saot
Jul 20 16:44:52 host13 ovpn-host13[19774]: Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-ECDSA-AES128-GCM-SHA256
Jul 20 16:44:52 host13 ovpn-host13[19774]: [server_ckfc0jZ77S88Saot] Peer Connection Initiated with [AF_INET]97.98.99.100:1194
Jul 20 16:44:52 host13 ovpn-host13[19773]: Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-ECDSA-AES128-GCM-SHA256
Jul 20 16:44:52 host13 ovpn-host13[19773]: [server_ckfc0jZ77S88Saot] Peer Connection Initiated with [AF_INET]97.98.99.100:1194
Jul 20 16:44:53 host13 ovpn-host13[19773]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:44:53 host13 ovpn-host13[19773]: PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 127.0.0.1,dhcp-option DNS 8.8.8.8,dhcp-option DNS 4.4.4.4,redirect-gateway def1 bypass-dhcp,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.26 255.255.255.0,peer-id 2,cipher AES-128-GCM'
Jul 20 16:44:53 host13 ovpn-host13[19773]: OPTIONS IMPORT: timers and/or timeouts modified
Jul 20 16:44:53 host13 ovpn-host13[19773]: OPTIONS IMPORT: --ifconfig/up options modified
Jul 20 16:44:53 host13 ovpn-host13[19773]: OPTIONS IMPORT: route options modified
Jul 20 16:44:53 host13 ovpn-host13[19773]: OPTIONS IMPORT: route-related options modified
Jul 20 16:44:53 host13 ovpn-host13[19773]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Jul 20 16:44:53 host13 ovpn-host13[19773]: OPTIONS IMPORT: peer-id set
Jul 20 16:44:53 host13 ovpn-host13[19773]: OPTIONS IMPORT: adjusting link_mtu to 1624
Jul 20 16:44:53 host13 ovpn-host13[19773]: OPTIONS IMPORT: data channel crypto options modified
Jul 20 16:44:53 host13 ovpn-host13[19773]: Data Channel Encrypt: Cipher 'AES-128-GCM' initialized with 128 bit key
Jul 20 16:44:53 host13 ovpn-host13[19773]: Data Channel Decrypt: Cipher 'AES-128-GCM' initialized with 128 bit key
Jul 20 16:44:53 host13 ovpn-host13[19773]: ROUTE_GATEWAY ON_LINK IFACE=ppp0 HWADDR=00:00:00:00:00:00
Jul 20 16:44:53 host13 ovpn-host13[19773]: TUN/TAP device tun0 opened
Jul 20 16:44:53 host13 ovpn-host13[19773]: TUN/TAP TX queue length set to 100
Jul 20 16:44:53 host13 ovpn-host13[19773]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Jul 20 16:44:53 host13 ovpn-host13[19773]: /sbin/ip link set dev tun0 up mtu 1500
Jul 20 16:44:53 host13 ovpn-host13[19773]: /sbin/ip addr add dev tun0 10.8.0.26/24 broadcast 10.8.0.255
Jul 20 16:44:53 host13 ovpn-host13[19773]: /sbin/ip route add 97.98.99.100/32 dev ppp0
Jul 20 16:44:53 host13 ovpn-host13[19773]: /sbin/ip route add 0.0.0.0/1 via 10.8.0.1
Jul 20 16:44:53 host13 ovpn-host13[19773]: /sbin/ip route add 128.0.0.0/1 via 10.8.0.1
Jul 20 16:44:53 host13 ovpn-host13[19773]: Initialization Sequence Completed
Jul 20 16:44:53 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:44:59 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:01 host13 CRON[19872]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jul 20 16:45:01 host13 CRON[19873]: (root) CMD (/sbin/fake-hwclock save)
Jul 20 16:45:04 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:09 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:14 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:19 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:24 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:29 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:35 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:40 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:45 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:50 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:45:55 host13 ovpn-host13[19774]: No reply from server after sending 12 push requests
Jul 20 16:45:55 host13 ovpn-host13[19774]: SIGUSR1[soft,no-push-reply] received, process restarting
Jul 20 16:45:55 host13 ovpn-host13[19774]: Restart pause, 5 second(s)
Jul 20 16:46:00 host13 ovpn-host13[19774]: Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 20 16:46:00 host13 ovpn-host13[19774]: Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 20 16:46:00 host13 ovpn-host13[19774]: Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 20 16:46:00 host13 ovpn-host13[19774]: Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 20 16:46:00 host13 ovpn-host13[19774]: TCP/UDP: Preserving recently used remote address: [AF_INET]97.98.99.100:1194
Jul 20 16:46:00 host13 ovpn-host13[19774]: Socket Buffers: R=[163840->163840] S=[163840->163840]
Jul 20 16:46:00 host13 ovpn-host13[19774]: UDP link local: (not bound)
Jul 20 16:46:00 host13 ovpn-host13[19774]: UDP link remote: [AF_INET]97.98.99.100:1194
Jul 20 16:46:00 host13 ovpn-host13[19774]: TLS: Initial packet from [AF_INET]97.98.99.100:1194, sid=e65cdf80 cd2a1bf6
Jul 20 16:46:00 host13 ovpn-host13[19774]: VERIFY OK: depth=1, CN=cn_taUIhV5xJA90gpW2
Jul 20 16:46:00 host13 ovpn-host13[19774]: Validating certificate key usage
Jul 20 16:46:00 host13 ovpn-host13[19774]: ++ Certificate has key usage 00a0, expects 00a0
Jul 20 16:46:00 host13 ovpn-host13[19774]: VERIFY KU OK
Jul 20 16:46:00 host13 ovpn-host13[19774]: Validating certificate extended key usage
Jul 20 16:46:00 host13 ovpn-host13[19774]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Jul 20 16:46:00 host13 ovpn-host13[19774]: VERIFY EKU OK
Jul 20 16:46:00 host13 ovpn-host13[19774]: VERIFY X509NAME OK: CN=server_ckfc0jZ77S88Saot
Jul 20 16:46:00 host13 ovpn-host13[19774]: VERIFY OK: depth=0, CN=server_ckfc0jZ77S88Saot
Jul 20 16:46:01 host13 ovpn-host13[19774]: Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-ECDSA-AES128-GCM-SHA256
Jul 20 16:46:01 host13 ovpn-host13[19774]: [server_ckfc0jZ77S88Saot] Peer Connection Initiated with [AF_INET]97.98.99.100:1194
Jul 20 16:46:01 host13 CRON[20231]: (root) CMD (/sbin/fake-hwclock save)
Jul 20 16:46:02 host13 ovpn-host13[19774]: SENT CONTROL [server_ckfc0jZ77S88Saot]: 'PUSH_REQUEST' (status=1)
Jul 20 16:46:02 host13 ovpn-host13[19774]: PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 127.0.0.1,dhcp-option DNS 8.8.8.8,dhcp-option DNS 4.4.4.4,redirect-gateway def1 bypass-dhcp,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.26 255.255.255.0,peer-id 13,cipher AES-128-GCM'
Jul 20 16:46:02 host13 ovpn-host13[19774]: OPTIONS IMPORT: timers and/or timeouts modified
Jul 20 16:46:02 host13 ovpn-host13[19774]: OPTIONS IMPORT: --ifconfig/up options modified
Jul 20 16:46:02 host13 ovpn-host13[19774]: OPTIONS IMPORT: route options modified
Jul 20 16:46:02 host13 ovpn-host13[19774]: OPTIONS IMPORT: route-related options modified
Jul 20 16:46:02 host13 ovpn-host13[19774]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Jul 20 16:46:02 host13 ovpn-host13[19774]: OPTIONS IMPORT: peer-id set
Jul 20 16:46:02 host13 ovpn-host13[19774]: OPTIONS IMPORT: adjusting link_mtu to 1624
Jul 20 16:46:02 host13 ovpn-host13[19774]: OPTIONS IMPORT: data channel crypto options modified
Jul 20 16:46:02 host13 ovpn-host13[19774]: Data Channel Encrypt: Cipher 'AES-128-GCM' initialized with 128 bit key
Jul 20 16:46:02 host13 ovpn-host13[19774]: Data Channel Decrypt: Cipher 'AES-128-GCM' initialized with 128 bit key
Jul 20 16:46:02 host13 ovpn-host13[19774]: ROUTE_GATEWAY ON_LINK IFACE=ppp0 HWADDR=00:00:00:00:00:00
Jul 20 16:46:02 host13 ovpn-host13[19774]: TUN/TAP device tun1 opened
Jul 20 16:46:02 host13 ovpn-host13[19774]: TUN/TAP TX queue length set to 100
Jul 20 16:46:02 host13 ovpn-host13[19774]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Jul 20 16:46:02 host13 ovpn-host13[19774]: /sbin/ip link set dev tun1 up mtu 1500
Jul 20 16:46:02 host13 ovpn-host13[19774]: /sbin/ip addr add dev tun1 10.8.0.26/24 broadcast 10.8.0.255
Jul 20 16:46:02 host13 ovpn-host13[19774]: /sbin/ip route add 97.98.99.100/32 dev ppp0
Jul 20 16:46:02 host13 ovpn-host13[19774]: ERROR: Linux route add command failed: external program exited with error status: 2
Jul 20 16:46:02 host13 ovpn-host13[19774]: /sbin/ip route add 0.0.0.0/1 via 10.8.0.1
Jul 20 16:46:02 host13 ovpn-host13[19774]: ERROR: Linux route add command failed: external program exited with error status: 2
Jul 20 16:46:02 host13 ovpn-host13[19774]: /sbin/ip route add 128.0.0.0/1 via 10.8.0.1
Jul 20 16:46:02 host13 ovpn-host13[19774]: ERROR: Linux route add command failed: external program exited with error status: 2
Jul 20 16:46:02 host13 ovpn-host13[19774]: Initialization Sequence Completed
server conf
port 1194
proto udp
dev tun
user nobody
group nogroup
persist-key
persist-tun
keepalive 10 120
topology subnet
server 10.8.0.0 255.255.255.0
ifconfig-pool-persist ipp.txt
push "dhcp-option DNS 127.0.0.1"
push "dhcp-option DNS 8.8.8.8"
push "dhcp-option DNS 4.4.4.4"
push "redirect-gateway def1 bypass-dhcp"
dh none
ecdh-curve prime256v1
tls-crypt tls-crypt.key
crl-verify crl.pem
ca ca.crt
cert server_ckfc0jZ77S88Saot.crt
key server_ckfc0jZ77S88Saot.key
auth SHA256
cipher AES-128-GCM
ncp-ciphers AES-128-GCM
tls-server
tls-version-min 1.2
tls-cipher TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256
client-config-dir /etc/openvpn/ccd
status /var/log/openvpn/status.log
verb 3
management localhost 7505
client conf
client
proto udp
explicit-exit-notify
remote 97.98.99.100 1194
dev tun
resolv-retry infinite
nobind
persist-key
persist-tun
remote-cert-tls server
verify-x509-name server_ckfc0jZ77S88Saot name
auth SHA256
auth-nocache
cipher AES-128-GCM
tls-client
tls-version-min 1.2
tls-cipher TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256
ignore-unknown-option block-outside-dns
setenv opt block-outside-dns # Prevent Windows 10 DNS leak
verb 3