topic Re: VPN to Azure dropouts in General Topics

VPN to Azure dropouts

dmann2 — Wed, 20 Jul 2016 23:24:08 GMT

I have searched high and low for this and found a few articles regarding IKE configuration and nothing seems to fix it.

PAN 3020 v7.0.5. IKE 2 VPN to Azure. The VPN works but around every 50 mintues the tunnel drops out for a few minutes then re-establishes. I have tried various different IKE and IPsec settings as per advice from Palo Alto articles, Microsoft Azure articles and settings from a comment against a Palo Alto article that the commentor said worked. No joy.

From the Azure console there is no way of checking IPsec ettings.

Any help would be good.

Re: VPN to Azure dropouts

TranceforLife — Thu, 21 Jul 2016 13:41:54 GMT

Hi,

Just had a similar issue. Can you post your VPN settings so I can compare with my and tell you what I have changed to make it working? Please send a screenshot of the logs from the Monitoring tab> System. Both successful and unsuccessful.

Cheers

Re: VPN to Azure dropouts

TranceforLife — Thu, 21 Jul 2016 21:40:56 GMT

Hi,

Just a quick update/tips on this:

- make sure Palo in the "passive" mode. So it will not be able to initiate a VPN but we could not make it working when its disabled.

- IKEv2 initiate 2 tunnels: IKE tunnel ( old name of IKEv1 Phase 1) and CHILD_SA (old name of IKEv1 Phace 2). Default lifetime for IKE Tunnel is 86400 or 28800 seconds (depends of the vendor) for CHILD_SA is 3600 seconds hence your tunnel will be always re-established every hour. But it takes couple seconds not minutes.

- disable no-pfs on IPSec Crypto

- disable "Liveness Check" on the IKE Gateway configuration.

Make sure that all other setting are compatible with Azure. Please see below:

IPsec Parameters

Note:

Although the values listed below are supported by the Azure VPN Gateway, currently there is no way for you to specify or select a specific combination from the Azure VPN Gateway. You must specify any constraints from the on-premises VPN device. In addition, you must clamp MSS at 1350.

IKE Phase 1 setup

Property	Policy-based	Route-based and Standard or High Performance VPN gateway
IKE Version	IKEv1	IKEv2
Diffie-Hellman Group	Group 2 (1024 bit)	Group 2 (1024 bit)
Authentication Method	Pre-Shared Key	Pre-Shared Key
Encryption Algorithms	AES256 AES128 3DES	AES256 3DES
Hashing Algorithm	SHA1(SHA128)	SHA1(SHA128), SHA2(SHA256)
Phase 1 Security Association (SA) Lifetime (Time)	28,800 seconds	10,800 seconds

IKE Phase 2 setup

Property	Policy-based	Route-based and Standard or High Performance VPN gateway
IKE Version	IKEv1	IKEv2
Hashing Algorithm	SHA1(SHA128)	SHA1(SHA128)
Phase 2 Security Association (SA) Lifetime (Time)	3,600 seconds	3,600 seconds
Phase 2 Security Association (SA) Lifetime (Throughput)	102,400,000 KB	-
IPsec SA Encryption & Authentication Offers (in the order of preference)	1. ESP-AES256 2. ESP-AES128 3. ESP-3DES 4. N/A	See Route-based Gateway IPsec Security Association (SA) Offers(below)
Perfect Forward Secrecy (PFS)	No	Yes (DH Group1, 2, 5, 14, 24)
Dead Peer Detection	Not supported	Supported

After doing all this tunnel still stable for the past 3 days.

You can clear the tunnel couple times to see if everything is working correctly:

> clear vpn ike-sa gateway (for IKE Tunnel)

> clear vpn ipsec-sa tunnel (for CHILD_SA)

Hope it helps!

Re: VPN to Azure dropouts

dmann2 — Fri, 22 Jul 2016 04:25:38 GMT

Re: VPN to Azure dropouts

TranceforLife — Fri, 22 Jul 2016 10:57:48 GMT

Hi,

The first thing I have noticed that you Palo device not in the "Passive" mode. Try to configure/modify config using my settings and get back, please.

All the best

Re: VPN to Azure dropouts

dmann2 — Sun, 24 Jul 2016 22:17:12 GMT

