Project

General

Profile

Issue #2840

Old policy not fully removed - resulting in "unable to install policy"

Added by Marcel Müller over 3 years ago. Updated over 3 years ago.

Status:
Closed
Priority:
Normal
Category:
libcharon
Affected version:
5.6.2
Resolution:
No change required

Description

Hello everyone,

I got an issue which rarley occurs, so it's quite hard to debug (sorry). It looks like an policy for an IKEv2 connection is not fully removed from ip xfrm pol resulting in the following error message on the next connect:

Nov 29 14:49:19 29[CFG] <Mobile|98257> unable to install policy 172.31.0.0/16 === 172.31.11.64/32 out for reqid 5258, the same policy for reqid 743 exists

The lease itself is marked as offline by strongswan:

root@strongSwan:~# ipsec leases
Leases in pool '172.31.11.64-172.31.11.128', usage: 4/65, 1 online
(...)
     172.31.11.64   offline   '(name)'

but is still there in ip xfrm pol:

src 172.31.0.0/16 dst 172.31.11.64/32
        dir out priority 375423 ptype main
        tmpl src 172.31.1.5 dst (...)
                proto esp spi 0x07a0d6eb reqid 743 mode tunnel

Some background:
- This is an IKEv2 connection made by an iPhone/iPad
- The error only occurs (atleast it looks like this), when the phone is connected via Wifi to an LTE router
- The LTE router is getting a private address by the carrier, so there's carrier-grade NAT involved here.
- The cellular connection is stable most of the time, but gets unstable once in a while.
- The current workaround (without restarting strongswan or manually removing the policy) is to change the pool assigned to the connection to a different range and reload ipsec.conf. After this connecting works fine and vpn is usable.

Log:

Nov 29 14:49:19 29[CFG] <Mobile|98257> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 14:49:19 29[CFG] <Mobile|98257> selected proposal: ESP:AES_CBC_128/HMAC_SHA2_256_128/NO_EXT_SEQ
Nov 29 14:49:19 29[KNL] <Mobile|98257> got SPI c73eb806
Nov 29 14:49:19 29[CFG] <Mobile|98257> selecting traffic selectors for us:
Nov 29 14:49:19 29[CFG] <Mobile|98257>  config: 172.31.0.0/16, received: 0.0.0.0/0 => match: 172.31.0.0/16
Nov 29 14:49:19 29[CFG] <Mobile|98257>  config: 172.31.0.0/16, received: ::/0 => no match
Nov 29 14:49:19 29[CFG] <Mobile|98257> selecting traffic selectors for other:
Nov 29 14:49:19 29[CFG] <Mobile|98257>  config: 172.31.11.64/32, received: 0.0.0.0/0 => match: 172.31.11.64/32
Nov 29 14:49:19 29[CFG] <Mobile|98257>  config: 172.31.11.64/32, received: ::/0 => no match
Nov 29 14:49:19 29[KNL] <Mobile|98257> adding SAD entry with SPI c73eb806 and reqid {5258}
Nov 29 14:49:19 29[KNL] <Mobile|98257>   using encryption algorithm AES_CBC with key size 128
Nov 29 14:49:19 29[KNL] <Mobile|98257>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 14:49:19 29[KNL] <Mobile|98257>   using replay window of 32 packets
Nov 29 14:49:19 29[KNL] <Mobile|98257> adding SAD entry with SPI 0298c0b9 and reqid {5258}
Nov 29 14:49:19 29[KNL] <Mobile|98257>   using encryption algorithm AES_CBC with key size 128
Nov 29 14:49:19 29[KNL] <Mobile|98257>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 14:49:19 29[KNL] <Mobile|98257>   using replay window of 0 packets
Nov 29 14:49:19 29[KNL] <Mobile|98257> adding policy 172.31.11.64/32 === 172.31.0.0/16 in [priority 375423, refcount 1]
Nov 29 14:49:19 29[KNL] <Mobile|98257> adding policy 172.31.11.64/32 === 172.31.0.0/16 fwd [priority 375423, refcount 1]
Nov 29 14:49:19 29[CFG] <Mobile|98257> unable to install policy 172.31.0.0/16 === 172.31.11.64/32 out for reqid 5258, the same policy for reqid 743 exists
Nov 29 14:49:19 29[KNL] <Mobile|98257> deleting policy 172.31.0.0/16 === 172.31.11.64/32 out
Nov 29 14:49:19 29[KNL] <Mobile|98257> policy still used by another CHILD_SA, not removed
Nov 29 14:49:19 29[KNL] <Mobile|98257> not updating policy 172.31.0.0/16 === 172.31.11.64/32 out [priority 375423, refcount 1]
Nov 29 14:49:19 29[KNL] <Mobile|98257> deleting policy 172.31.11.64/32 === 172.31.0.0/16 in
Nov 29 14:49:19 29[KNL] <Mobile|98257> deleting policy 172.31.11.64/32 === 172.31.0.0/16 fwd
Nov 29 14:49:19 29[KNL] <Mobile|98257> deleting SAD entry with SPI c73eb806
Nov 29 14:49:19 29[KNL] <Mobile|98257> deleted SAD entry with SPI c73eb806
Nov 29 14:49:19 29[KNL] <Mobile|98257> deleting SAD entry with SPI 0298c0b9
Nov 29 14:49:19 29[KNL] <Mobile|98257> deleted SAD entry with SPI 0298c0b9
Nov 29 14:49:19 31[IKE] <Mobile|98257> deleting IKE_SA Mobile[98257] between 172.31.1.5[(fqdn)]...(ip)[(name)]
Nov 29 14:49:19 31[IKE] <Mobile|98257> IKE_SA deleted
Nov 29 14:49:19 31[CFG] <Mobile|98257> lease 172.31.11.64 by '(name)' went offline

