Bug 1576910 - DHCP Renewal Kills Anyconnect VPN Connections
Summary: DHCP Renewal Kills Anyconnect VPN Connections
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: NetworkManager
Version: 28
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Lubomir Rintel
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-10 16:49 UTC by John W Smith
Modified: 2019-12-23 08:45 UTC (History)
20 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2019-05-28 22:27:37 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
/var/log/messages related entries (14.86 KB, application/x-bzip)
2018-05-10 16:49 UTC, John W Smith
no flags Details
Journal entries from latest failure (22.17 KB, application/x-bzip)
2018-05-11 20:10 UTC, John W Smith
no flags Details
anyconnect working with fc27 (3.29 KB, text/plain)
2018-05-26 20:50 UTC, Brian P.
no flags Details
anyconnect breaking with fc28 (12.07 KB, text/plain)
2018-05-26 20:51 UTC, Brian P.
no flags Details

Description John W Smith 2018-05-10 16:49:53 UTC
Created attachment 1434477 [details]
/var/log/messages related entries

Description of problem:
After connecting via Anyconnect VPN, the next dhcp renewal modifies the Routing / IP Forwarding table, and doesn't notify Anyconnect of the change. This causes Anyconnect to treat the change as an unauthorized change which it then tries to correct but eventually fails. Anyconnect works flawlessly on same network / dhcp lease schedule with Fedora 27.

I've confirmed this is related to DHCP by setting a static IP for both my wireless and wired connections, testing on each.

How reproducible:
Connect via Anyconnect VPN, wait for next DHCP lease renewal.

Actual results:
VPN Disconnects, most of the time requiring cycling of the wired/wireless connection state and restart of the vpn agent daemon in order to reconnect.

Expected results:
VPN stays connected.

Comment 1 John W Smith 2018-05-10 16:51:25 UTC
This could also be related to NetworkManager, I tried increasing the lease time provided by the DHCP server (my router) to 2 days, but it always renews the lease @ 2880 sec intervals, or there abouts.