I noticed that first log entry myself as the PAN tries to start the SA negotiation as intitator but it is definitely in passive mode.

Re: VPN to Azure dropouts

TranceforLife — Mon, 25 Jul 2016 06:59:21 GMT

Did you commit the changes?

Re: VPN to Azure dropouts

dmann2 — Mon, 25 Jul 2016 21:47:26 GMT

It has been passive for quite a while now having commited multiple changes over the last few weeks.

Re: VPN to Azure dropouts

TranceforLife — Mon, 25 Jul 2016 22:51:15 GMT

Very strange. What are the latest logs suggests? Did you try my suggestions? Our VPN still stable, fingers crossed 🙂

Re: VPN to Azure dropouts

dmann2 — Mon, 25 Jul 2016 22:54:15 GMT

Can you take some screenshots of your config and I will match that and see how it goes? I can't find much info on the log entires except what you have already suggested.

If I match what you have it might improve.

Thanks for your input.

Re: VPN to Azure dropouts

TranceforLife — Mon, 25 Jul 2016 23:09:56 GMT

Sorry don't have a direct access to the box but my config listed below:

IKEv2
Diffie-Hellman Group Group 2
Authentication Method SHA1
Encryption Algorithms AES256, 3DES
Phase 1 Security Association (SA) Lifetime (Time) 28,800 seconds

CHILD_SA
Encryption Algorithms AES128, 3DES
Authentication Method SHA1
Phase 2 Security Association (SA) Lifetime (Time) 3,600 seconds
Perfect Forward Secrecy (PFS) no-pfs

Cheers

Re: VPN to Azure dropouts

dmann2 — Tue, 26 Jul 2016 00:28:13 GMT

It is just passed the 1 hour mark, since making changes to match yours, where we were dropping packets before and the tunnel has stayed up. The negotiation seemed to run smoothly.

Fingers crossed.

Re: VPN to Azure dropouts

dmann2 — Tue, 26 Jul 2016 03:57:31 GMT

It looks as though it is dropping 4 or 5 packets every hour or so.

Re: VPN to Azure dropouts

TranceforLife — Tue, 26 Jul 2016 06:47:20 GMT

I am not sure but it could be because of the tunnel rekeying. But l don't know if 4-5packets acceptable or not

Re: VPN to Azure dropouts

TranceforLife — Tue, 26 Jul 2016 07:07:41 GMT

More info here:

https://tools.ietf.org/html/draft-jenkins-ipsec-rekeying-03#section-2.2.1.2

Re: VPN to Azure dropouts

dmann2 — Wed, 27 Jul 2016 01:36:04 GMT

A bit more info for anyone watching.

It doesn't happen every time the tunnel is re-negotiated (every hour). In some cases there are no dropped packets. At various times I get the following sequence of events. The dropped packets seem to occur following these events. There is around a 10 second period of dropped packets between the event "IKEV2 IKE SA is down as determined by DPD" and the successful re-negotiation.

I'm not sure why it is starting a negotiation as initiator when in passive mode.

There is no setting for DPD when in "IKEV2 only mode" on the IKE Gateway.

Re: VPN to Azure dropouts

TranceforLife — Wed, 27 Jul 2016 06:59:57 GMT

Hi,

DPD it is actually for IKEv1, Liveness check is a new term for IKEv2. Please disable this future:

https://www.paloaltonetworks.com/documentation/70/pan-os/pan-os/vpns/site-to-site-vpn-concepts

Just to confirm you do have a security policy configured as bi-directional for Azure peer.

Good question why it is still initiating a tunnel when in passive mode.

Cheers

Re: VPN to Azure dropouts

dmann2 — Wed, 27 Jul 2016 23:37:32 GMT

I definitely have the Liveness box unchecked on the IKE gateway but when I look at the window that lists the IKE Gateways under Liveness for this gateway it has "default".

Your info on liveness check certainly describes what is happening according to the log entries.

Security policies are good.

Re: VPN to Azure dropouts

TranceforLife — Thu, 28 Jul 2016 15:07:44 GMT

Hi,

Something weird happening 🙂 When the passive mode is enabled, Palo still initiating a VPN tunnel or when Liveness check disabled it is still tear down the tunnel. I am confused ))) Please post the Ike Gateway screen shot and the output of the ikemgr.log:

