Issue #2394
IP is not assigned after re-authentication
Status:
Feedback
Priority:
Normal
Assignee:
-
Category:
kernel-interface
Affected version:
5.3.5
Resolution:
Description
Steps to reproduce:
1. Establish connection between a client and a server
conn %default
keyexchange=ikev2
ike=aes256gcm128-sha512-prfsha512-ecp521,aes256ccm16-sha512-prfsha512-ecp521,aes256ctr-sha512-prfsha512-ecp521!
esp=aes256ctr-sha512-ecp521-esn,aes256gcm128-sha512-ecp521-esn,aes256ccm16-sha512-prfsha512-ecp521-esn!
keyingtries=%forever
rekey=yes
reauth=yes
lifebytes=34359738368
marginbytes=1073741824
dpdaction=restart
dpddelay=25s
type=tunnel
forceencaps=yes
compress=yes
mobike=yes
authby=ecdsasig
# only for debuging the issue
ikelifetime=240s
rekeyfuzz="200%"
keylife=30s
margintime=10s
closeaction=restart
inactivity=120s
conn MAS
auto=start
...
2. Observe
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
inet 192.168.22.58/24 brd 192.168.22.255 scope global eth0
valid_lft forever preferred_lft forever
inet 172.16.1.1/32 scope global eth0 <--- Leased address
valid_lft forever preferred_lft forever
inet6 fe80::56a0:50ff:fed7:1a6/64 scope link
valid_lft forever preferred_lft forever
3. Execute
systemctl restart networking
4. Wait for re-authentication
...
Jul 28 12:47:34 11[IKE] <MAS|3> scheduling reauthentication in 222s
Jul 28 12:47:34 11[IKE] <MAS|3> maximum IKE_SA lifetime 232s
Jul 28 12:47:34 11[IKE] <MAS|3> installing DNS server 172.16.0.1 via resolvconf
Jul 28 12:47:34 11[IKE] <MAS|3> installing new virtual IP 172.16.1.1
Jul 28 12:47:34 11[IKE] <MAS|3> CHILD_SA MAS{53} established with SPIs cadb8ff4_i ca53c0a6_o and TS 172.16.1.0/24 === 172.16.0.1/32
Jul 28 12:47:34 11[IKE] <MAS|3> received AUTH_LIFETIME of 19930s, reauthentication already scheduled in 221s
Jul 28 12:47:34 11[IKE] <MAS|3> peer supports MOBIKE
...
5. However, the leased IP address (i.e., 172.16.1.1) is not assigned with eth0
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
inet 192.168.22.58/24 brd 192.168.22.255 scope global eth0
valid_lft forever preferred_lft forever
inet6 fe80::56a0:50ff:fed7:1a6/64 scope link
valid_lft forever preferred_lft forever
Version/kernel information:
ipsec --version Linux strongSwan U5.3.5/K4.4.0-87-generic
History
#1 Updated by Tobias Brunner over 4 years ago
- Category set to kernel-interface
- Status changed from New to Feedback
3. Execute
[...]
Why? Just as a test? What events does this generate (in terms of Netlink messages, try ip monitor label).
5. However, the leased IP address (i.e., 172.16.1.1) is not assigned with eth0
[...]
If the kernel-netlink plugin still thinks the IP is installed that's to be expected.
#2 Updated by Oleksandr Kazymyrov over 4 years ago
3. It is an example to reproduce the issue.
after systemctl restart networking, ip -ts monitor label produces:
[2017-08-03T09:36:30.325890] [ADDR]Deleted 2: eth0 inet 192.168.22.58/24 brd 192.168.22.255 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:36:30.325982] [ROUTE]Deleted 192.168.22.0/24 dev eth0 proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:30.326064] [ROUTE]Deleted broadcast 192.168.22.255 dev eth0 table local proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:30.326128] [ROUTE]Deleted broadcast 192.168.22.0 dev eth0 table local proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:30.326206] [ROUTE]Deleted local 192.168.22.58 dev eth0 table local proto kernel scope host src 192.168.22.58
[2017-08-03T09:36:30.326257] [ADDR]Deleted 2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:36:30.326340] [ROUTE]Deleted local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:36:30.326367] [NEIGH]Deleted 192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff REACHABLE
[2017-08-03T09:36:30.326390] [NEIGH]Deleted 192.168.22.222 dev eth0 lladdr 08:00:27:a9:be:0c REACHABLE
[2017-08-03T09:36:30.372613] [LINK]2: eth0: <BROADCAST,MULTICAST> mtu 1500 qdisc pfifo_fast state DOWN group default
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:30.372822] [NEIGH]Deleted ff02::1:ffd7:1a6 dev eth0 lladdr 33:33:ff:d7:01:a6 NOARP
[2017-08-03T09:36:30.372854] [NEIGH]Deleted ff02::16 dev eth0 lladdr 33:33:00:00:00:16 NOARP
[2017-08-03T09:36:30.372875] [NEIGH]Deleted ff02::2 dev eth0 lladdr 33:33:00:00:00:02 NOARP
[2017-08-03T09:36:30.372896] [ROUTE]Deleted fe80::/64 dev eth0 proto kernel metric 256 pref medium
[2017-08-03T09:36:30.372919] [ROUTE]Deleted ff00::/8 dev eth0 table local metric 256 pref medium
[2017-08-03T09:36:30.372938] [ADDR]Deleted 2: eth0 inet6 fe80::56a0:50ff:fed7:1a6/64 scope link
valid_lft forever preferred_lft forever
[2017-08-03T09:36:30.372968] [ROUTE]Deleted local fe80::56a0:50ff:fed7:1a6 dev lo table local proto none metric 0 pref medium
[2017-08-03T09:36:30.555651] [LINK]2: eth0: <BROADCAST,MULTICAST,UP> mtu 1500 qdisc pfifo_fast state UP group default
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:30.555850] [LINK]2: eth0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc pfifo_fast state DOWN group default
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:33.382793] [ROUTE]ff00::/8 dev eth0 table local metric 256 pref medium
[2017-08-03T09:36:33.382986] [ROUTE]fe80::/64 dev eth0 proto kernel metric 256 pref medium
[2017-08-03T09:36:33.383030] [LINK]2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:33.976685] [ADDR]2: eth0 inet 192.168.22.58/24 brd 192.168.22.255 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:36:33.976866] [ROUTE]local 192.168.22.58 dev eth0 table local proto kernel scope host src 192.168.22.58
[2017-08-03T09:36:33.976959] [ROUTE]broadcast 192.168.22.255 dev eth0 table local proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:33.977039] [ROUTE]192.168.22.0/24 dev eth0 proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:33.977141] [ROUTE]broadcast 192.168.22.0 dev eth0 table local proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:33.978035] [NEIGH]192.168.22.222 dev eth0 lladdr 08:00:27:a9:be:0c REACHABLE
[2017-08-03T09:36:33.978553] [ROUTE]default via 192.168.22.1 dev eth0
[2017-08-03T09:36:34.115995] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff REACHABLE
[2017-08-03T09:36:34.169784] [LINK]11: wlan1: <NO-CARRIER,BROADCAST,ALLMULTI,PROMISC,NOTRAILERS,UP> mtu 1500 qdisc mq state DOWN group default
link/ieee802.11/radiotap ec:22:80:0d:a0:3b brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:34.436250] [ADDR]2: eth0 inet6 fe80::56a0:50ff:fed7:1a6/64 scope link
valid_lft forever preferred_lft forever
[2017-08-03T09:36:34.436539] [ROUTE]local fe80::56a0:50ff:fed7:1a6 dev lo table local proto none metric 0 pref medium
[2017-08-03T09:37:14.500198] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff STALE
[2017-08-03T09:37:26.356229] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff PROBE
[2017-08-03T09:37:26.356391] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff REACHABLE
[2017-08-03T09:37:49.083456] [ADDR]2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:37:49.083607] [ROUTE]local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:37:49.165539] [ADDR]Deleted 2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:37:49.165804] [ROUTE]Deleted local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:37:49.166132] [ADDR]2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:37:49.166213] [ROUTE]local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:37:49.184269] [ROUTE]172.16.0.1 via 192.168.22.1 dev eth0 table 220 proto static src 172.16.1.1
[2017-08-03T09:37:49.278080] [ADDR]Deleted 2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:37:49.278135] [ROUTE]Deleted local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:38:06.724200] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff STALE
[2017-08-03T09:38:12.292211] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff PROBE
[2017-08-03T09:38:12.292405] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff REACHABLE
[2017-08-03T09:38:52.548204] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff STALE
[2017-08-03T09:39:01.412217] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff PROBE
[2017-08-03T09:39:01.412395] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff REACHABLE
and the corresponding strongSwan logs
...
Aug 3 09:37:49 04[IKE] <MAS|2> scheduling reauthentication in 92s
Aug 3 09:37:49 04[IKE] <MAS|2> maximum IKE_SA lifetime 102s
Aug 3 09:37:49 04[IKE] <MAS|2> installing DNS server 172.16.0.1 via resolvconf
Aug 3 09:37:49 04[IKE] <MAS|2> installing new virtual IP 172.16.1.1
Aug 3 09:37:49 04[IKE] <MAS|2> CHILD_SA MAS{15} established with SPIs cec291ad_i c74da71f_o and TS 172.16.1.0/24 === 172.16.0.1/32
Aug 3 09:37:49 04[IKE] <MAS|2> received AUTH_LIFETIME of 20284s, reauthentication already scheduled in 91s
Aug 3 09:37:49 04[IKE] <MAS|2> peer supports MOBIKE
...
Results of ip address show eth0
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
inet 192.168.22.58/24 brd 192.168.22.255 scope global eth0
valid_lft forever preferred_lft forever
inet6 fe80::56a0:50ff:fed7:1a6/64 scope link
valid_lft forever preferred_lft forever
#3 Updated by Tobias Brunner over 4 years ago
Thanks for the event output.
[2017-08-03T09:36:30.325890] [ADDR]Deleted 2: eth0 inet 192.168.22.58/24 brd 192.168.22.255 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:36:30.325982] [ROUTE]Deleted 192.168.22.0/24 dev eth0 proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:30.326064] [ROUTE]Deleted broadcast 192.168.22.255 dev eth0 table local proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:30.326128] [ROUTE]Deleted broadcast 192.168.22.0 dev eth0 table local proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:30.326206] [ROUTE]Deleted local 192.168.22.58 dev eth0 table local proto kernel scope host src 192.168.22.58
[2017-08-03T09:36:30.326257] [ADDR]Deleted 2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:36:30.326340] [ROUTE]Deleted local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:36:30.326367] [NEIGH]Deleted 192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff REACHABLE
[2017-08-03T09:36:30.326390] [NEIGH]Deleted 192.168.22.222 dev eth0 lladdr 08:00:27:a9:be:0c REACHABLE
[2017-08-03T09:36:30.372613] [LINK]2: eth0: <BROADCAST,MULTICAST> mtu 1500 qdisc pfifo_fast state DOWN group default
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:30.372822] [NEIGH]Deleted ff02::1:ffd7:1a6 dev eth0 lladdr 33:33:ff:d7:01:a6 NOARP
[2017-08-03T09:36:30.372854] [NEIGH]Deleted ff02::16 dev eth0 lladdr 33:33:00:00:00:16 NOARP
[2017-08-03T09:36:30.372875] [NEIGH]Deleted ff02::2 dev eth0 lladdr 33:33:00:00:00:02 NOARP
[2017-08-03T09:36:30.372896] [ROUTE]Deleted fe80::/64 dev eth0 proto kernel metric 256 pref medium
[2017-08-03T09:36:30.372919] [ROUTE]Deleted ff00::/8 dev eth0 table local metric 256 pref medium
[2017-08-03T09:36:30.372938] [ADDR]Deleted 2: eth0 inet6 fe80::56a0:50ff:fed7:1a6/64 scope link
valid_lft forever preferred_lft forever
[2017-08-03T09:36:30.372968] [ROUTE]Deleted local fe80::56a0:50ff:fed7:1a6 dev lo table local proto none metric 0 pref medium
[2017-08-03T09:36:30.555651] [LINK]2: eth0: <BROADCAST,MULTICAST,UP> mtu 1500 qdisc pfifo_fast state UP group default
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:30.555850] [LINK]2: eth0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc pfifo_fast state DOWN group default
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
This seems to be the reset, i.e. all addresses and routes are removed (including the virtual IP, interestingly there is no event for the route in table 220).
Then the network connection is reestablished (I guess the delay is due to DHCP):
[2017-08-03T09:36:33.382793] [ROUTE]ff00::/8 dev eth0 table local metric 256 pref medium
[2017-08-03T09:36:33.382986] [ROUTE]fe80::/64 dev eth0 proto kernel metric 256 pref medium
[2017-08-03T09:36:33.383030] [LINK]2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default
link/ether 54:a0:50:d7:01:a6 brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:33.976685] [ADDR]2: eth0 inet 192.168.22.58/24 brd 192.168.22.255 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:36:33.976866] [ROUTE]local 192.168.22.58 dev eth0 table local proto kernel scope host src 192.168.22.58
[2017-08-03T09:36:33.976959] [ROUTE]broadcast 192.168.22.255 dev eth0 table local proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:33.977039] [ROUTE]192.168.22.0/24 dev eth0 proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:33.977141] [ROUTE]broadcast 192.168.22.0 dev eth0 table local proto kernel scope link src 192.168.22.58
[2017-08-03T09:36:33.978035] [NEIGH]192.168.22.222 dev eth0 lladdr 08:00:27:a9:be:0c REACHABLE
[2017-08-03T09:36:33.978553] [ROUTE]default via 192.168.22.1 dev eth0
[2017-08-03T09:36:34.115995] [NEIGH]192.168.22.1 dev eth0 lladdr 20:cf:30:b7:d9:ff REACHABLE
[2017-08-03T09:36:34.169784] [LINK]11: wlan1: <NO-CARRIER,BROADCAST,ALLMULTI,PROMISC,NOTRAILERS,UP> mtu 1500 qdisc mq state DOWN group default
link/ieee802.11/radiotap ec:22:80:0d:a0:3b brd ff:ff:ff:ff:ff:ff
[2017-08-03T09:36:34.436250] [ADDR]2: eth0 inet6 fe80::56a0:50ff:fed7:1a6/64 scope link
valid_lft forever preferred_lft forever
[2017-08-03T09:36:34.436539] [ROUTE]local fe80::56a0:50ff:fed7:1a6 dev lo table local proto none metric 0 pref medium
According to the timestamps the following happens when the SA is reestablished:
[2017-08-03T09:37:49.083456] [ADDR]2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:37:49.083607] [ROUTE]local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:37:49.165539] [ADDR]Deleted 2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:37:49.165804] [ROUTE]Deleted local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:37:49.166132] [ADDR]2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:37:49.166213] [ROUTE]local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
[2017-08-03T09:37:49.184269] [ROUTE]172.16.0.1 via 192.168.22.1 dev eth0 table 220 proto static src 172.16.1.1
[2017-08-03T09:37:49.278080] [ADDR]Deleted 2: eth0 inet 172.16.1.1/32 scope global eth0
valid_lft forever preferred_lft forever
[2017-08-03T09:37:49.278135] [ROUTE]Deleted local 172.16.1.1 dev eth0 table local proto kernel scope host src 172.16.1.1
For some reason the address gets added, then removed, added again, and removed a second time. You could increase the log level for KNL to 2 to get slightly more information when the IP is installed/deleted. Do you use make-before-break reauthentication?
To get a more stable behavior you could perhaps set charon.install_virtual_ip_on = lo in strongswan.conf so the virtual IP is installed on lo and not the outgoing interface. The code currently does only reinstall routes, but not virtual IPs.
#4 Updated by Oleksandr Kazymyrov over 4 years ago
DPD before:
Aug 4 14:34:59 19[KNL] received a XFRM_MSG_EXPIRE
Aug 4 14:34:59 19[KNL] creating rekey job for CHILD_SA ESP/0xc33457c5/192.168.22.58
Aug 4 14:34:59 19[IKE] <MAS|1> establishing CHILD_SA MAS{1}
Aug 4 14:34:59 19[KNL] <MAS|1> got SPI cac1ab8a
Aug 4 14:34:59 19[KNL] <MAS|1> got CPI 1787
Aug 4 14:34:59 19[ENC] <MAS|1> generating CREATE_CHILD_SA request 25 [ N(REKEY_SA) N(IPCOMP_SUP) SA No KE TSi TSr ]
Aug 4 14:34:59 19[NET] <MAS|1> sending packet: from 192.168.22.58[4500] to 10.246.162.90[4500] (444 bytes)
Aug 4 14:34:59 20[NET] <MAS|1> received packet: from 10.246.162.90[4500] to 192.168.22.58[4500] (344 bytes)
Aug 4 14:34:59 20[ENC] <MAS|1> parsed CREATE_CHILD_SA response 25 [ N(IPCOMP_SUP) SA No KE TSi TSr ]
Aug 4 14:34:59 20[KNL] <MAS|1> adding SAD entry with SPI 00001787 and reqid {1} (mark 0/0x00000000)
Aug 4 14:34:59 20[KNL] <MAS|1> using compression algorithm IPCOMP_DEFLATE
Aug 4 14:34:59 20[KNL] <MAS|1> adding SAD entry with SPI cac1ab8a and reqid {1} (mark 0/0x00000000)
Aug 4 14:34:59 20[KNL] <MAS|1> using encryption algorithm AES_CTR with key size 288
Aug 4 14:34:59 20[KNL] <MAS|1> using integrity algorithm HMAC_SHA2_512_256 with key size 512
Aug 4 14:34:59 20[KNL] <MAS|1> using replay window of 32 packets
Aug 4 14:34:59 20[KNL] <MAS|1> using extended sequence numbers (ESN)
Aug 4 14:34:59 20[KNL] <MAS|1> adding SAD entry with SPI 0000cb96 and reqid {1} (mark 0/0x00000000)
Aug 4 14:34:59 20[KNL] <MAS|1> using compression algorithm IPCOMP_DEFLATE
Aug 4 14:34:59 20[KNL] <MAS|1> adding SAD entry with SPI cad23e60 and reqid {1} (mark 0/0x00000000)
Aug 4 14:34:59 20[KNL] <MAS|1> using encryption algorithm AES_CTR with key size 288
Aug 4 14:34:59 20[KNL] <MAS|1> using integrity algorithm HMAC_SHA2_512_256 with key size 512
Aug 4 14:34:59 20[KNL] <MAS|1> using replay window of 32 packets
Aug 4 14:34:59 20[KNL] <MAS|1> using extended sequence numbers (ESN)
Aug 4 14:34:59 20[KNL] <MAS|1> policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:34:59 20[KNL] <MAS|1> policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:34:59 20[KNL] <MAS|1> policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:34:59 20[KNL] <MAS|1> policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:34:59 20[KNL] <MAS|1> updating policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:34:59 20[KNL] <MAS|1> policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:34:59 20[KNL] <MAS|1> updating policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:34:59 20[KNL] <MAS|1> policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:34:59 20[KNL] <MAS|1> updating policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:34:59 20[KNL] <MAS|1> getting a local address in traffic selector 172.16.1.0/24
Aug 4 14:34:59 20[KNL] <MAS|1> no local address found in traffic selector 172.16.1.0/24
Aug 4 14:34:59 20[IKE] <MAS|1> CHILD_SA MAS{12} established with SPIs cac1ab8a_i cad23e60_o and TS 172.16.1.0/24 === 172.16.0.1/32
Aug 4 14:34:59 20[KNL] <MAS|1> querying SAD entry with SPI c33457c5 (mark 0/0x00000000)
Aug 4 14:34:59 20[KNL] <MAS|1> querying SAD entry with SPI c08d1db0 (mark 0/0x00000000)
Aug 4 14:34:59 20[IKE] <MAS|1> closing CHILD_SA MAS{11} with SPIs c33457c5_i (0 bytes) c08d1db0_o (0 bytes) and TS 172.16.1.0/24 === 172.16.0.1/32
Aug 4 14:34:59 20[IKE] <MAS|1> sending DELETE for ESP CHILD_SA with SPI c33457c5
Aug 4 14:34:59 20[ENC] <MAS|1> generating INFORMATIONAL request 26 [ D ]
Aug 4 14:34:59 20[NET] <MAS|1> sending packet: from 192.168.22.58[4500] to 10.246.162.90[4500] (69 bytes)
Aug 4 14:34:59 22[NET] <MAS|1> received packet: from 10.246.162.90[4500] to 192.168.22.58[4500] (69 bytes)
Aug 4 14:34:59 22[ENC] <MAS|1> parsed INFORMATIONAL response 26 [ D ]
Aug 4 14:34:59 22[IKE] <MAS|1> received DELETE for ESP CHILD_SA with SPI c08d1db0
Aug 4 14:34:59 22[IKE] <MAS|1> CHILD_SA closed
Aug 4 14:34:59 22[KNL] <MAS|1> deleting policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:34:59 22[KNL] <MAS|1> deleting policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:34:59 22[KNL] <MAS|1> deleting policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:34:59 22[KNL] <MAS|1> deleting policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:34:59 22[KNL] <MAS|1> deleting policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:34:59 22[KNL] <MAS|1> deleting policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:34:59 22[KNL] <MAS|1> deleting SAD entry with SPI 000057cd (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> deleted SAD entry with SPI 000057cd (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> deleting SAD entry with SPI c33457c5 (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> deleted SAD entry with SPI c33457c5 (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> deleting SAD entry with SPI 00007526 (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> deleted SAD entry with SPI 00007526 (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> deleting SAD entry with SPI c08d1db0 (mark 0/0x00000000)
Aug 4 14:34:59 22[KNL] <MAS|1> deleted SAD entry with SPI c08d1db0 (mark 0/0x00000000)
systemctl restart networking
Aug 4 14:35:02 16[IKE] <MAS|1> reauthenticating IKE_SA MAS[1]
Aug 4 14:35:02 16[KNL] <MAS|1> 192.168.22.58 is on interface eth0
Aug 4 14:35:02 16[IKE] <MAS|1> installing new virtual IP 172.16.1.1
Aug 4 14:35:02 16[KNL] <MAS|1> virtual IP 172.16.1.1 installed on eth0
Aug 4 14:35:02 16[IKE] <MAS|1> initiating IKE_SA MAS[2] to 10.246.162.90
Aug 4 14:35:02 16[ENC] <MAS|1> generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(HASH_ALG) ]
Aug 4 14:35:02 16[NET] <MAS|1> sending packet: from 192.168.22.58[4500] to 10.246.162.90[4500] (412 bytes)
Aug 4 14:35:02 05[NET] <MAS|2> received packet: from 10.246.162.90[4500] to 192.168.22.58[4500] (409 bytes)
Aug 4 14:35:02 05[ENC] <MAS|2> parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(HASH_ALG) N(MULT_AUTH) ]
Aug 4 14:35:02 05[IKE] <MAS|2> local host is behind NAT, sending keep alives
Aug 4 14:35:02 05[IKE] <MAS|2> remote host is behind NAT
...
Aug 4 14:35:02 05[IKE] <MAS|2> establishing CHILD_SA MAS
Aug 4 14:35:02 05[KNL] <MAS|2> got SPI cd3b3392
Aug 4 14:35:02 05[KNL] <MAS|2> got CPI 30b5
Aug 4 14:35:02 05[ENC] <MAS|2> generating IKE_AUTH request 1 [ IDi CERT IDr AUTH CPRQ(ADDR DNS) N(IPCOMP_SUP) SA TSi TSr N(MOBIKE_SUP) N(NO_ADD_ADDR) N(MULT_AUTH) N(EAP_ONLY) ]
Aug 4 14:35:02 05[NET] <MAS|2> sending packet: from 192.168.22.58[4500] to 10.246.162.90[4500] (1284 bytes)
Aug 4 14:35:02 25[NET] <MAS|2> received packet: from 10.246.162.90[4500] to 192.168.22.58[4500] (2394 bytes)
...
Aug 4 14:35:02 25[IKE] <MAS|2> scheduling reauthentication in 98s
Aug 4 14:35:02 25[IKE] <MAS|2> maximum IKE_SA lifetime 108s
Aug 4 14:35:02 25[IKE] <MAS|2> installing DNS server 172.16.0.1 via resolvconf
Aug 4 14:35:02 25[KNL] <MAS|2> deleting virtual IP 172.16.1.1
Aug 4 14:35:02 25[KNL] <MAS|2> 192.168.22.58 is on interface eth0
Aug 4 14:35:02 25[IKE] <MAS|2> installing new virtual IP 172.16.1.1
Aug 4 14:35:02 25[KNL] <MAS|2> virtual IP 172.16.1.1 installed on eth0
Aug 4 14:35:02 25[KNL] <MAS|2> adding SAD entry with SPI 000030b5 and reqid {1} (mark 0/0x00000000)
Aug 4 14:35:02 25[KNL] <MAS|2> using compression algorithm IPCOMP_DEFLATE
Aug 4 14:35:02 25[KNL] <MAS|2> adding SAD entry with SPI cd3b3392 and reqid {1} (mark 0/0x00000000)
Aug 4 14:35:02 25[KNL] <MAS|2> using encryption algorithm AES_CTR with key size 288
Aug 4 14:35:02 25[KNL] <MAS|2> using integrity algorithm HMAC_SHA2_512_256 with key size 512
Aug 4 14:35:02 25[KNL] <MAS|2> using replay window of 32 packets
Aug 4 14:35:02 25[KNL] <MAS|2> using extended sequence numbers (ESN)
Aug 4 14:35:02 25[KNL] <MAS|2> adding SAD entry with SPI 00001b8e and reqid {1} (mark 0/0x00000000)
Aug 4 14:35:02 25[KNL] <MAS|2> using compression algorithm IPCOMP_DEFLATE
Aug 4 14:35:02 25[KNL] <MAS|2> adding SAD entry with SPI c02a32f8 and reqid {1} (mark 0/0x00000000)
Aug 4 14:35:02 25[KNL] <MAS|2> using encryption algorithm AES_CTR with key size 288
Aug 4 14:35:02 25[KNL] <MAS|2> using integrity algorithm HMAC_SHA2_512_256 with key size 512
Aug 4 14:35:02 25[KNL] <MAS|2> using replay window of 32 packets
Aug 4 14:35:02 25[KNL] <MAS|2> using extended sequence numbers (ESN)
Aug 4 14:35:02 25[KNL] <MAS|2> policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:02 25[KNL] <MAS|2> policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:02 25[KNL] <MAS|2> policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:02 25[KNL] <MAS|2> policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:02 25[KNL] <MAS|2> updating policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:35:02 25[KNL] <MAS|2> policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:02 25[KNL] <MAS|2> updating policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:35:02 25[KNL] <MAS|2> policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:02 25[KNL] <MAS|2> updating policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:35:02 25[KNL] <MAS|2> getting a local address in traffic selector 172.16.1.0/24
Aug 4 14:35:02 25[KNL] <MAS|2> using host 172.16.1.1
Aug 4 14:35:02 25[KNL] <MAS|2> using 192.168.22.1 as nexthop to reach 10.246.162.90/32
Aug 4 14:35:02 25[KNL] <MAS|2> 192.168.22.58 is on interface eth0
Aug 4 14:35:02 25[IKE] <MAS|2> CHILD_SA MAS{13} established with SPIs cd3b3392_i c02a32f8_o and TS 172.16.1.0/24 === 172.16.0.1/32
Aug 4 14:35:02 25[KNL] <MAS|2> 192.168.22.58 is on interface eth0
Aug 4 14:35:02 30[KNL] getting iface index for eth0
Aug 4 14:35:02 25[IKE] <MAS|2> received AUTH_LIFETIME of 20176s, reauthentication already scheduled in 98s
Aug 4 14:35:02 25[IKE] <MAS|2> peer supports MOBIKE
Aug 4 14:35:02 31[IKE] <MAS|1> deleting IKE_SA MAS[1] between ...
Aug 4 14:35:02 31[IKE] <MAS|1> sending DELETE for IKE_SA MAS[1]
Aug 4 14:35:02 31[ENC] <MAS|1> generating INFORMATIONAL request 27 [ D ]
Aug 4 14:35:02 31[NET] <MAS|1> sending packet: from 192.168.22.58[4500] to 10.246.162.90[4500] (65 bytes)
Aug 4 14:35:02 04[NET] <MAS|1> received packet: from 10.246.162.90[4500] to 192.168.22.58[4500] (57 bytes)
Aug 4 14:35:02 04[ENC] <MAS|1> parsed INFORMATIONAL response 27 [ ]
Aug 4 14:35:02 04[IKE] <MAS|1> IKE_SA deleted
Aug 4 14:35:02 04[KNL] <MAS|1> deleting policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:35:02 04[KNL] <MAS|1> deleting policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:35:02 04[KNL] <MAS|1> deleting policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:35:02 04[KNL] <MAS|1> deleting policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:35:02 04[KNL] <MAS|1> deleting policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:35:02 04[KNL] <MAS|1> deleting policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> policy still used by another CHILD_SA, not removed
Aug 4 14:35:02 04[KNL] <MAS|1> deleting SAD entry with SPI 00001787 (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> deleted SAD entry with SPI 00001787 (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> deleting SAD entry with SPI cac1ab8a (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> deleted SAD entry with SPI cac1ab8a (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> deleting SAD entry with SPI 0000cb96 (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> deleted SAD entry with SPI 0000cb96 (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> deleting SAD entry with SPI cad23e60 (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> deleted SAD entry with SPI cad23e60 (mark 0/0x00000000)
Aug 4 14:35:02 04[KNL] <MAS|1> deleting virtual IP 172.16.1.1
Aug 4 14:35:04 02[KNL] <MAS|2> querying SAD entry with SPI cd3b3392 (mark 0/0x00000000)
Aug 4 14:35:04 02[KNL] <MAS|2> querying SAD entry with SPI c02a32f8 (mark 0/0x00000000)
DPD after:
Aug 4 14:35:05 13[KNL] received a XFRM_MSG_EXPIRE
Aug 4 14:35:05 13[KNL] creating rekey job for CHILD_SA ESP/0xcd3b3392/192.168.22.58
Aug 4 14:35:05 13[IKE] <MAS|2> establishing CHILD_SA MAS{1}
Aug 4 14:35:05 13[KNL] <MAS|2> got SPI c5cf7528
Aug 4 14:35:05 13[KNL] <MAS|2> got CPI 939c
Aug 4 14:35:05 13[ENC] <MAS|2> generating CREATE_CHILD_SA request 2 [ N(REKEY_SA) N(IPCOMP_SUP) SA No KE TSi TSr ]
Aug 4 14:35:05 13[NET] <MAS|2> sending packet: from 192.168.22.58[4500] to 10.246.162.90[4500] (444 bytes)
Aug 4 14:35:05 15[NET] <MAS|2> received packet: from 10.246.162.90[4500] to 192.168.22.58[4500] (344 bytes)
Aug 4 14:35:05 15[ENC] <MAS|2> parsed CREATE_CHILD_SA response 2 [ N(IPCOMP_SUP) SA No KE TSi TSr ]
Aug 4 14:35:05 15[KNL] <MAS|2> adding SAD entry with SPI 0000939c and reqid {1} (mark 0/0x00000000)
Aug 4 14:35:05 15[KNL] <MAS|2> using compression algorithm IPCOMP_DEFLATE
Aug 4 14:35:05 15[KNL] <MAS|2> adding SAD entry with SPI c5cf7528 and reqid {1} (mark 0/0x00000000)
Aug 4 14:35:05 15[KNL] <MAS|2> using encryption algorithm AES_CTR with key size 288
Aug 4 14:35:05 15[KNL] <MAS|2> using integrity algorithm HMAC_SHA2_512_256 with key size 512
Aug 4 14:35:05 15[KNL] <MAS|2> using replay window of 32 packets
Aug 4 14:35:05 15[KNL] <MAS|2> using extended sequence numbers (ESN)
Aug 4 14:35:05 15[KNL] <MAS|2> adding SAD entry with SPI 00009b84 and reqid {1} (mark 0/0x00000000)
Aug 4 14:35:05 15[KNL] <MAS|2> using compression algorithm IPCOMP_DEFLATE
Aug 4 14:35:05 15[KNL] <MAS|2> adding SAD entry with SPI c4731c8c and reqid {1} (mark 0/0x00000000)
Aug 4 14:35:05 15[KNL] <MAS|2> using encryption algorithm AES_CTR with key size 288
Aug 4 14:35:05 15[KNL] <MAS|2> using integrity algorithm HMAC_SHA2_512_256 with key size 512
Aug 4 14:35:05 15[KNL] <MAS|2> using replay window of 32 packets
Aug 4 14:35:05 15[KNL] <MAS|2> using extended sequence numbers (ESN)
Aug 4 14:35:05 15[KNL] <MAS|2> policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:05 15[KNL] <MAS|2> policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:05 15[KNL] <MAS|2> policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:05 15[KNL] <MAS|2> policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:05 15[KNL] <MAS|2> updating policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:35:05 15[KNL] <MAS|2> policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:05 15[KNL] <MAS|2> updating policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:35:05 15[KNL] <MAS|2> policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000) already exists, increasing refcount
Aug 4 14:35:05 15[KNL] <MAS|2> updating policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:35:05 15[KNL] <MAS|2> getting a local address in traffic selector 172.16.1.0/24
Aug 4 14:35:05 15[KNL] <MAS|2> no local address found in traffic selector 172.16.1.0/24
Aug 4 14:35:05 15[IKE] <MAS|2> CHILD_SA MAS{14} established with SPIs c5cf7528_i c4731c8c_o and TS 172.16.1.0/24 === 172.16.0.1/32
Aug 4 14:35:05 15[KNL] <MAS|2> querying SAD entry with SPI cd3b3392 (mark 0/0x00000000)
Aug 4 14:35:05 15[KNL] <MAS|2> querying SAD entry with SPI c02a32f8 (mark 0/0x00000000)
Aug 4 14:35:05 15[IKE] <MAS|2> closing CHILD_SA MAS{13} with SPIs cd3b3392_i (0 bytes) c02a32f8_o (0 bytes) and TS 172.16.1.0/24 === 172.16.0.1/32
Aug 4 14:35:05 15[IKE] <MAS|2> sending DELETE for ESP CHILD_SA with SPI cd3b3392
Aug 4 14:35:05 15[ENC] <MAS|2> generating INFORMATIONAL request 3 [ D ]
Aug 4 14:35:05 15[NET] <MAS|2> sending packet: from 192.168.22.58[4500] to 10.246.162.90[4500] (69 bytes)
Aug 4 14:35:05 17[NET] <MAS|2> received packet: from 10.246.162.90[4500] to 192.168.22.58[4500] (69 bytes)
Aug 4 14:35:05 17[ENC] <MAS|2> parsed INFORMATIONAL response 3 [ D ]
Aug 4 14:35:05 17[IKE] <MAS|2> received DELETE for ESP CHILD_SA with SPI c02a32f8
Aug 4 14:35:05 17[IKE] <MAS|2> CHILD_SA closed
Aug 4 14:35:05 17[KNL] <MAS|2> deleting policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> policy still used by another CHILD_SA, not removed
Aug 4 14:35:05 17[KNL] <MAS|2> deleting policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> policy still used by another CHILD_SA, not removed
Aug 4 14:35:05 17[KNL] <MAS|2> deleting policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> policy still used by another CHILD_SA, not removed
Aug 4 14:35:05 17[KNL] <MAS|2> deleting policy 172.16.1.0/24 === 172.16.0.1/32 out (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> policy still used by another CHILD_SA, not removed
Aug 4 14:35:05 17[KNL] <MAS|2> deleting policy 172.16.0.1/32 === 172.16.1.0/24 in (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> policy still used by another CHILD_SA, not removed
Aug 4 14:35:05 17[KNL] <MAS|2> deleting policy 172.16.0.1/32 === 172.16.1.0/24 fwd (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> policy still used by another CHILD_SA, not removed
Aug 4 14:35:05 17[KNL] <MAS|2> deleting SAD entry with SPI 000030b5 (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> deleted SAD entry with SPI 000030b5 (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> deleting SAD entry with SPI cd3b3392 (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> deleted SAD entry with SPI cd3b3392 (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> deleting SAD entry with SPI 00001b8e (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> deleted SAD entry with SPI 00001b8e (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> deleting SAD entry with SPI c02a32f8 (mark 0/0x00000000)
Aug 4 14:35:05 17[KNL] <MAS|2> deleted SAD entry with SPI c02a32f8 (mark 0/0x00000000)
Do you use make-before-break reauthentication?
Setting make_before_break = no resolves the isse. However, the IP address will be reinstallaed only after expiration of ikelifetime. Can this situation be handled by strongSwan prior ikelifetime is ended?
To get a more stable behavior you could perhaps set charon.install_virtual_ip_on = lo ...
Hmm... I have not imagined that virtual IP can be installed in such a way. This configuration fixed the issue permanently even with make_before_break = yes.
#5 Updated by Tobias Brunner over 4 years ago
Do you use make-before-break reauthentication?
Setting
make_before_break = noresolves the isse.
I see. From the log it's clear what happens. First the new SA is initiated and the VIP is copied to it (in theory this increases the refcount, as the VIP is already in use, however, because the VIP was deleted in the kernel, this is like a new install):
Aug 4 14:35:02 16[IKE] <MAS|1> reauthenticating IKE_SA MAS[1] Aug 4 14:35:02 16[KNL] <MAS|1> 192.168.22.58 is on interface eth0 Aug 4 14:35:02 16[IKE] <MAS|1> installing new virtual IP 172.16.1.1 Aug 4 14:35:02 16[KNL] <MAS|1> virtual IP 172.16.1.1 installed on eth0 Aug 4 14:35:02 16[IKE] <MAS|1> initiating IKE_SA MAS[2] to 10.246.162.90
The following is caused by a call to clear_virtual_ips() followed by adding the actually assigned VIPs (again, this should, in theory, only affect the reference count):
Aug 4 14:35:02 25[KNL] <MAS|2> deleting virtual IP 172.16.1.1 Aug 4 14:35:02 25[KNL] <MAS|2> 192.168.22.58 is on interface eth0 Aug 4 14:35:02 25[IKE] <MAS|2> installing new virtual IP 172.16.1.1 Aug 4 14:35:02 25[KNL] <MAS|2> virtual IP 172.16.1.1 installed on eth0
Later the replaced IKE_SA is deleted, which unfortunately removes the VIP:
Aug 4 14:35:02 04[KNL] <MAS|1> deleting virtual IP 172.16.1.1
However, the IP address will be reinstallaed only after expiration of
ikelifetime.
Yes, without make-before-break reauthentication the old IKE_SA is deleted first and will not affect the VIP installed by the new IKE_SA later. But in both cases the virtual IP is not reinstalled.
Can this situation be handled by strongSwan prior ikelifetime is ended?
Theoretically, the VIP could be reinstalled if the interface comes up gain but that could be tricky due to race conditions (I'd have to take a close look, though). And...
To get a more stable behavior you could perhaps set charon.install_virtual_ip_on = lo ...
Hmm... I have not imagined that virtual IP can be installed in such a way. This configuration fixed the issue permanently even with
make_before_break = yes.
...this workaround usually works fine in dynamic environments. Edit: In dynamic environments where the network connectivity changes significantly (e.g. the IP changes, or a switch from one to another interface occurs) the virtual IP would be re-installed automatically on the outbound interface when the source IP address of the CHILD_SA is updated. So this is mainly a problem if interfaces (or even just IPs) disappear and then reappear with the same IPs/routes.