Comment 2 Pavel Zhukov 2018-05-10 19:21:00 UTC
(In reply to John W Smith from comment #1)
> This could also be related to NetworkManager, I tried increasing the lease
> time provided by the DHCP server (my router) to 2 days, but it always renews
> the lease @ 2880 sec intervals, or there abouts.

I think it's related to NM [See 1]. Please disable NM and try to reproduce the issue with dhclient.
(dhclient -d -v <iface>)


[1]
May 10 08:59:13 cg-linux1 NetworkManager[1176]: <info>  [1525957153.3452] device (cscotun0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
May 10 08:59:13 cg-linux1 NetworkManager[1176]: <info>  [1525957153.3487] device (cscotun0): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
May 10 08:59:13 cg-linux1 acvpnagent[3839]: Index of questionable route entry in 'Modified' table: 2

Comment 3 John W Smith 2018-05-10 21:13:25 UTC
Initially, removing NetworkManager seems to have resolved the issue. However, right before this, had a power blip and my docking station momentarily disconnected, and the wired port disappeared, which of course killed the VPN. Once I manually brought the interface back up, I was able to reconnect. I'll leave the VPN up overnight and see if its still running in the morning.

So this does indeed seem to be a NM issue. Also, its seems Anyconnect wants a library from NM, I assume so they can talk, which they obviously aren't doing. Since the latest NM doesn't provide a libnm-glibe.so.2, I can only assume there was something leftover from F27 during the upgrade that was keeping the error from displaying. After uninstalling all the NM packages, this error showed up, but doesn't seem to be fatal. Missing library error messages from log below.


Log entries follow:
May 10 16:16:02 cg-linux1 acvpnagent[1952]: Function: CNWMgrHelper File: ../../vpn/Common/Utility/linux/NWMgrHelper.cpp Line: 79 dlopen failed: libnm-glib.so.2: cannot open shared object file: No such file or directory
May 10 16:16:02 cg-linux1 acvpnagent[1952]: Function: createSingletonInstance File: ../../vpn/Common/Utility/linux/NWMgrHelper.cpp Line: 151 Invoked Function: CNWMgrHelper::CNWMgrHelper Return Code: -22151161 (0xFEAE0007) Description: NWMGRHELPER_ERROR_NOT_INITIALIZED
May 10 16:16:02 cg-linux1 acvpnagent[1952]: Function: CNetInterface File: ../../vpn/Common/Utility/NetInterface_unix.cpp Line: 188 Failed to load libnm library, features like TND may not work properly.
May 10 16:16:02 cg-linux1 acvpnagent[1952]: Function: CNWMgrHelper File: ../../vpn/Common/Utility/linux/NWMgrHelper.cpp Line: 79 dlopen failed: libnm-glib.so.2: cannot open shared object file: No such file or directory

Comment 4 John W Smith 2018-05-10 21:18:44 UTC
Followup to above, I also changed the interface back to DHCP, so refreshes don't seem to be bothering it.

Comment 5 John W Smith 2018-05-11 11:32:25 UTC
VPN Connection remained connected overnight, no failures.

I removed all NM packages, which seems to have fixed things up. This however is suboptimal.

Comment 6 Beniamino Galvani 2018-05-11 16:33:57 UTC
Can you please set 'level=trace' in the [logging] section of /etc/NetworkManager/NetworkManager.conf, re-enable NM, reproduce the issue and attach the journal logs when the issue happens again? Thanks!

Comment 7 John W Smith 2018-05-11 20:10:07 UTC
Created attachment 1435117 [details]
Journal entries from latest failure

Comment 8 John W Smith 2018-05-17 16:25:41 UTC
Update:

Installed NetworkManager update to 1.10.8-1, problem still exists.

Comment 9 Brian P. 2018-05-26 20:50:36 UTC
Created attachment 1442139 [details]
anyconnect working with fc27

Comment 10 Brian P. 2018-05-26 20:51:17 UTC
Created attachment 1442140 [details]
anyconnect breaking with fc28

Comment 11 Brian P. 2018-05-26 20:53:57 UTC
I have confirmed the same issue. I also have confirmed the VPN connection is stable with NetworkManager stopped.

I also included some logs that I have from FC27 and what I am seeing with FC28, just the section where I am seeing the failure. 

FC27 version that worked was 1.8.6-1.fc27
FC28 version that is causing problems is 1.10.6-2.fc28

Comment 12 Beniamino Galvani 2018-06-08 07:44:18 UTC
(In reply to Brian P. from comment #11)
> I have confirmed the same issue. I also have confirmed the VPN connection is
> stable with NetworkManager stopped.
> 
> I also included some logs that I have from FC27 and what I am seeing with
> FC28, just the section where I am seeing the failure. 
> 
> FC27 version that worked was 1.8.6-1.fc27
> FC28 version that is causing problems is 1.10.6-2.fc28

Can you please try with the latest RPM (NetworkManager-1.10.8-1.fc28) ?

Looking at logs, I see that after DHCP renewal, NM updates the address lifetime and sets the default route with metric 20600, that is, 600 + a 20000 penalty because connectivity check detects that the interface has no connectivity. After that, someone else keep adding and removing routes externally to NM.

Can you please try to disable connectivity check and see if it makes a difference? To disable it, uninstall package NetworkManager-config-connectivity-fedora and restart NM.

Comment 13 John W Smith 2018-06-08 18:14:11 UTC
The change/upgrade to 1.10.8-1 as stated in comment #8 above, did not fix the issue. However, removing the NetworkManager-config-connectivity-fedora package so far has made the connection stable under DHCP. Granted, I've only been testing for a couple of hours, but so far so good. Previously it would have disconnected before now.

Comment 14 John W Smith 2018-06-09 02:08:36 UTC
Connection was stable over several hours, so I would presume that the removal of NetworkManager-config-connectivity-fedora at least is a workaround / masks the issue. Which in turn points something in the package being the issue.

Comment 15 Brian P. 2018-06-09 14:50:55 UTC
Same, the issue is fixed with the removal NetworkManager-config-connectivity-fedora(upgrading first did not fix it).

The logs are now the same as the FC27 logs:
Jun  9 09:23:01 localhost NetworkManager[1728]: <info>  [1528554181.8971] dhcp4 (ens33): state changed bound -> bound
Jun  9 09:23:01 localhost acvpnagent[2347]: A routing table change notification has been received.  Starting automatic correction of the routing table.
Jun  9 09:23:01 localhost acvpnagent[2347]: Automatic correction of the routing table has been successful.

Comment 16 Michael B. Messmer 2018-09-17 19:54:12 UTC
Same, Auto reconnect works with the removal NetworkManager-config-connectivity-fedora.  

removing it also took out the following:
---
Removing:
 NetworkManager-config-connectivity-fedora 
Removing dependent packages:
 fedora-release-workstation

Comment 17 Ben Cotton 2019-05-02 20:55:07 UTC
This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 28 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 18 Ben Cotton 2019-05-28 22:27:37 UTC
Fedora 28 changed to end-of-life (EOL) status on 2019-05-28. Fedora 28 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Comment 19 William Bader 2019-06-15 02:59:29 UTC
I am getting this on Fedora 30.
The wifi connection periodically disconnects, I think when dhcp tries to renew, and /var/log/messages is full of sequences like the ones below.
I have some VPN connections entered in NetworkManager that carried over from the update from Fedora 28 to 30, but I have not used them recently.

Jun 15 03:42:16 scslaptop37 acvpnagent[1468]: Function: CNWMgrHelper File: ../../vpn/Common/Utility/linux/NWMgrHelper.cpp Line: 79 dlopen failed: libnm-glib.so.2: cannot open shared object file: No such file or directory
Jun 15 03:42:16 scslaptop37 acvpnagent[1468]: Function: createSingletonInstance File: ../../vpn/Common/Utility/linux/NWMgrHelper.cpp Line: 151 Invoked Function: CNWMgrHelper::CNWMgrHelper Return Code: -20447225 (0xFEC80007) Description: NWMGRHELPER_ERROR_NOT_INITIALIZED
Jun 15 03:42:16 scslaptop37 acvpnagent[1468]: Function: CNetInterface File: ../../vpn/Common/Utility/NetInterface_unix.cpp Line: 198 Failed to load libnm library, features like TND may not work properly.

$ uname -a
Linux scslaptop37 5.1.8-300.fc30.x86_64 #1 SMP Sun Jun 9 17:09:32 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
$ rpm -q NetworkManager
NetworkManager-1.16.2-1.fc30.x86_64
$ sudo dnf provides '*/libnm-glib.so*'
Error: No Matches found

Comment 20 Judd 2019-12-22 13:43:14 UTC
I was able to replicate this with a clean install of Fedora 30 as well as verify that removing "NetworkManager-config-connectivity-fedora" does resolve the issue. Subsequent reinstall of the package causes the behavior again.

Comment 21 Pavel Zhukov 2019-12-23 08:45:56 UTC
(In reply to Judd from comment #20)
> I was able to replicate this with a clean install of Fedora 30 as well as
> verify that removing "NetworkManager-config-connectivity-fedora" does
> resolve the issue. Subsequent reinstall of the package causes the behavior
> again.

Please open new bug against NetworkManager component.


Note You need to log in before you can comment on or make changes to this bug.