Config:

conn win7machine
        leftcert=serverCert2014.pem
        leftsubnet=172.31.0.0/16
        right=%any
        rightsourceip=172.31.11.70-172.31.11.128
        keyexchange=ikev2

        # First proposal is for Win7, second for iOS 10
        ike=aes256-sha1-modp1024,aes128-sha2_256-modp2048!
        esp=aes256-sha1,aes128-sha2_256-modp2048!
        rekey=no
        rightdns=172.31.1.9
        fragmentation=yes

conn iosikev2
        also=win7machine
        leftid=<fqdn>
        dpddelay=15m

conn Mobile
        also=iosikev2
        rightid="<name>" 
        rightcert=<name>.pem
        auto=add

It looks like the problem only occurs in this constellation with a LTE router.

I now raised KNL and CFG debug level to 2 and have a working connection right now. I'm waiting for this to happen again, maybe to get a clue what happens. Any other idea what this might cause or how to debug it further?

Thanks!

History

#1 Updated by Marcel Müller over 3 years ago

Sorry, forgot to add, this is a Debian 8.10 machine with the following kernel:
Linux strongSwan 4.9.0-0.bpo.4-amd64 #1 SMP Debian 4.9.51-1~bpo8+1 (2017-10-17) x86_64 GNU/Linux

#2 Updated by Tobias Brunner over 3 years ago

  • Status changed from New to Feedback

Not much to go on from this information. It looks like the outbound policy was not updated/deleted correctly at some point plus that there was apparently a time when no CHILD_SA actually referenced the reqid, so that a new reqid could have been allocated for the same traffic selectors by the new SA. Please report back with the complete logs once you were able to reproduce the issue.

#3 Updated by Marcel Müller over 3 years ago

Thanks Tobias!
Yes, at the time I took the command outputs there was no CHILD_SA in ipsec status. I'll see if I can reproduce this and report back.

#4 Updated by Marcel Müller over 3 years ago

Hi Tobias,

it happened again and I got the logs with KNL and CFG level set to 2 (I skipped some query entries).

