NM creates tun devices, while reconnecting constantly after hibernatio

kaymio · 2018-05-09 10:10:35

The Problem:

After my laptop wakes up from hibernation, NetworkManager (NM) reconnects to the WLAN and does so too with the VPN and says the connection was was successfully established. After a few seconds it says the connection timed out and creates a new tun device (up to 3 ; 0-2)

Restarting NM doesn't help, only a full reboot.

Mai 09 11:55:21 sidekick nm-openvpn[5521]: [server] Inactivity timeout (--ping-restart), restarting
Mai 09 11:55:21 sidekick nm-openvpn[5521]: SIGUSR1[soft,ping-restart] received, process restarting
Mai 09 11:55:26 sidekick nm-openvpn[5521]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mai 09 11:55:26 sidekick nm-openvpn[5521]: TCP/UDP: Preserving recently used remote address: [AF_INET]213.152.161.19:443
Mai 09 11:55:26 sidekick nm-openvpn[5521]: UDP link local: (not bound)
Mai 09 11:55:26 sidekick nm-openvpn[5521]: UDP link remote: [AF_INET]213.152.161.19:443
Mai 09 11:55:26 sidekick nm-openvpn[5521]: [server] Peer Connection Initiated with [AF_INET]213.152.161.19:443
Mai 09 11:55:27 sidekick nm-openvpn[5521]: Preserving previous TUN/TAP instance: tun2
Mai 09 11:55:27 sidekick nm-openvpn[5521]: /usr/lib/nm-openvpn-service-openvpn-helper --debug 0 5518 --bus-name org.freedesktop.NetworkManager.openvpn.Connection_11 --tun -- tun2 1500 1558 10.4.58.2>
Mai 09 11:55:27 sidekick dbus-daemon[436]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.699" (uid=972 pid=7098 comm="/usr/lib/nm-openvpn-service-openvpn-helper --d>
Mai 09 11:55:27 sidekick dbus-daemon[436]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.699" (uid=972 pid=7098 comm="/usr/lib/nm-openvpn-service-openvpn-helper --d>
Mai 09 11:55:27 sidekick dbus-daemon[436]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.699" (uid=972 pid=7098 comm="/usr/lib/nm-openvpn-service-openvpn-helper --d>
Mai 09 11:55:27 sidekick nm-openvpn[5521]: Initialization Sequence Completed
Mai 09 11:55:55 sidekick nm-openvpn[5064]: [server] Inactivity timeout (--ping-restart), restarting
Mai 09 11:55:55 sidekick nm-openvpn[5064]: SIGUSR1[soft,ping-restart] received, process restarting

