Project

General

Profile

Issue #2394

IP is not assigned after re-authentication

Added by Oleksandr Kazymyrov about 2 years ago. Updated about 2 years ago.

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 about 2 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 about 2 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 about 2 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 about 2 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 about 2 years ago

Do you use make-before-break reauthentication?

Setting make_before_break = no resolves 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.

Also available in: Atom PDF