> tail lines 200 mp-log ikemgr.log

Cheers

Re: VPN to Azure dropouts

dmann2 — Thu, 28 Jul 2016 22:59:27 GMT

Yes weird.

It seems I cant attach a txt file so I''l copy the log here.

I think 3:19:42 to 3:19:58 in the first re-negotiation in this log is the time where It would drop packets.

2016-07-29 03:14:22 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS INITIATOR, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000000 parent SN:465 <====
2016-07-29 03:19:41 [PROTO_ERR]: 465:138.44.5.6[500] - 13.75.156.231[500]:(nil):retransmission count exceeded the limit
2016-07-29 03:19:41 [INFO]: 465:138.44.5.6[500] - 13.75.156.231[500]:(nil):aborting IKEv2 SA Azure-IKE-Gateway:465
2016-07-29 03:19:41 [INFO]: SADB_DELETE ul_proto=255 src=13.75.156.231[0] dst=138.44.5.6[0] satype=ESP spi=0xBB1B49E4
2016-07-29 03:19:41 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xBB1B49E4
2016-07-29 03:19:41 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xBB1B49E4/0x2D0DC3C4 <====
2016-07-29 03:19:41 [INFO]: SADB_DELETE ul_proto=255 src=138.44.5.6[0] dst=13.75.156.231[0] satype=ESP spi=0x2D0DC3C4
2016-07-29 03:19:41 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0x2D0DC3C4
2016-07-29 03:19:41.376 +1000 IKEv2 liveness {Azure-IKE-Gateway:465-R}: DPD down, rekey vpn tunnel <Azure-IPsec-Tunnel(Azure-IKE-Gateway)>, SA state ESTABLISHED
2016-07-29 03:19:41 [INFO]: passive mode is specified for IKE gateway Azure-IKE-Gateway.
2016-07-29 03:19:42 [INFO]: keymirror del start ----------------
2016-07-29 03:19:42 [INFO]: keymirror del for gw 1, tn 1, selfSPI BB1B49E4, retcode 0.
2016-07-29 03:19:58 [PROTO_WARN]: 0:138.44.5.6[500] - 13.75.156.231[500]:0x8fe7ba0:message to a nonexistent ike_sa
2016-07-29 03:19:59 [PROTO_WARN]: 0:138.44.5.6[500] - 13.75.156.231[500]:0x8efc240:message to a nonexistent ike_sa
2016-07-29 03:20:00 [PROTO_WARN]: 0:138.44.5.6[500] - 13.75.156.231[500]:0x8f13fa0:message to a nonexistent ike_sa
2016-07-29 03:20:01 [PROTO_WARN]: 0:138.44.5.6[500] - 13.75.156.231[500]:0x8efc240:message to a nonexistent ike_sa
2016-07-29 03:20:05 [PROTO_NOTIFY]: ====> IKEv2 IKE SA NEGOTIATION STARTED AS RESPONDER, non-rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] SPI:8200c742bac96fe4:290a5d6bbc4c4ccf SN:466 <====
2016-07-29 03:20:05 [PROTO_WARN]: 466:138.44.5.6[500] - 13.75.156.231[500]:0x8f13fa0:ignoring unauthenticated notify payload (NAT_DETECTION_SOURCE_IP)
2016-07-29 03:20:05 [PROTO_WARN]: 466:138.44.5.6[500] - 13.75.156.231[500]:0x8f13fa0:ignoring unauthenticated notify payload (NAT_DETECTION_DESTINATION_IP)
2016-07-29 03:20:05 [PROTO_WARN]: 466:138.44.5.6[500] - 13.75.156.231[500]:0x8f13fa0:vendor id payload ignored
2016-07-29 03:20:05 [PROTO_WARN]: 466:138.44.5.6[500] - 13.75.156.231[500]:0x8f13fa0:vendor id payload ignored
2016-07-29 03:20:05 [PROTO_WARN]: 466:138.44.5.6[500] - 13.75.156.231[500]:0x8f13fa0:vendor id payload ignored
2016-07-29 03:20:05 [PROTO_WARN]: 466:138.44.5.6[500] - 13.75.156.231[500]:0x8f13fa0:vendor id payload ignored
2016-07-29 03:20:05 [INFO]: 466:138.44.5.6[500] - 13.75.156.231[500]:0x8fe64c8:authentication result: success
2016-07-29 03:20:05 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS RESPONDER, non-rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000001 parent SN:466 <====
2016-07-29 03:20:05 [INTERNAL_WARN]: selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out src is ambiguous, using the first one of the expanded addresses
2016-07-29 03:20:05 [INTERNAL_WARN]: selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out dst is ambiguous, using the first one of the expanded addresses
2016-07-29 03:20:05.294 +1000 IKEv2 TS {Azure-IKE-Gateway:466-R}: TS matching for configured selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out 0.0.0.0[0]/0-0.0.0.0[0]/0 proto 0
2016-07-29 03:20:05.294 +1000 .. check local TS (num 2, TS0 is not specific) against selector 0:0.0.0.0[0]/0
2016-07-29 03:20:05.294 +1000 ... TS 0: ts type mismtach, selector is not IPv6
2016-07-29 03:20:05.294 +1000 ... TS 1: exact match
2016-07-29 03:20:05.294 +1000 ... result: local TS = 0.0.0.0[0]/0
2016-07-29 03:20:05.294 +1000 .. check remote TS (num 2, TS0 is not specific) against selector 0:0.0.0.0[0]/0
2016-07-29 03:20:05.294 +1000 ... TS 0: ts type mismtach, selector is not IPv6
2016-07-29 03:20:05.294 +1000 ... TS 1: exact match
2016-07-29 03:20:05.294 +1000 ... result: remote TS = 0.0.0.0[0]/0
2016-07-29 03:20:05.294 +1000 - IKEv2 TS {Azure-IKE-Gateway:466-R}: TS matching result: TS_l match(=), TS_r match(=) *
2016-07-29 03:20:05.294 +1000 *** IKEv2 TS {Azure-IKE-Gateway:466-R}: selector chosen Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out: tid 1
2016-07-29 03:20:05 [INFO]: SADB_UPDATE ul_proto=255 src=13.75.156.231[500] dst=138.44.5.6[500] satype=ESP samode=tunl spi=0xA445D650 authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=2965 bytes=0 hard time=3600 bytes=0
2016-07-29 03:20:05 [INFO]: SADB_ADD ul_proto=255 src=138.44.5.6[500] dst=13.75.156.231[500] satype=ESP samode=tunl spi=0x9969D73C authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=3175 bytes=0 hard time=3600 bytes=0
2016-07-29 03:20:05.294 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 03:20:05.294 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 03:20:05 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xA445D650/0x9969D73C lifetime 3600 Sec lifesize unlimited <====
2016-07-29 03:20:05 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION SUCCEEDED AS RESPONDER, non-rekey <====
====> Established SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000001, SPI:0xA445D650/0x9969D73C parent SN:466 <====
2016-07-29 03:20:05 [PROTO_NOTIFY]: ====> IKEv2 IKE SA NEGOTIATION SUCCEEDED AS RESPONDER, non-rekey <====
====> Established SA: 138.44.5.6[500]-13.75.156.231[500] SPI:8200c742bac96fe4:290a5d6bbc4c4ccf SN:466 lifetime 28800 Sec <====
2016-07-29 03:20:05 [INFO]: keymirror add start ++++++++++++++++
2016-07-29 03:20:05 [INFO]: keymirror add for gw 0x1, tn 1, selfSPI A445D650, retcode 0.
2016-07-29 04:12:59 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS INITIATOR, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000000 parent SN:466 <====
2016-07-29 04:15:53 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS RESPONDER, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x0000000C parent SN:466 <====
2016-07-29 04:15:53 [INTERNAL_WARN]: selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out src is ambiguous, using the first one of the expanded addresses
2016-07-29 04:15:53 [INTERNAL_WARN]: selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out dst is ambiguous, using the first one of the expanded addresses
2016-07-29 04:15:53.175 +1000 IKEv2 TS {Azure-IKE-Gateway:466-R}: TS matching for configured selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out 0.0.0.0[0]/0-0.0.0.0[0]/0 proto 0
2016-07-29 04:15:53.175 +1000 .. check local TS (num 2, TS0 is not specific) against selector 0:0.0.0.0[0]/0
2016-07-29 04:15:53.175 +1000 ... TS 0: ts type mismtach, selector is not IPv6
2016-07-29 04:15:53.175 +1000 ... TS 1: exact match
2016-07-29 04:15:53.175 +1000 ... result: local TS = 0.0.0.0[0]/0
2016-07-29 04:15:53.175 +1000 .. check remote TS (num 2, TS0 is not specific) against selector 0:0.0.0.0[0]/0
2016-07-29 04:15:53.175 +1000 ... TS 0: ts type mismtach, selector is not IPv6
2016-07-29 04:15:53.175 +1000 ... TS 1: exact match
2016-07-29 04:15:53.175 +1000 ... result: remote TS = 0.0.0.0[0]/0
2016-07-29 04:15:53.175 +1000 - IKEv2 TS {Azure-IKE-Gateway:466-R}: TS matching result: TS_l match(=), TS_r match(=) *
2016-07-29 04:15:53.175 +1000 *** IKEv2 TS {Azure-IKE-Gateway:466-R}: selector chosen Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out: tid 1
2016-07-29 04:15:53 [INFO]: SADB_UPDATE ul_proto=255 src=13.75.156.231[500] dst=138.44.5.6[500] satype=ESP samode=tunl spi=0xB9AC02C2 authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=3140 bytes=0 hard time=3600 bytes=0
2016-07-29 04:15:53 [INFO]: SADB_ADD ul_proto=255 src=138.44.5.6[500] dst=13.75.156.231[500] satype=ESP samode=tunl spi=0x946BF430 authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=3177 bytes=0 hard time=3600 bytes=0
2016-07-29 04:15:53.175 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 04:15:53.175 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 04:15:53 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xB9AC02C2/0x946BF430 lifetime 3600 Sec lifesize unlimited <====
2016-07-29 04:15:53 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION SUCCEEDED AS RESPONDER, rekey <====
====> Established SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x0000000C, SPI:0xB9AC02C2/0x946BF430 parent SN:466 <====
2016-07-29 04:15:53 [INFO]: keymirror add start ++++++++++++++++
2016-07-29 04:15:53 [INFO]: keymirror add for gw 0x1, tn 1, selfSPI B9AC02C2, retcode 0.
2016-07-29 04:15:53 [INFO]: 466:138.44.5.6[500] - 13.75.156.231[500]:(nil):delete proto ESP spi 0x9969D73C
2016-07-29 04:15:53 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xA445D650/0x9969D73C <====
2016-07-29 04:15:53 [INFO]: SADB_DELETE ul_proto=255 src=138.44.5.6[0] dst=13.75.156.231[0] satype=ESP spi=0x9969D73C
2016-07-29 04:15:53 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0x9969D73C
2016-07-29 04:15:53 [INFO]: SADB_DELETE ul_proto=255 src=13.75.156.231[0] dst=138.44.5.6[0] satype=ESP spi=0xA445D650
2016-07-29 04:15:53 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xA445D650
2016-07-29 04:15:53 [INFO]: keymirror del start ----------------
2016-07-29 04:15:53 [INFO]: keymirror del for gw 1, tn 1, selfSPI A445D650, retcode 0.
2016-07-29 04:16:10 [PROTO_ERR]: 466:138.44.5.6[500] - 13.75.156.231[500]:(nil):received Notify payload protocol 0 type 12345
2016-07-29 04:16:10 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION FAILED AS INITIATOR, rekey <====
====> Failed SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000000 parent SN:466 <==== Error code 111
2016-07-29 05:08:49 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS INITIATOR, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000000 parent SN:466 <====
2016-07-29 05:11:38 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS RESPONDER, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000012 parent SN:466 <====
2016-07-29 05:11:38 [INTERNAL_WARN]: selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out src is ambiguous, using the first one of the expanded addresses
2016-07-29 05:11:38 [INTERNAL_WARN]: selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out dst is ambiguous, using the first one of the expanded addresses
2016-07-29 05:11:38.501 +1000 IKEv2 TS {Azure-IKE-Gateway:466-R}: TS matching for configured selector Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out 0.0.0.0[0]/0-0.0.0.0[0]/0 proto 0
2016-07-29 05:11:38.501 +1000 .. check local TS (num 2, TS0 is not specific) against selector 0:0.0.0.0[0]/0
2016-07-29 05:11:38.501 +1000 ... TS 0: ts type mismtach, selector is not IPv6
2016-07-29 05:11:38.501 +1000 ... TS 1: exact match
2016-07-29 05:11:38.501 +1000 ... result: local TS = 0.0.0.0[0]/0
2016-07-29 05:11:38.501 +1000 .. check remote TS (num 2, TS0 is not specific) against selector 0:0.0.0.0[0]/0
2016-07-29 05:11:38.501 +1000 ... TS 0: ts type mismtach, selector is not IPv6
2016-07-29 05:11:38.501 +1000 ... TS 1: exact match
2016-07-29 05:11:38.501 +1000 ... result: remote TS = 0.0.0.0[0]/0
2016-07-29 05:11:38.501 +1000 - IKEv2 TS {Azure-IKE-Gateway:466-R}: TS matching result: TS_l match(=), TS_r match(=) *
2016-07-29 05:11:38.501 +1000 *** IKEv2 TS {Azure-IKE-Gateway:466-R}: selector chosen Azure-IPsec-Tunnel(Azure-IKE-Gateway)_out: tid 1
2016-07-29 05:11:38 [INFO]: SADB_UPDATE ul_proto=255 src=13.75.156.231[500] dst=138.44.5.6[500] satype=ESP samode=tunl spi=0xF30D6381 authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=3203 bytes=0 hard time=3600 bytes=0
2016-07-29 05:11:38 [INFO]: SADB_ADD ul_proto=255 src=138.44.5.6[500] dst=13.75.156.231[500] satype=ESP samode=tunl spi=0xAE2BA4DC authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=2913 bytes=0 hard time=3600 bytes=0
2016-07-29 05:11:38.501 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 05:11:38.501 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 05:11:38 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xF30D6381/0xAE2BA4DC lifetime 3600 Sec lifesize unlimited <====
2016-07-29 05:11:38 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION SUCCEEDED AS RESPONDER, rekey <====
====> Established SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000012, SPI:0xF30D6381/0xAE2BA4DC parent SN:466 <====
2016-07-29 05:11:38 [INFO]: keymirror add start ++++++++++++++++
2016-07-29 05:11:38 [INFO]: keymirror add for gw 0x1, tn 1, selfSPI F30D6381, retcode 0.
2016-07-29 05:11:38 [INFO]: 466:138.44.5.6[500] - 13.75.156.231[500]:(nil):delete proto ESP spi 0x946BF430
2016-07-29 05:11:38 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xB9AC02C2/0x946BF430 <====
2016-07-29 05:11:38 [INFO]: SADB_DELETE ul_proto=255 src=138.44.5.6[0] dst=13.75.156.231[0] satype=ESP spi=0x946BF430
2016-07-29 05:11:38 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0x946BF430
2016-07-29 05:11:38 [INFO]: SADB_DELETE ul_proto=255 src=13.75.156.231[0] dst=138.44.5.6[0] satype=ESP spi=0xB9AC02C2
2016-07-29 05:11:38 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xB9AC02C2
2016-07-29 05:11:38 [INFO]: keymirror del start ----------------
2016-07-29 05:11:38 [INFO]: keymirror del for gw 1, tn 1, selfSPI B9AC02C2, retcode 0.
2016-07-29 05:12:00 [PROTO_ERR]: 466:138.44.5.6[500] - 13.75.156.231[500]:(nil):received Notify payload protocol 0 type 12345
2016-07-29 05:12:00 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION FAILED AS INITIATOR, rekey <====
====> Failed SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000001 parent SN:466 <==== Error code 111
2016-07-29 06:00:11 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS INITIATOR, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000000 parent SN:466 <====
2016-07-29 06:00:11 [INFO]: SADB_UPDATE ul_proto=255 src=13.75.156.231[500] dst=138.44.5.6[500] satype=ESP samode=tunl spi=0xD8014654 authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=3230 bytes=0 hard time=3600 bytes=0
2016-07-29 06:00:11 [INFO]: SADB_ADD ul_proto=255 src=138.44.5.6[500] dst=13.75.156.231[500] satype=ESP samode=tunl spi=0xFF5EF270 authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=3009 bytes=0 hard time=3600 bytes=0
2016-07-29 06:00:11.389 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 06:00:11.389 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 06:00:11 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xD8014654/0xFF5EF270 lifetime 3600 Sec lifesize unlimited <====
2016-07-29 06:00:11 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION SUCCEEDED AS INITIATOR, rekey <====
====> Established SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000002, SPI:0xD8014654/0xFF5EF270 parent SN:466 <====
2016-07-29 06:00:11 [INFO]: keymirror add start ++++++++++++++++
2016-07-29 06:00:11 [INFO]: keymirror add for gw 0x1, tn 1, selfSPI D8014654, retcode 0.
2016-07-29 06:00:11 [INFO]: keymirror del start ----------------
2016-07-29 06:00:11 [INFO]: keymirror del for gw 1, tn 1, selfSPI F30D6381, retcode 0.
2016-07-29 06:00:11 [INFO]: SADB_DELETE ul_proto=255 src=13.75.156.231[0] dst=138.44.5.6[0] satype=ESP spi=0xF30D6381
2016-07-29 06:00:11 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xF30D6381
2016-07-29 06:00:11 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xF30D6381/0xAE2BA4DC <====
2016-07-29 06:00:11 [INFO]: SADB_DELETE ul_proto=255 src=138.44.5.6[0] dst=13.75.156.231[0] satype=ESP spi=0xAE2BA4DC
2016-07-29 06:00:11 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xAE2BA4DC
2016-07-29 06:05:11 [INFO]: 466:138.44.5.6[500] - 13.75.156.231[500]:(nil):delete proto ESP spi 0xAE2BA4DC
2016-07-29 06:05:11 [PROTO_WARN]: 466:138.44.5.6[500] - 13.75.156.231[500]:(nil):can't find sa for proto ESP spi 0xAE2BA4DC
2016-07-29 06:11:07 [PROTO_NOTIFY]: ====> IKEv2 IKE SA NEGOTIATION STARTED AS RESPONDER, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] SPI:7b6ad57db0e66afd:af6028d3c14c9faa SN:467 <====
2016-07-29 06:11:07.404 +1000 >>> IKEv2 rekey {Azure-IKE-Gateway:467-R}: adopt children SA from IKE SA 466
2016-07-29 06:11:07.404 +1000 IKEv2 rekey {Azure-IKE-Gateway:467-R}: child SA 196717 is adopted, tid 1, state MATURE
2016-07-29 06:11:07 [PROTO_NOTIFY]: ====> IKEv2 IKE SA NEGOTIATION SUCCEEDED AS RESPONDER, rekey <====
====> Established SA: 138.44.5.6[500]-13.75.156.231[500] SPI:7b6ad57db0e66afd:af6028d3c14c9faa SN:467 lifetime 28800 Sec <====
2016-07-29 06:11:07 [INFO]: 466:138.44.5.6[500] - 13.75.156.231[500]:(nil):received DELETE IKE_SA
2016-07-29 06:11:07.420 +1000 IKEv2 {Azure-IKE-Gateway:466-R}: received DELETE IKE_SA, SA state ESTABLISHED, SPI 8200c742bac96fe4:290a5d6bbc4c4ccf
2016-07-29 06:11:07 [INFO]: 466:138.44.5.6[500] - 13.75.156.231[500]:(nil):aborting IKEv2 SA Azure-IKE-Gateway:466
2016-07-29 06:50:20 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS INITIATOR, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000000 parent SN:467 <====
2016-07-29 06:50:20 [INFO]: SADB_UPDATE ul_proto=255 src=13.75.156.231[500] dst=138.44.5.6[500] satype=ESP samode=tunl spi=0xD4531654 authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=3200 bytes=0 hard time=3600 bytes=0
2016-07-29 06:50:20 [INFO]: SADB_ADD ul_proto=255 src=138.44.5.6[500] dst=13.75.156.231[500] satype=ESP samode=tunl spi=0x58A1452E authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=2997 bytes=0 hard time=3600 bytes=0
2016-07-29 06:50:20.392 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 06:50:20.392 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 06:50:20 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xD4531654/0x58A1452E lifetime 3600 Sec lifesize unlimited <====
2016-07-29 06:50:20 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION SUCCEEDED AS INITIATOR, rekey <====
====> Established SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000000, SPI:0xD4531654/0x58A1452E parent SN:467 <====
2016-07-29 06:50:20 [INFO]: keymirror add start ++++++++++++++++
2016-07-29 06:50:20 [INFO]: keymirror add for gw 0x1, tn 1, selfSPI D4531654, retcode 0.
2016-07-29 06:50:21 [INFO]: keymirror del start ----------------
2016-07-29 06:50:21 [INFO]: keymirror del for gw 1, tn 1, selfSPI D8014654, retcode 0.
2016-07-29 06:50:21 [INFO]: SADB_DELETE ul_proto=255 src=13.75.156.231[0] dst=138.44.5.6[0] satype=ESP spi=0xD8014654
2016-07-29 06:50:21 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xD8014654
2016-07-29 06:50:21 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xD8014654/0xFF5EF270 <====
2016-07-29 06:50:21 [INFO]: SADB_DELETE ul_proto=255 src=138.44.5.6[0] dst=13.75.156.231[0] satype=ESP spi=0xFF5EF270
2016-07-29 06:50:21 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xFF5EF270
2016-07-29 06:55:19 [INFO]: 467:138.44.5.6[500] - 13.75.156.231[500]:(nil):delete proto ESP spi 0xFF5EF270
2016-07-29 06:55:19 [PROTO_WARN]: 467:138.44.5.6[500] - 13.75.156.231[500]:(nil):can't find sa for proto ESP spi 0xFF5EF270
2016-07-29 07:40:17 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS INITIATOR, rekey <====
====> Initiated SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000000 parent SN:467 <====
2016-07-29 07:40:17 [INFO]: SADB_UPDATE ul_proto=255 src=13.75.156.231[500] dst=138.44.5.6[500] satype=ESP samode=tunl spi=0xC9083D8E authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=3058 bytes=0 hard time=3600 bytes=0
2016-07-29 07:40:17 [INFO]: SADB_ADD ul_proto=255 src=138.44.5.6[500] dst=13.75.156.231[500] satype=ESP samode=tunl spi=0xDAA11134 authtype=SHA1 enctype=3DES enclen=24 lifetime soft time=2893 bytes=0 hard time=3600 bytes=0
2016-07-29 07:40:17.390 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 07:40:17.390 +1000 sadb ts: port 0:65535 IP 0.0.0.0->255.255.255.255 proto:0 len:16
2016-07-29 07:40:17 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xC9083D8E/0xDAA11134 lifetime 3600 Sec lifesize unlimited <====
2016-07-29 07:40:17 [PROTO_NOTIFY]: ====> IKEv2 CHILD SA NEGOTIATION SUCCEEDED AS INITIATOR, rekey <====
====> Established SA: 138.44.5.6[500]-13.75.156.231[500] message id:0x00000001, SPI:0xC9083D8E/0xDAA11134 parent SN:467 <====
2016-07-29 07:40:17 [INFO]: keymirror add start ++++++++++++++++
2016-07-29 07:40:17 [INFO]: keymirror add for gw 0x1, tn 1, selfSPI C9083D8E, retcode 0.
2016-07-29 07:40:17 [INFO]: keymirror del start ----------------
2016-07-29 07:40:17 [INFO]: keymirror del for gw 1, tn 1, selfSPI D4531654, retcode 0.
2016-07-29 07:40:17 [INFO]: SADB_DELETE ul_proto=255 src=13.75.156.231[0] dst=138.44.5.6[0] satype=ESP spi=0xD4531654
2016-07-29 07:40:17 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xD4531654
2016-07-29 07:40:17 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 138.44.5.6[500]-13.75.156.231[500] SPI:0xD4531654/0x58A1452E <====
2016-07-29 07:40:17 [INFO]: SADB_DELETE ul_proto=255 src=138.44.5.6[0] dst=13.75.156.231[0] satype=ESP spi=0x58A1452E
2016-07-29 07:40:17 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0x58A1452E
2016-07-29 07:45:14 [INFO]: 467:138.44.5.6[500] - 13.75.156.231[500]:(nil):delete proto ESP spi 0x58A1452E
2016-07-29 07:45:14 [PROTO_WARN]: 467:138.44.5.6[500] - 13.75.156.231[500]:(nil):can't find sa for proto ESP spi 0x58A1452E