Mai 09 11:29:32 sidekick nm-openvpn[5521]: UID set to nm-openvpn
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8691] vpn-connection[0x5637cf5b46f0,90869d5d-a7a5-4669-b077-c51fab854620,"AirVPN_NL-Alblasserdam_Salm_UDP-443",7:(tun2)]: Data:   In>
Mai 09 11:29:32 sidekick nm-openvpn[5521]: Initialization Sequence Completed
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8691] vpn-connection[0x5637cf5b46f0,90869d5d-a7a5-4669-b077-c51fab854620,"AirVPN_NL-Alblasserdam_Salm_UDP-443",7:(tun2)]: Data:   St>
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8691] vpn-connection[0x5637cf5b46f0,90869d5d-a7a5-4669-b077-c51fab854620,"AirVPN_NL-Alblasserdam_Salm_UDP-443",7:(tun2)]: Data:   St>
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8691] vpn-connection[0x5637cf5b46f0,90869d5d-a7a5-4669-b077-c51fab854620,"AirVPN_NL-Alblasserdam_Salm_UDP-443",7:(tun2)]: Data:   In>
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8692] vpn-connection[0x5637cf5b46f0,90869d5d-a7a5-4669-b077-c51fab854620,"AirVPN_NL-Alblasserdam_Salm_UDP-443",7:(tun2)]: Data:   DN>
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8692] vpn-connection[0x5637cf5b46f0,90869d5d-a7a5-4669-b077-c51fab854620,"AirVPN_NL-Alblasserdam_Salm_UDP-443",7:(tun2)]: Data: No I>
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8692] vpn-connection[0x5637cf5b46f0,90869d5d-a7a5-4669-b077-c51fab854620,"AirVPN_NL-Alblasserdam_Salm_UDP-443",7:(tun2)]: VPN plugin>
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8850] vpn-connection[0x5637cf5b46f0,90869d5d-a7a5-4669-b077-c51fab854620,"AirVPN_NL-Alblasserdam_Salm_UDP-443",7:(tun2)]: VPN connec>
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8858] device (tun2): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8870] device (wlp3s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8873] manager: NetworkManager state is now CONNECTED_SITE
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8937] manager: NetworkManager state is now CONNECTED_LOCAL
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.8938] manager: NetworkManager state is now CONNECTED_SITE
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9072] device (wlp3s0): Activation: successful, device activated.
Mai 09 11:29:32 sidekick nm-dispatcher[5075]: req:17 'up' [wlp3s0]: new request (1 scripts)
Mai 09 11:29:32 sidekick nm-dispatcher[5075]: req:18 'vpn-up' [tun2]: new request (1 scripts)
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9314] keyfile: add connection in-memory (d59f8796-7e43-49f7-bf99-965e550144b2,"tun2")
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9325] device (tun2): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9334] device (tun2): Activation: starting connection 'tun2' (d59f8796-7e43-49f7-bf99-965e550144b2)
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9371] device (tun2): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9376] device (tun2): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9379] device (tun2): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9380] device (tun2): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9385] device (tun2): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9387] device (tun2): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
Mai 09 11:29:32 sidekick NetworkManager[441]: <info>  [1525858172.9677] device (tun2): Activation: successful, device activated.
Mai 09 11:29:32 sidekick nm-dispatcher[5075]: req:19 'up' [tun2]: new request (1 scripts)
Mai 09 11:29:33 sidekick NetworkManager[441]: <info>  [1525858173.0027] manager: NetworkManager state is now CONNECTED_GLOBAL
Mai 09 11:29:33 sidekick nm-dispatcher[5075]: req:20 'connectivity-change': new request (1 scripts)
Mai 09 11:29:37 sidekick kernel: [UFW BLOCK] IN= OUT=wlp3s0 SRC=fe80:0000:0000:0000:38da:6b14:8ac1:1dbb DST=ff02:0000:0000:0000:0000:0000:0000:00fb LEN=88 TC=0 HOPLIMIT=1 FLOWLBL=405825 PROTO=UDP SP>
Mai 09 11:29:38 sidekick kernel: [UFW BLOCK] IN= OUT=wlp3s0 SRC=145.107.136.227 DST=224.0.0.22 LEN=40 TOS=0x00 PREC=0xC0 TTL=1 ID=0 DF PROTO=2 MARK=0x94
Mai 09 11:30:00 sidekick nm-openvpn[5064]: [server] Inactivity timeout (--ping-restart), restarting
Mai 09 11:30:00 sidekick nm-openvpn[5064]: SIGUSR1[soft,ping-restart] received, process restarting
Mai 09 11:30:05 sidekick nm-openvpn[5064]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mai 09 11:30:05 sidekick nm-openvpn[5064]: TCP/UDP: Preserving recently used remote address: [AF_INET]213.152.161.19:443
Mai 09 11:30:05 sidekick nm-openvpn[5064]: UDP link local: (not bound)
Mai 09 11:30:05 sidekick nm-openvpn[5064]: UDP link remote: [AF_INET]213.152.161.19:443
Mai 09 11:30:05 sidekick nm-openvpn[5064]: [server] Peer Connection Initiated with [AF_INET]213.152.161.19:443
Mai 09 11:30:06 sidekick nm-openvpn[5064]: Preserving previous TUN/TAP instance: tun1
Mai 09 11:30:06 sidekick nm-openvpn[5064]: /usr/lib/nm-openvpn-service-openvpn-helper --debug 0 5061 --bus-name org.freedesktop.NetworkManager.openvpn.Connection_5 --tun -- tun1 1500 1558 10.4.58.24>
Mai 09 11:30:06 sidekick nm-openvpn[5064]: Initialization Sequence Completed
Mai 09 11:30:14 sidekick nm-openvpn[512]: [server] Inactivity timeout (--ping-restart), restarting
Mai 09 11:30:14 sidekick nm-openvpn[512]: SIGUSR1[soft,ping-restart] received, process restarting
Mai 09 11:30:19 sidekick nm-openvpn[512]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mai 09 11:30:19 sidekick nm-openvpn[512]: TCP/UDP: Preserving recently used remote address: [AF_INET]213.152.161.19:443
Mai 09 11:30:19 sidekick nm-openvpn[512]: UDP link local: (not bound)
Mai 09 11:30:19 sidekick nm-openvpn[512]: UDP link remote: [AF_INET]213.152.161.19:443
Mai 09 11:30:19 sidekick nm-openvpn[512]: [server] Peer Connection Initiated with [AF_INET]213.152.161.19:443
Mai 09 11:30:20 sidekick nm-openvpn[512]: Preserving previous TUN/TAP instance: tun0
Mai 09 11:30:20 sidekick nm-openvpn[512]: /usr/lib/nm-openvpn-service-openvpn-helper --debug 0 506 --bus-name org.freedesktop.NetworkManager.openvpn.Connection_2 --tun -- tun0 1500 1558 10.4.58.248 >
Mai 09 11:30:20 sidekick nm-openvpn[512]: Initialization Sequence Completed