Nov 29 20:52:51 26[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:52:51 26[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:53:11 10[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:53:11 10[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:53:31 08[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:53:31 08[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:53:51 15[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:53:51 15[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:54:11 07[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:54:11 07[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:54:31 21[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:54:31 21[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:54:51 15[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:54:51 15[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:55:11 30[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:55:11 30[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:55:31 23[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:55:31 23[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:55:51 11[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:55:51 11[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:56:11 26[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:56:11 26[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:56:31 12[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:56:31 12[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:56:33 31[CFG] <Mobile|98756> selecting proposal:
Nov 29 20:56:33 31[CFG] <Mobile|98756>   no acceptable ENCRYPTION_ALGORITHM found
Nov 29 20:56:33 31[CFG] <Mobile|98756> selecting proposal:
Nov 29 20:56:33 31[CFG] <Mobile|98756>   proposal matches
Nov 29 20:56:33 31[CFG] <Mobile|98756> received proposals: ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 20:56:33 31[CFG] <Mobile|98756> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 20:56:33 31[CFG] <Mobile|98756> selected proposal: ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 20:56:33 31[KNL] <Mobile|98756> got SPI c2b617df
Nov 29 20:56:33 31[CFG] <Mobile|98756> selecting traffic selectors for us:
Nov 29 20:56:33 31[CFG] <Mobile|98756>  config: 172.31.0.0/16, received: 172.31.0.0/16 => match: 172.31.0.0/16
Nov 29 20:56:33 31[CFG] <Mobile|98756> selecting traffic selectors for other:
Nov 29 20:56:33 31[CFG] <Mobile|98756>  config: 172.31.11.73/32, received: 172.31.11.73/32 => match: 172.31.11.73/32
Nov 29 20:56:33 31[KNL] <Mobile|98756> adding SAD entry with SPI c2b617df and reqid {5456}
Nov 29 20:56:33 31[KNL] <Mobile|98756>   using encryption algorithm AES_CBC with key size 128
Nov 29 20:56:33 31[KNL] <Mobile|98756>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 20:56:33 31[KNL] <Mobile|98756>   using replay window of 32 packets
Nov 29 20:56:33 31[KNL] <Mobile|98756> adding SAD entry with SPI 0f2439c6 and reqid {5456}
Nov 29 20:56:33 31[KNL] <Mobile|98756>   using encryption algorithm AES_CBC with key size 128
Nov 29 20:56:33 31[KNL] <Mobile|98756>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 20:56:33 31[KNL] <Mobile|98756>   using replay window of 0 packets
Nov 29 20:56:33 31[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 in already exists, increasing refcount
Nov 29 20:56:33 31[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 2]
Nov 29 20:56:33 31[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 fwd already exists, increasing refcount
Nov 29 20:56:33 31[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 2]
Nov 29 20:56:33 31[IKE] <Mobile|98756> inbound CHILD_SA Mobile{80562} established with SPIs c2b617df_i 0f2439c6_o and TS 172.31.0.0/16 === 172.31.11.73/32
Nov 29 20:56:36 27[KNL] <Mobile|98756> querying SAD entry with SPI cf6c89bd
Nov 29 20:56:36 27[KNL] <Mobile|98756> querying SAD entry with SPI 027a5561
Nov 29 20:56:36 27[IKE] <Mobile|98756> closing CHILD_SA Mobile{80525} with SPIs cf6c89bd_i (0 bytes) 027a5561_o (0 bytes) and TS 172.31.0.0/16 === 172.31.11.73/32
Nov 29 20:56:36 27[KNL] <Mobile|98756> policy 172.31.0.0/16 === 172.31.11.73/32 out already exists, increasing refcount
Nov 29 20:56:36 27[KNL] <Mobile|98756> updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 2]
Nov 29 20:56:36 27[KNL] <Mobile|98756> getting a local address in traffic selector 172.31.0.0/16
Nov 29 20:56:36 27[KNL] <Mobile|98756> using host 172.31.1.5
Nov 29 20:56:36 27[KNL] <Mobile|98756> getting iface name for index 2
Nov 29 20:56:36 27[KNL] <Mobile|98756> using 172.31.0.254 as nexthop and eth0 as dev to reach <IP>/32
Nov 29 20:56:36 27[IKE] <Mobile|98756> outbound CHILD_SA Mobile{80562} established with SPIs c2b617df_i 0f2439c6_o and TS 172.31.0.0/16 === 172.31.11.73/32
Nov 29 20:56:36 27[KNL] <Mobile|98756> deleting policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:56:36 27[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 20:56:36 27[KNL] <Mobile|98756> not updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 1]
Nov 29 20:56:36 27[KNL] <Mobile|98756> deleting SAD entry with SPI 027a5561
Nov 29 20:56:36 27[KNL] <Mobile|98756> deleted SAD entry with SPI 027a5561
Nov 29 20:56:38 13[CFG] <Mobile|98756> selecting proposal:
Nov 29 20:56:38 13[CFG] <Mobile|98756>   no acceptable ENCRYPTION_ALGORITHM found
Nov 29 20:56:38 13[CFG] <Mobile|98756> selecting proposal:
Nov 29 20:56:38 13[CFG] <Mobile|98756>   proposal matches
Nov 29 20:56:38 13[CFG] <Mobile|98756> received proposals: ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 20:56:38 13[CFG] <Mobile|98756> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 20:56:38 13[CFG] <Mobile|98756> selected proposal: ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 20:56:38 13[KNL] <Mobile|98756> got SPI cd75c2e2
Nov 29 20:56:38 13[CFG] <Mobile|98756> selecting traffic selectors for us:
Nov 29 20:56:38 13[CFG] <Mobile|98756>  config: 172.31.0.0/16, received: 172.31.0.0/16 => match: 172.31.0.0/16
Nov 29 20:56:38 13[CFG] <Mobile|98756> selecting traffic selectors for other:
Nov 29 20:56:38 13[CFG] <Mobile|98756>  config: 172.31.11.73/32, received: 172.31.11.73/32 => match: 172.31.11.73/32
Nov 29 20:56:38 13[KNL] <Mobile|98756> adding SAD entry with SPI cd75c2e2 and reqid {5456}
Nov 29 20:56:38 13[KNL] <Mobile|98756>   using encryption algorithm AES_CBC with key size 128
Nov 29 20:56:38 13[KNL] <Mobile|98756>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 20:56:38 13[KNL] <Mobile|98756>   using replay window of 32 packets
Nov 29 20:56:38 13[KNL] <Mobile|98756> adding SAD entry with SPI 087ffcf9 and reqid {5456}
Nov 29 20:56:38 13[KNL] <Mobile|98756>   using encryption algorithm AES_CBC with key size 128
Nov 29 20:56:38 13[KNL] <Mobile|98756>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 20:56:38 13[KNL] <Mobile|98756>   using replay window of 0 packets
Nov 29 20:56:38 13[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 in already exists, increasing refcount
Nov 29 20:56:38 13[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 3]
Nov 29 20:56:38 13[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 fwd already exists, increasing refcount
Nov 29 20:56:38 13[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 3]
Nov 29 20:56:38 13[IKE] <Mobile|98756> inbound CHILD_SA Mobile{80563} established with SPIs cd75c2e2_i 087ffcf9_o and TS 172.31.0.0/16 === 172.31.11.73/32
Nov 29 20:56:41 21[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 in
Nov 29 20:56:41 21[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 20:56:41 21[KNL] <Mobile|98756> not updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 2]
Nov 29 20:56:41 21[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 fwd
Nov 29 20:56:41 21[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 20:56:41 21[KNL] <Mobile|98756> not updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 2]
Nov 29 20:56:41 21[KNL] <Mobile|98756> deleting SAD entry with SPI cf6c89bd
Nov 29 20:56:41 21[KNL] <Mobile|98756> deleted SAD entry with SPI cf6c89bd
Nov 29 20:56:41 09[KNL] <Mobile|98756> querying SAD entry with SPI c2b617df
Nov 29 20:56:41 09[KNL] <Mobile|98756> querying SAD entry with SPI 0f2439c6
Nov 29 20:56:41 09[IKE] <Mobile|98756> closing CHILD_SA Mobile{80562} with SPIs c2b617df_i (0 bytes) 0f2439c6_o (0 bytes) and TS 172.31.0.0/16 === 172.31.11.73/32
Nov 29 20:56:41 09[KNL] <Mobile|98756> policy 172.31.0.0/16 === 172.31.11.73/32 out already exists, increasing refcount
Nov 29 20:56:41 09[KNL] <Mobile|98756> updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 2]
Nov 29 20:56:41 09[KNL] <Mobile|98756> getting a local address in traffic selector 172.31.0.0/16
Nov 29 20:56:41 09[KNL] <Mobile|98756> using host 172.31.1.5
Nov 29 20:56:41 09[KNL] <Mobile|98756> getting iface name for index 2
Nov 29 20:56:41 09[KNL] <Mobile|98756> using 172.31.0.254 as nexthop and eth0 as dev to reach <IP>/32
Nov 29 20:56:41 09[IKE] <Mobile|98756> outbound CHILD_SA Mobile{80563} established with SPIs cd75c2e2_i 087ffcf9_o and TS 172.31.0.0/16 === 172.31.11.73/32
Nov 29 20:56:41 09[KNL] <Mobile|98756> deleting policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:56:41 09[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 20:56:41 09[KNL] <Mobile|98756> not updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 1]
Nov 29 20:56:41 09[KNL] <Mobile|98756> deleting SAD entry with SPI 0f2439c6
Nov 29 20:56:41 09[KNL] <Mobile|98756> deleted SAD entry with SPI 0f2439c6
Nov 29 20:56:46 27[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 in
Nov 29 20:56:46 27[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 20:56:46 27[KNL] <Mobile|98756> not updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 1]
Nov 29 20:56:46 27[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 fwd
Nov 29 20:56:46 27[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 20:56:46 27[KNL] <Mobile|98756> not updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 1]
Nov 29 20:56:46 27[KNL] <Mobile|98756> deleting SAD entry with SPI c2b617df
Nov 29 20:56:46 27[KNL] <Mobile|98756> deleted SAD entry with SPI c2b617df
Nov 29 20:56:51 14[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:56:51 14[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:57:01 11[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:57:01 11[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:57:21 29[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:57:21 29[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:57:32 06[KNL] <Mobile|98756> querying policy 172.31.11.73/32 === 172.31.0.0/16 in
Nov 29 20:57:32 06[KNL] <Mobile|98756> querying policy 172.31.11.73/32 === 172.31.0.0/16 fwd
Nov 29 20:57:32 06[KNL] <Mobile|98756> querying SAD entry with SPI cd75c2e2
Nov 29 20:57:41 25[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:57:41 25[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:58:01 11[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:58:01 11[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:58:21 17[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:58:21 17[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:58:41 06[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:58:41 06[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:59:01 19[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:59:01 19[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:59:21 05[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:59:21 05[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 20:59:41 30[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 20:59:41 30[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:00:01 10[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:00:01 10[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:00:21 29[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:00:21 29[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:00:41 24[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:00:41 24[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:01:01 30[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:01:01 30[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:01:21 19[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:01:21 19[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:01:41 11[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:01:41 11[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:02:01 06[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:02:01 06[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:02:21 23[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:02:21 23[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9

Nov 29 21:19:21 04[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:19:21 04[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:19:24 19[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:19:24 19[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:19:44 10[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:19:44 10[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:19:47 09[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:19:47 09[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:20:07 20[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:20:07 20[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:20:09 30[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:20:09 30[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:20:29 10[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:20:29 10[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:20:32 10[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:20:32 10[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:20:52 18[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:20:52 18[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:20:54 15[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:20:54 15[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9

Nov 29 21:20:56 09[CFG] <Mobile|98756> selecting proposal:
Nov 29 21:20:56 09[CFG] <Mobile|98756>   no acceptable ENCRYPTION_ALGORITHM found
Nov 29 21:20:56 09[CFG] <Mobile|98756> selecting proposal:
Nov 29 21:20:56 09[CFG] <Mobile|98756>   proposal matches
Nov 29 21:20:56 09[CFG] <Mobile|98756> received proposals: ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 21:20:56 09[CFG] <Mobile|98756> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 21:20:56 09[CFG] <Mobile|98756> selected proposal: ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 21:20:56 09[KNL] <Mobile|98756> got SPI c62783fd
Nov 29 21:20:56 09[CFG] <Mobile|98756> selecting traffic selectors for us:
Nov 29 21:20:56 09[CFG] <Mobile|98756>  config: 172.31.0.0/16, received: 172.31.0.0/16 => match: 172.31.0.0/16
Nov 29 21:20:56 09[CFG] <Mobile|98756> selecting traffic selectors for other:
Nov 29 21:20:56 09[CFG] <Mobile|98756>  config: 172.31.11.73/32, received: 172.31.11.73/32 => match: 172.31.11.73/32
Nov 29 21:20:56 09[KNL] <Mobile|98756> adding SAD entry with SPI c62783fd and reqid {5456}
Nov 29 21:20:56 09[KNL] <Mobile|98756>   using encryption algorithm AES_CBC with key size 128
Nov 29 21:20:56 09[KNL] <Mobile|98756>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 21:20:56 09[KNL] <Mobile|98756>   using replay window of 32 packets
Nov 29 21:20:56 09[KNL] <Mobile|98756> adding SAD entry with SPI 0bed6280 and reqid {5456}
Nov 29 21:20:56 09[KNL] <Mobile|98756>   using encryption algorithm AES_CBC with key size 128
Nov 29 21:20:56 09[KNL] <Mobile|98756>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 21:20:56 09[KNL] <Mobile|98756>   using replay window of 0 packets
Nov 29 21:20:56 09[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 in already exists, increasing refcount
Nov 29 21:20:56 09[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 2]
Nov 29 21:20:56 09[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 fwd already exists, increasing refcount
Nov 29 21:20:56 09[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 2]
Nov 29 21:20:56 09[IKE] <Mobile|98756> inbound CHILD_SA Mobile{80572} established with SPIs c62783fd_i 0bed6280_o and TS 172.31.0.0/16 === 172.31.11.73/32

Nov 29 21:22:28 23[KNL] <Mobile|98756> policy 172.31.0.0/16 === 172.31.11.73/32 out already exists, increasing refcount
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 2]
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:22:28 23[KNL] <Mobile|98756> not updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 1]
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 in
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:22:28 23[KNL] <Mobile|98756> not updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 1]
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 fwd
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:22:28 23[KNL] <Mobile|98756> not updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 1]
Nov 29 21:22:28 23[KNL] <Mobile|98756> querying SAD entry with SPI cd75c2e2 for update
Nov 29 21:22:28 23[KNL] <Mobile|98756> querying replay state from SAD entry with SPI cd75c2e2
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting SAD entry with SPI cd75c2e2
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleted SAD entry with SPI cd75c2e2
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating SAD entry with SPI cd75c2e2 from <IP>[26817]..172.31.1.5[4500] to <IP>[6898]..172.31.1.5[4500]
Nov 29 21:22:28 23[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9 for update
Nov 29 21:22:28 23[KNL] <Mobile|98756> querying replay state from SAD entry with SPI 087ffcf9
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting SAD entry with SPI 087ffcf9
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleted SAD entry with SPI 087ffcf9
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating SAD entry with SPI 087ffcf9 from 172.31.1.5[4500]..<IP>[26817] to 172.31.1.5[4500]..<IP>[6898]
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 in already exists, increasing refcount
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 2]
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 fwd already exists, increasing refcount
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 2]
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy 172.31.0.0/16 === 172.31.11.73/32 out already exists, increasing refcount
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 2]
Nov 29 21:22:28 23[KNL] <Mobile|98756> getting a local address in traffic selector 172.31.0.0/16
Nov 29 21:22:28 23[KNL] <Mobile|98756> using host 172.31.1.5
Nov 29 21:22:28 23[KNL] <Mobile|98756> getting iface name for index 2
Nov 29 21:22:28 23[KNL] <Mobile|98756> using 172.31.0.254 as nexthop and eth0 as dev to reach <IP>/32
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:22:28 23[KNL] <Mobile|98756> not updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 1]
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy 172.31.0.0/16 === 172.31.11.73/32 out already exists, increasing refcount
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 2]
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:22:28 23[KNL] <Mobile|98756> not updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 2]
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 in
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:22:28 23[KNL] <Mobile|98756> not updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 1]
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 fwd
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:22:28 23[KNL] <Mobile|98756> not updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 1]
Nov 29 21:22:28 23[KNL] <Mobile|98756> querying SAD entry with SPI c62783fd for update
Nov 29 21:22:28 23[KNL] <Mobile|98756> querying replay state from SAD entry with SPI c62783fd
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting SAD entry with SPI c62783fd
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleted SAD entry with SPI c62783fd
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating SAD entry with SPI c62783fd from <IP>[26817]..172.31.1.5[4500] to <IP>[6898]..172.31.1.5[4500]
Nov 29 21:22:28 23[KNL] <Mobile|98756> querying SAD entry with SPI 0bed6280 for update
Nov 29 21:22:28 23[KNL] <Mobile|98756> querying replay state from SAD entry with SPI 0bed6280
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting SAD entry with SPI 0bed6280
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleted SAD entry with SPI 0bed6280
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating SAD entry with SPI 0bed6280 from 172.31.1.5[4500]..<IP>[26817] to 172.31.1.5[4500]..<IP>[6898]
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 in already exists, increasing refcount
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 2]
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy 172.31.11.73/32 === 172.31.0.0/16 fwd already exists, increasing refcount
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 2]
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy 172.31.0.0/16 === 172.31.11.73/32 out already exists, increasing refcount
Nov 29 21:22:28 23[KNL] <Mobile|98756> updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 3]
Nov 29 21:22:28 23[KNL] <Mobile|98756> getting a local address in traffic selector 172.31.0.0/16
Nov 29 21:22:28 23[KNL] <Mobile|98756> using host 172.31.1.5
Nov 29 21:22:28 23[KNL] <Mobile|98756> getting iface name for index 2
Nov 29 21:22:28 23[KNL] <Mobile|98756> using 172.31.0.254 as nexthop and eth0 as dev to reach <IP>/32
Nov 29 21:22:28 23[KNL] <Mobile|98756> deleting policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:22:28 23[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:22:28 23[KNL] <Mobile|98756> not updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 2]

Nov 29 21:38:36 18[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:38:36 18[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:38:36 18[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:38:36 18[KNL] <Mobile|98756> querying SAD entry with SPI 0bed6280
Nov 29 21:38:39 05[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:38:39 05[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:38:39 05[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:38:39 05[KNL] <Mobile|98756> querying SAD entry with SPI 0bed6280
Nov 29 21:38:59 13[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:38:59 13[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:38:59 13[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:38:59 13[KNL] <Mobile|98756> querying SAD entry with SPI 0bed6280
Nov 29 21:39:19 19[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:39:19 19[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:39:19 19[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:39:19 19[KNL] <Mobile|98756> querying SAD entry with SPI 0bed6280
Nov 29 21:39:21 18[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:39:21 18[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:39:21 18[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:39:21 18[KNL] <Mobile|98756> querying SAD entry with SPI 0bed6280
Nov 29 21:39:41 24[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:39:41 24[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:39:41 24[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:39:41 24[KNL] <Mobile|98756> querying SAD entry with SPI 0bed6280
Nov 29 21:40:01 07[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:40:01 07[KNL] <Mobile|98756> querying SAD entry with SPI 087ffcf9
Nov 29 21:40:01 07[KNL] <Mobile|98756> querying policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:40:01 07[KNL] <Mobile|98756> querying SAD entry with SPI 0bed6280
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 in
Nov 29 21:40:17 07[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:40:17 07[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 1]
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 fwd
Nov 29 21:40:17 07[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:40:17 07[KNL] <Mobile|98756> updating policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 1]
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting SAD entry with SPI c62783fd
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleted SAD entry with SPI c62783fd
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting SAD entry with SPI 0bed6280
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleted SAD entry with SPI 0bed6280
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:40:17 07[KNL] <Mobile|98756> policy still used by another CHILD_SA, not removed
Nov 29 21:40:17 07[KNL] <Mobile|98756> not updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 1]
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 in
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting policy 172.31.11.73/32 === 172.31.0.0/16 fwd
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting SAD entry with SPI cd75c2e2
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleted SAD entry with SPI cd75c2e2
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleting SAD entry with SPI 087ffcf9
Nov 29 21:40:17 07[KNL] <Mobile|98756> deleted SAD entry with SPI 087ffcf9
Nov 29 21:40:17 07[CFG] <Mobile|98756> lease 172.31.11.73 by '' went offline
Nov 29 21:41:07 26[CFG] <98833> looking for an ike config for 172.31.1.5...<IP>
Nov 29 21:41:07 26[CFG] <98833>   candidate: %any...%any, prio 28
Nov 29 21:41:07 26[CFG] <98833>   candidate: %any...%any, prio 28
Nov 29 21:41:07 26[CFG] <98833>   candidate: %any...%any, prio 28
Nov 29 21:41:07 26[CFG] <98833>   candidate: %any...%any, prio 28
Nov 29 21:41:07 26[CFG] <98833>   candidate: %any...%any, prio 28
Nov 29 21:41:07 26[CFG] <98833>   candidate: %any...%any, prio 28
Nov 29 21:41:07 26[CFG] <98833>   candidate: %any...%any, prio 28
Nov 29 21:41:07 26[CFG] <98833>   candidate: %any...%any, prio 28
Nov 29 21:41:07 26[CFG] <98833> found matching ike config: %any...%any with prio 28
Nov 29 21:41:07 26[IKE] <98833> <IP> is initiating an IKE_SA
Nov 29 21:41:07 26[CFG] <98833> selecting proposal:
Nov 29 21:41:07 26[CFG] <98833>   no acceptable ENCRYPTION_ALGORITHM found
Nov 29 21:41:07 26[CFG] <98833> selecting proposal:
Nov 29 21:41:07 26[CFG] <98833>   proposal matches
Nov 29 21:41:07 26[CFG] <98833> received proposals: IKE:AES_CBC_128/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048
Nov 29 21:41:07 26[CFG] <98833> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024, IKE:AES_CBC_128/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048
Nov 29 21:41:07 26[CFG] <98833> selected proposal: IKE:AES_CBC_128/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048
Nov 29 21:41:08 27[CFG] <98833> looking for peer configs matching 172.31.1.5[<FQDN>]...<IP>[]
Nov 29 21:41:08 27[CFG] <98833>   candidate "win7chap", match: 20/1/28 (me/other/ike)
Nov 29 21:41:08 27[CFG] <98833>   candidate "Mobile", match: 20/20/28 (me/other/ike)
Nov 29 21:41:08 27[CFG] <Mobile|98833> selected peer config 'Mobile'
Nov 29 21:41:08 27[CFG] <Mobile|98833>   certificate "C=DE, O=<Cert>, CN=" key: 2048 bit RSA
Nov 29 21:41:08 27[CFG] <Mobile|98833>   using trusted ca certificate "C=DE, O=<Cert>, CN=<Cert> Root CA" 
Nov 29 21:41:08 27[CFG] <Mobile|98833> checking certificate status of "C=DE, O=<Cert>, CN=" 
Nov 29 21:41:08 27[CFG] <Mobile|98833> ocsp check skipped, no ocsp found
Nov 29 21:41:08 27[CFG] <Mobile|98833> certificate status is not available
Nov 29 21:41:08 27[CFG] <Mobile|98833>   certificate "C=DE, O=<Cert>, CN=<Cert> Root CA" key: 4096 bit RSA
Nov 29 21:41:08 27[CFG] <Mobile|98833>   reached self-signed root ca with a path length of 0
Nov 29 21:41:08 27[CFG] <Mobile|98833>   using trusted certificate "C=DE, O=<Cert>, CN=" 
Nov 29 21:41:08 27[IKE] <Mobile|98833> IKE_SA Mobile[98833] established between 172.31.1.5[<FQDN>]...<IP>[]
Nov 29 21:41:08 27[CFG] <Mobile|98833> reassigning offline lease to ''
Nov 29 21:41:08 27[CFG] <Mobile|98833> looking for a child config for 0.0.0.0/0 ::/0 === 0.0.0.0/0 ::/0
Nov 29 21:41:08 27[CFG] <Mobile|98833> proposing traffic selectors for us:
Nov 29 21:41:08 27[CFG] <Mobile|98833>  172.31.0.0/16
Nov 29 21:41:08 27[CFG] <Mobile|98833> proposing traffic selectors for other:
Nov 29 21:41:08 27[CFG] <Mobile|98833>  172.31.11.73/32
Nov 29 21:41:08 27[CFG] <Mobile|98833>   candidate "Mobile" with prio 2+2
Nov 29 21:41:08 27[CFG] <Mobile|98833> found matching child config "Mobile" with prio 4
Nov 29 21:41:08 27[CFG] <Mobile|98833> selecting proposal:
Nov 29 21:41:08 27[CFG] <Mobile|98833>   no acceptable ENCRYPTION_ALGORITHM found
Nov 29 21:41:08 27[CFG] <Mobile|98833> selecting proposal:
Nov 29 21:41:08 27[CFG] <Mobile|98833>   proposal matches
Nov 29 21:41:08 27[CFG] <Mobile|98833> received proposals: ESP:AES_CBC_128/HMAC_SHA2_256_128/NO_EXT_SEQ
Nov 29 21:41:08 27[CFG] <Mobile|98833> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ
Nov 29 21:41:08 27[CFG] <Mobile|98833> selected proposal: ESP:AES_CBC_128/HMAC_SHA2_256_128/NO_EXT_SEQ
Nov 29 21:41:08 27[KNL] <Mobile|98833> got SPI c3339d7f
Nov 29 21:41:08 27[CFG] <Mobile|98833> selecting traffic selectors for us:
Nov 29 21:41:08 27[CFG] <Mobile|98833>  config: 172.31.0.0/16, received: 0.0.0.0/0 => match: 172.31.0.0/16
Nov 29 21:41:08 27[CFG] <Mobile|98833>  config: 172.31.0.0/16, received: ::/0 => no match
Nov 29 21:41:08 27[CFG] <Mobile|98833> selecting traffic selectors for other:
Nov 29 21:41:08 27[CFG] <Mobile|98833>  config: 172.31.11.73/32, received: 0.0.0.0/0 => match: 172.31.11.73/32
Nov 29 21:41:08 27[CFG] <Mobile|98833>  config: 172.31.11.73/32, received: ::/0 => no match
Nov 29 21:41:08 27[KNL] <Mobile|98833> adding SAD entry with SPI c3339d7f and reqid {5457}
Nov 29 21:41:08 27[KNL] <Mobile|98833>   using encryption algorithm AES_CBC with key size 128
Nov 29 21:41:08 27[KNL] <Mobile|98833>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 21:41:08 27[KNL] <Mobile|98833>   using replay window of 32 packets
Nov 29 21:41:08 27[KNL] <Mobile|98833> adding SAD entry with SPI 0a34c24d and reqid {5457}
Nov 29 21:41:08 27[KNL] <Mobile|98833>   using encryption algorithm AES_CBC with key size 128
Nov 29 21:41:08 27[KNL] <Mobile|98833>   using integrity algorithm HMAC_SHA2_256_128 with key size 256
Nov 29 21:41:08 27[KNL] <Mobile|98833>   using replay window of 0 packets
Nov 29 21:41:08 27[KNL] <Mobile|98833> adding policy 172.31.11.73/32 === 172.31.0.0/16 in [priority 375423, refcount 1]
Nov 29 21:41:08 27[KNL] <Mobile|98833> adding policy 172.31.11.73/32 === 172.31.0.0/16 fwd [priority 375423, refcount 1]
Nov 29 21:41:08 27[CFG] <Mobile|98833> unable to install policy 172.31.0.0/16 === 172.31.11.73/32 out for reqid 5457, the same policy for reqid 5456 exists
Nov 29 21:41:08 27[KNL] <Mobile|98833> deleting policy 172.31.0.0/16 === 172.31.11.73/32 out
Nov 29 21:41:08 27[KNL] <Mobile|98833> policy still used by another CHILD_SA, not removed
Nov 29 21:41:08 27[KNL] <Mobile|98833> not updating policy 172.31.0.0/16 === 172.31.11.73/32 out [priority 375423, refcount 1]
Nov 29 21:41:08 27[KNL] <Mobile|98833> deleting policy 172.31.11.73/32 === 172.31.0.0/16 in
Nov 29 21:41:08 27[KNL] <Mobile|98833> deleting policy 172.31.11.73/32 === 172.31.0.0/16 fwd
Nov 29 21:41:08 27[KNL] <Mobile|98833> deleting SAD entry with SPI c3339d7f
Nov 29 21:41:08 27[KNL] <Mobile|98833> deleted SAD entry with SPI c3339d7f
Nov 29 21:41:08 27[KNL] <Mobile|98833> deleting SAD entry with SPI 0a34c24d
Nov 29 21:41:08 27[KNL] <Mobile|98833> deleted SAD entry with SPI 0a34c24d
Nov 29 21:41:08 25[IKE] <Mobile|98833> deleting IKE_SA Mobile[98833] between 172.31.1.5[<FQDN>]...<IP>[]
Nov 29 21:41:08 25[IKE] <Mobile|98833> IKE_SA deleted
Nov 29 21:41:08 25[CFG] <Mobile|98833> lease 172.31.11.73 by '' went offline

At the end of the log you find:
Nov 29 21:41:08 27[CFG] <Mobile|98833> unable to install policy 172.31.0.0/16 === 172.31.11.73/32 out for reqid 5457, the same policy for reqid 5456 exists
Do you see anything useful here? I'm having a hard time to interpret this log.
What I find strange is that suddenly (see Nov 29 21:20:56 09[CFG]) there's a "selecting proposal" entry, without any selection process before (so no complete connect?).

Thanks again!

#5 Updated by Tobias Brunner over 3 years ago

Do you see anything useful here? I'm having a hard time to interpret this log.

The messages logged with enc on level 1 are usually useful to see what messages are exchanged.

What I find strange is that suddenly (see Nov 29 21:20:56 09[CFG]) there's a "selecting proposal" entry, without any selection process before (so no complete connect?).

That's a CHILD_SA rekeying. Not sure what you mean with "selection process before". More of an issue is that the rekeying is not complete (the old SA is not deleted) because the peer apparently went offline. It seems to come back, but from a different port/IP, which triggers updates of the IPsec SAs/policies at Nov 29 21:22:28. But it doesn't look like it completes the rekeying afterwards, so at this point you have two CHILD_SAs, of which only the old one is used to send traffic, which is not really a problem as long as the client still has that SA open, too, but it's strange that it doesn't send a delete (at least if we assume the address update was triggered by a MOBIKE update). At Nov 29 21:40:17 the IKE_SA is apparently terminated and 50 seconds later reestablished.

Now, seeing that you are using 5.6.2 and that there is an update of the IPsec SAs/policies that collides with a rekeying, the eventual problem is most likely caused by the bug that was fixed with 529ffc2fe3 (contained in 5.6.3).

#6 Updated by Marcel Müller over 3 years ago

Hi Tobias,

thanks again for your help and explanation. I looked through the changelog, but must have missed this one, sorry.
I just updated to 5.7.1 and will keep an eye on this issue (leaving the log levels and adding ENC). I have to use this particular constellation with a LTE router for another week, so this should be enough to see if it happens again.

Thanks,
Marcel

#7 Updated by Marcel Müller over 3 years ago

Hi Tobias,

I was unable to reproduce this error after updating to 5.7.1 So this issue can be closed as resolved.

Thanks for your help,
Marcel

#8 Updated by Tobias Brunner over 3 years ago

  • Category set to libcharon
  • Status changed from Feedback to Closed
  • Assignee set to Tobias Brunner
  • Resolution set to No change required

OK, great.

Also available in: Atom PDF