Hello Balena Support,
We are using iot-gate-imx8 as platform for our product. Currently we are having issue that Balena VPN keeps dis-connection every few minutes and then connect back. We verified that internet is reachable via cellular network. Please see the journalctl logs when vpn dis-connects (there is also ping request which verifies the connectivity). We are looking for some clues on what possibly could cause vpn to dis-connect. Please let me know if you need additional info.
root@47e7444:~# uname -a
Linux 47e7444 5.4.24-iot-gate-imx8-2.4 #1 SMP PREEMPT Sat May 30 07:25:46 UTC 2020 aarch64 aarch64 aarch64 GNU/Linux
HOST OS Version: balenaOS 2.85.2+rev1
64 bytes from 142.251.46.174: seq=321 ttl=114 time=33.020 ms
64 bytes from 142.251.46.174: seq=322 ttl=114 time=34.318 ms
Feb 17 23:22:24 47e7444 openvpn[23564]: Thu Feb 17 23:22:24 2022 Connection reset, restarting [0]
Feb 17 23:22:24 47e7444 openvpn[23564]: Thu Feb 17 23:22:24 2022 /etc/openvpn-misc/downscript.sh resin-vpn 1500 1555 10.240.50.10 52.4.252.97 r
estart
Feb 17 23:22:24 47e7444 openvpn[23564]: Thu Feb 17 23:22:24 2022 SIGUSR1[soft,connection-reset] received, process restarting
Feb 17 23:22:24 47e7444 aac03a07c25b[1326]: [info] VPN connection is not active.
Feb 17 23:22:24 47e7444 balena-supervisor[2622]: [info] VPN connection is not active.
Feb 17 23:22:24 47e7444 openvpn[23564]: Thu Feb 17 23:22:24 2022 Restart pause, 5 second(s)
64 bytes from 142.251.46.174: seq=323 ttl=114 time=34.478 ms
64 bytes from 142.251.46.174: seq=324 ttl=114 time=40.403 ms
64 bytes from 142.251.46.174: seq=325 ttl=114 time=35.465 ms
Feb 17 23:22:27 47e7444 aac03a07c25b[1326]: [api] GET /v1/healthy 200 - 7.652 ms
Feb 17 23:22:27 47e7444 balena-supervisor[2622]: [api] GET /v1/healthy 200 - 7.652 ms
64 bytes from 142.251.46.174: seq=326 ttl=114 time=50.400 ms
64 bytes from 142.251.46.174: seq=327 ttl=114 time=32.778 ms
Feb 17 23:22:29 47e7444 openvpn[23564]: Thu Feb 17 23:22:29 2022 NOTE: the current --script-security setting may allow this configuration to ca
ll user-defined scripts
Feb 17 23:22:29 47e7444 openvpn[23564]: Thu Feb 17 23:22:29 2022 TCP/UDP: Preserving recently used remote address: [AF_INET]3.227.28.93:443
Feb 17 23:22:29 47e7444 openvpn[23564]: Thu Feb 17 23:22:29 2022 Socket Buffers: R=[131072->131072] S=[16384->16384]
Feb 17 23:22:29 47e7444 openvpn[23564]: Thu Feb 17 23:22:29 2022 Attempting to establish TCP connection with [AF_INET]3.227.28.93:443 [nonblock
]
64 bytes from 142.251.46.174: seq=328 ttl=114 time=42.463 ms
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 TCP connection established with [AF_INET]3.227.28.93:443
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 Socket flags: TCP_NODELAY=1 succeeded
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 TCP_CLIENT link local: (not bound)
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 TCP_CLIENT link remote: [AF_INET]3.227.28.93:443
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 TLS: Initial packet from [AF_INET]3.227.28.93:443, sid=e430b755 de674d60
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 VERIFY OK: depth=1, C=AU, ST=Some-State, O=Internet Widgits Pty Ltd
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 VERIFY KU OK
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 Validating certificate extended key usage
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Se
rver Authentication
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 VERIFY EKU OK
Feb 17 23:22:30 47e7444 openvpn[23564]: Thu Feb 17 23:22:30 2022 VERIFY OK: depth=0, C=US, ST=WA, O=balena.io, OU=balenaCloud, CN=vpn.balena-cl
oud.com
Feb 17 23:22:31 47e7444 openvpn[23564]: Thu Feb 17 23:22:31 2022 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Feb 17 23:22:31 47e7444 openvpn[23564]: Thu Feb 17 23:22:31 2022 [vpn.balena-cloud.com] Peer Connection Initiated with [AF_INET]3.227.28.93:443
64 bytes from 142.251.46.174: seq=329 ttl=114 time=34.643 ms
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 SENT CONTROL [vpn.balena-cloud.com]: 'PUSH_REQUEST' (status=1)
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 PUSH: Received control message: 'PUSH_REPLY,sndbuf 0,rcvbuf 0,route 52.4.252.9
7,ping 10,ping-restart 60,socket-flags TCP_NODELAY,ifconfig 10.240.100.38 52.4.252.97,peer-id 0,cipher AES-128-GCM'
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 OPTIONS IMPORT: timers and/or timeouts modified
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 Socket Buffers: R=[131072->131072] S=[87040->87040]
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 OPTIONS IMPORT: --socket-flags option modified
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 Socket flags: TCP_NODELAY=1 succeeded
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 OPTIONS IMPORT: --ifconfig/up options modified
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 OPTIONS IMPORT: route options modified
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 OPTIONS IMPORT: peer-id set
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 OPTIONS IMPORT: adjusting link_mtu to 1627
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 OPTIONS IMPORT: data channel crypto options modified
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 Data Channel: using negotiated cipher 'AES-128-GCM'
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 Outgoing Data Channel: Cipher 'AES-128-GCM' initialized with 128 bit key
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 Incoming Data Channel: Cipher 'AES-128-GCM' initialized with 128 bit key
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 Preserving previous TUN/TAP instance: resin-vpn
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 /etc/openvpn-misc/upscript.sh resin-vpn 1500 1555 10.240.50.10 52.4.252.97 res
tart
Feb 17 23:22:32 47e7444 aac03a07c25b[1326]: [info] VPN connection is active.
Feb 17 23:22:32 47e7444 aac03a07c25b[1326]: [info] VPN connection is active.
Feb 17 23:22:32 47e7444 balena-supervisor[2622]: [info] VPN connection is active.
Feb 17 23:22:32 47e7444 balena-supervisor[2622]: [info] VPN connection is active.
Feb 17 23:22:32 47e7444 balena-supervisor[2622]: [info] VPN connection is active.
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 NOTE: Pulled options changed on restart, will need to close and reopen TUN/TAP
device.
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 Closing TUN/TAP interface
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 /sbin/ip addr del dev resin-vpn local 10.240.50.10 peer 52.4.252.97
Feb 17 23:22:32 47e7444 aac03a07c25b[1326]: [info] VPN connection is active.
Feb 17 23:22:32 47e7444 aac03a07c25b[1326]: [info] VPN connection is active.
Feb 17 23:22:32 47e7444 balena-supervisor[2622]: [info] VPN connection is active.
Feb 17 23:22:32 47e7444 openvpn[25287]: ip: RTNETLINK answers: Operation not permitted
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 Linux ip addr del failed: external program exited with error status: 2
Feb 17 23:22:32 47e7444 openvpn[23564]: Thu Feb 17 23:22:32 2022 /etc/openvpn-misc/downscript.sh resin-vpn 1500 1555 10.240.50.10 52.4.252.97 i
nit
Feb 17 23:22:32 47e7444 aac03a07c25b[1326]: [info] VPN connection is not active.
Feb 17 23:22:32 47e7444 balena-supervisor[2622]: [info] VPN connection is not active.
64 bytes from 142.251.46.174: seq=330 ttl=114 time=32.412 ms
64 bytes from 142.251.46.174: seq=331 ttl=114 time=33.425 ms
Feb 17 23:22:33 47e7444 aac03a07c25b[1326]: [info] Waiting for connectivity...
Feb 17 23:22:33 47e7444 balena-supervisor[2622]: [info] Waiting for connectivity...
Feb 17 23:22:33 47e7444 openvpn[23564]: Thu Feb 17 23:22:33 2022 ROUTE_GATEWAY 100.67.188.65/255.255.255.128 IFACE=wwan0 HWADDR=00:00:00:00:00:
00
Feb 17 23:22:33 47e7444 openvpn[23564]: Thu Feb 17 23:22:33 2022 ERROR: Cannot ioctl TUNSETIFF resin-vpn: Operation not permitted (errno=1)
Feb 17 23:22:33 47e7444 openvpn[23564]: Thu Feb 17 23:22:33 2022 Exiting due to fatal error
Feb 17 23:22:33 47e7444 systemd[1]: openvpn.service: Main process exited, code=exited, status=1/FAILURE
Feb 17 23:22:33 47e7444 systemd[1]: openvpn.service: Failed with result 'exit-code'.
64 bytes from 142.251.46.174: seq=332 ttl=114 time=42.308 ms
64 bytes from 142.251.46.174: seq=333 ttl=114 time=42.816 ms
64 bytes from 142.251.46.174: seq=334 ttl=114 time=41.959 ms
64 bytes from 142.251.46.174: seq=335 ttl=114 time=41.723 ms
64 bytes from 142.251.46.174: seq=336 ttl=114 time=41.618 ms
64 bytes from 142.251.46.174: seq=337 ttl=114 time=41.372 ms
64 bytes from 142.251.46.174: seq=338 ttl=114 time=42.262 ms
64 bytes from 142.251.46.174: seq=339 ttl=114 time=41.772 ms
64 bytes from 142.251.46.174: seq=340 ttl=114 time=31.762 ms
64 bytes from 142.251.46.174: seq=341 ttl=114 time=32.938 ms
Feb 17 23:22:43 47e7444 openvpn[25314]: Thu Feb 17 23:22:43 2022 WARNING: file '/var/volatile/vpn-auth' is group or others accessible
Feb 17 23:22:43 47e7444 openvpn[25314]: Thu Feb 17 23:22:43 2022 OpenVPN 2.4.7 aarch64-poky-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/P
KTINFO] [AEAD] built on Feb 20 2019
Feb 17 23:22:43 47e7444 openvpn[25314]: Thu Feb 17 23:22:43 2022 library versions: OpenSSL 1.1.1i 8 Dec 2020, LZO 2.10
Feb 17 23:22:43 47e7444 openvpn[25314]: Thu Feb 17 23:22:43 2022 NOTE: the current --script-security setting may allow this configuration to ca
ll user-defined scripts
Feb 17 23:22:43 47e7444 openvpn[25314]: Thu Feb 17 23:22:43 2022 TCP/UDP: Preserving recently used remote address: [AF_INET]3.227.28.93:443
Feb 17 23:22:43 47e7444 openvpn[25314]: Thu Feb 17 23:22:43 2022 Socket Buffers: R=[131072->131072] S=[16384->16384]
Feb 17 23:22:43 47e7444 openvpn[25314]: Thu Feb 17 23:22:43 2022 Attempting to establish TCP connection with [AF_INET]3.227.28.93:443 [nonblock
]
64 bytes from 142.251.46.174: seq=342 ttl=114 time=42.844 ms
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 TCP connection established with [AF_INET]3.227.28.93:443
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 TCP_CLIENT link local: (not bound)
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 TCP_CLIENT link remote: [AF_INET]3.227.28.93:443
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-d
elay
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 TLS: Initial packet from [AF_INET]3.227.28.93:443, sid=0c37f4de d5d255f2
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 WARNING: this configuration may cache passwords in memory -- use the auth-noca
che option to prevent this
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 VERIFY OK: depth=1, C=AU, ST=Some-State, O=Internet Widgits Pty Ltd
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 VERIFY KU OK
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 Validating certificate extended key usage
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Se
rver Authentication
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 VERIFY EKU OK
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 VERIFY OK: depth=0, C=US, ST=WA, O=balena.io, OU=balenaCloud, CN=vpn.balena-cl
oud.com
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Feb 17 23:22:44 47e7444 openvpn[25314]: Thu Feb 17 23:22:44 2022 [vpn.balena-cloud.com] Peer Connection Initiated with [AF_INET]3.227.28.93:443
64 bytes from 142.251.46.174: seq=343 ttl=114 time=38.638 ms
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 SENT CONTROL [vpn.balena-cloud.com]: 'PUSH_REQUEST' (status=1)
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 PUSH: Received control message: 'PUSH_REPLY,sndbuf 0,rcvbuf 0,route 52.4.252.9
7,ping 10,ping-restart 60,socket-flags TCP_NODELAY,ifconfig 10.240.8.211 52.4.252.97,peer-id 0,cipher AES-128-GCM'
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 OPTIONS IMPORT: timers and/or timeouts modified
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 Socket Buffers: R=[131072->131072] S=[87040->87040]
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 OPTIONS IMPORT: --socket-flags option modified
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 Socket flags: TCP_NODELAY=1 succeeded
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 OPTIONS IMPORT: --ifconfig/up options modified
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 OPTIONS IMPORT: route options modified
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 OPTIONS IMPORT: peer-id set
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 OPTIONS IMPORT: adjusting link_mtu to 1627
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 OPTIONS IMPORT: data channel crypto options modified
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 Data Channel: using negotiated cipher 'AES-128-GCM'
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 Outgoing Data Channel: Cipher 'AES-128-GCM' initialized with 128 bit key
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 Incoming Data Channel: Cipher 'AES-128-GCM' initialized with 128 bit key
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 ROUTE_GATEWAY 100.67.188.65/255.255.255.128 IFACE=wwan0 HWADDR=00:00:00:00:00:
00
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 TUN/TAP device resin-vpn opened
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 TUN/TAP TX queue length set to 100
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 /sbin/ip link set dev resin-vpn up mtu 1500
Feb 17 23:22:46 47e7444 NetworkManager[1310]: <info> [1645140166.1553] manager: (resin-vpn): new Tun device (/org/freedesktop/NetworkManager/D
evices/24)
Feb 17 23:22:46 47e7444 systemd-udevd[25315]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 /sbin/ip addr add dev resin-vpn local 10.240.8.211 peer 52.4.252.97
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 /etc/openvpn-misc/upscript.sh resin-vpn 1500 1555 10.240.8.211 52.4.252.97 ini
t
Feb 17 23:22:46 47e7444 aac03a07c25b[1326]: [info] VPN connection is active.
Feb 17 23:22:46 47e7444 balena-supervisor[2622]: [info] VPN connection is active.
Feb 17 23:22:46 47e7444 aac03a07c25b[1326]: [info] VPN connection is active.
Feb 17 23:22:46 47e7444 balena-supervisor[2622]: [info] VPN connection is active.
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 /sbin/ip route add 52.4.252.97/32 via 52.4.252.97
Feb 17 23:22:46 47e7444 aac03a07c25b[1326]: [info] VPN connection is active.
Feb 17 23:22:46 47e7444 balena-supervisor[2622]: [info] VPN connection is active.
Feb 17 23:22:46 47e7444 aac03a07c25b[1326]: [info] VPN connection is active.
Feb 17 23:22:46 47e7444 balena-supervisor[2622]: [info] VPN connection is active.
Feb 17 23:22:46 47e7444 openvpn[25324]: ip: RTNETLINK answers: File exists
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 ERROR: Linux route add command failed: external program exited with error stat
us: 2
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 GID set to openvpn
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 UID set to openvpn
Feb 17 23:22:46 47e7444 openvpn[25314]: Thu Feb 17 23:22:46 2022 Initialization Sequence Completed
64 bytes from 142.251.46.174: seq=344 ttl=114 time=30.148 ms
64 bytes from 142.251.46.174: seq=345 ttl=114 time=42.282 ms
64 bytes from 142.251.46.174: seq=346 ttl=114 time=38.796 ms
64 bytes from 142.251.46.174: seq=347 ttl=114 time=30.688 ms
64 bytes from 142.251.46.174: seq=348 ttl=114 time=34.337 ms