And again:

Mai 09 12:12:22 sidekick nm-openvpn[497]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mai 09 12:12:22 sidekick nm-openvpn[497]: TCP/UDP: Preserving recently used remote address: [AF_INET]213.152.161.19:443
Mai 09 12:12:22 sidekick nm-openvpn[497]: UDP link local: (not bound)
Mai 09 12:12:22 sidekick nm-openvpn[497]: UDP link remote: [AF_INET]213.152.161.19:443
Mai 09 12:12:22 sidekick nm-openvpn[497]: [server] Peer Connection Initiated with [AF_INET]213.152.161.19:443
Mai 09 12:12:23 sidekick nm-openvpn[497]: Preserving previous TUN/TAP instance: tun0
Mai 09 12:12:23 sidekick nm-openvpn[497]: /usr/lib/nm-openvpn-service-openvpn-helper --debug 0 491 --bus-name org.freedesktop.NetworkManager.openvpn.Connection_2 --tun -- tun0 1500 1558 10.4.58.248 255.255.0.0 restart
Mai 09 12:12:23 sidekick nm-openvpn[497]: Initialization Sequence Completed
Mai 09 12:13:02 sidekick NetworkManager[430]: <info>  [1525860782.5803] manager: NetworkManager state is now CONNECTED_SITE
Mai 09 12:13:02 sidekick dbus-daemon[429]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.1' (uid=0 pid=430 comm="/usr/bin/NetworkManager --no-daemon ")
Mai 09 12:13:02 sidekick systemd[1]: Starting Cleanup of Temporary Directories...
Mai 09 12:13:02 sidekick systemd[1]: Starting Network Manager Script Dispatcher Service...
Mai 09 12:13:02 sidekick dbus-daemon[429]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Mai 09 12:13:02 sidekick systemd[1]: Started Network Manager Script Dispatcher Service.
Mai 09 12:13:02 sidekick nm-dispatcher[2694]: req:1 'connectivity-change': new request (1 scripts)
Mai 09 12:13:02 sidekick nm-dispatcher[2694]: req:1 'connectivity-change': start running ordered scripts...
Mai 09 12:13:02 sidekick systemd[1]: Started Cleanup of Temporary Directories.
Mai 09 12:13:13 sidekick nm-dispatcher[2694]: req:1 'connectivity-change', "/etc/NetworkManager/dispatcher.d/updns.sh": complete: failed with Script '/etc/NetworkManager/dispatcher.d/updns.sh' exited with error status 6.
Mai 09 12:13:13 sidekick NetworkManager[430]: <warn>  [1525860793.1270] dispatcher: (21) updns.sh failed (failed): Script '/etc/NetworkManager/dispatcher.d/updns.sh' exited with error status 6.
Mai 09 12:13:21 sidekick nm-openvpn[2498]: [server] Inactivity timeout (--ping-restart), restarting
Mai 09 12:13:21 sidekick nm-openvpn[2498]: SIGUSR1[soft,ping-restart] received, process restarting
Mai 09 12:13:25 sidekick nm-openvpn[497]: [server] Inactivity timeout (--ping-restart), restarting
Mai 09 12:13:25 sidekick nm-openvpn[497]: SIGUSR1[soft,ping-restart] received, process restarting
Mai 09 12:13:26 sidekick nm-openvpn[2498]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mai 09 12:13:26 sidekick nm-openvpn[2498]: TCP/UDP: Preserving recently used remote address: [AF_INET]213.152.161.19:443
Mai 09 12:13:26 sidekick nm-openvpn[2498]: UDP link local: (not bound)
Mai 09 12:13:26 sidekick nm-openvpn[2498]: UDP link remote: [AF_INET]213.152.161.19:443
Mai 09 12:13:26 sidekick nm-openvpn[2498]: [server] Peer Connection Initiated with [AF_INET]213.152.161.19:443
Mai 09 12:13:27 sidekick nm-openvpn[2498]: Preserving previous TUN/TAP instance: tun1
Mai 09 12:13:27 sidekick nm-openvpn[2498]: /usr/lib/nm-openvpn-service-openvpn-helper --debug 0 2495 --bus-name org.freedesktop.NetworkManager.openvpn.Connection_5 --tun -- tun1 1500 1558 10.4.58.248 255.255.0.0 restart
Mai 09 12:13:27 sidekick dbus-daemon[429]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.215" (uid=972 pid=2703 comm="/usr/lib/nm-openvpn-service-openvpn-helper --debug") interface="org.freedesktop.NetworkManager.VPN.Plugin" member="SetConfig" error name="(unset)" requested_reply="0" destination=":1.155" (uid=0 pid=2495 comm="/usr/lib/nm-openvpn-service --bus-name org.freedes")
Mai 09 12:13:27 sidekick dbus-daemon[429]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.215" (uid=972 pid=2703 comm="/usr/lib/nm-openvpn-service-openvpn-helper --debug") interface="org.freedesktop.NetworkManager.VPN.Plugin" member="SetIp4Config" error name="(unset)" requested_reply="0" destination=":1.155" (uid=0 pid=2495 comm="/usr/lib/nm-openvpn-service --bus-name org.freedes")
Mai 09 12:13:27 sidekick dbus-daemon[429]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.215" (uid=972 pid=2703 comm="/usr/lib/nm-openvpn-service-openvpn-helper --debug") interface="org.freedesktop.NetworkManager.VPN.Plugin" member="SetIp6Config" error name="(unset)" requested_reply="0" destination=":1.155" (uid=0 pid=2495 comm="/usr/lib/nm-openvpn-service --bus-name org.freedes")
Mai 09 12:13:27 sidekick nm-openvpn[2498]: Initialization Sequence Completed
Mai 09 12:13:30 sidekick nm-openvpn[497]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mai 09 12:13:30 sidekick nm-openvpn[497]: TCP/UDP: Preserving recently used remote address: [AF_INET]213.152.161.19:443
Mai 09 12:13:30 sidekick nm-openvpn[497]: UDP link local: (not bound)
Mai 09 12:13:30 sidekick nm-openvpn[497]: UDP link remote: [AF_INET]213.152.161.19:443
Mai 09 12:13:30 sidekick nm-openvpn[497]: [server] Peer Connection Initiated with [AF_INET]213.152.161.19:443
Mai 09 12:13:32 sidekick nm-openvpn[497]: Preserving previous TUN/TAP instance: tun0
Mai 09 12:13:32 sidekick nm-openvpn[497]: /usr/lib/nm-openvpn-service-openvpn-helper --debug 0 491 --bus-name org.freedesktop.NetworkManager.openvpn.Connection_2 --tun -- tun0 1500 1558 10.4.58.248 255.255.0.0 restart
Mai 09 12:13:32 sidekick nm-openvpn[497]: Initialization Sequence Completed

Last edited by kaymio (2018-05-09 10:19:41)

kaymio · 2018-05-14 10:22:18

Did I state the question wrong or too bluntly? Are there any other logs that I could provide? Should I perform specific tests?

It's a really annoying bug that appeared recently since the 4.15 cycle on a relatively fresh machine.

Arch Linux

#1 2018-05-09 10:10:35

NM creates tun devices, while reconnecting constantly after hibernatio

#2 2018-05-14 10:22:18

Re: NM creates tun devices, while reconnecting constantly after hibernatio

Board footer