Wireless Access

Hi community,

we have a strange issue with one of our dmz controllers terminating RAPs. After provisioning the RAPs the can successfully establish a tunnel to the dmz controller, but the tunnel terminates after about 30 seconds. When trying to convert a factory default IAP to a RAP it can successfully fetch the firmware image over the tunnel, but there is no connection possible after that.

One can see an ipsec sa, but the AP does not show up in the ap database.

We have another dmz controller with basically the same config working on another location.

The controller is behind a firewall doing NAT, so is the AP.

Here is some output from the security debug log:

Jul 31 09:55:58 :103076: <8352> <INFO> |ike| IKEv2 IPSEC Tunnel created for peer 10.72.0.2:35228
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| arubaIPSecSetKeys:IPSECKEY proto:50 ospi:2b1e5300 ispi:59e8a000 auth:2 len:20 enc:4 len:32 add:1 out:1
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| DP SA out:1 natt:1 mode:1 proto:1 cipher:4 auth:2 spi:2b1e5300 oppspi:59e8a000 esrc:10.72.0.60 edst:10.72.0.2 dstnet:10.73.8.25 dstmask:0.0.0.0 nattport:35228 trust:0 dpd:0 ingress:0 sacl:0 family: 2
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| Added the IPSEC SA --- DONE !!
Jul 31 09:55:58 :103060: <8352> <DBUG> |ike| ipc.c:is_HA_crypto_map_present:2781 Looking for MAP default-ha-ipsecmap10.72.0.2
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| DP SA out:0 natt:1 mode:1 proto:1 cipher:4 auth:2 spi:59e8a000 oppspi:2b1e5300 esrc:10.72.0.2 edst:10.72.0.60 dstnet:0.0.0.0 dstmask:0.0.0.0 nattport:35228 trust:0 dpd:0 ingress:0 sacl:0 family: 20
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| Added the IPSEC SA --- DONE !!
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| encr=aes ESP spi=2b1e5300 10.72.0.2 << 10.72.0.60 udp-enc(35228)* spd=0(0) exp=7200 secs auth=
Jul 31 09:55:58 :103078: <8352> <INFO> |ike| IKEv2 CHILD_SA successful for peer 10.72.0.2:35228
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| CHILD_SA [v2 R
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| cleanup_and_free_context delete ctx memory
Jul 31 09:55:58 :103063: <8352> <DBUG> |ike| xlp_rcv_response: Nothing to be read from cryptolib fd
Jul 31 09:55:59 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3518 SWITCH IPv6 is not configured
Jul 31 09:55:59 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3520 Recvd SWITCH IPv6 =0.0.0.0
Jul 31 09:56:04 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3518 SWITCH IPv6 is not configured
Jul 31 09:56:04 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3520 Recvd SWITCH IPv6 =0.0.0.0
Jul 31 09:56:09 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3518 SWITCH IPv6 is not configured
Jul 31 09:56:09 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3520 Recvd SWITCH IPv6 =0.0.0.0
Jul 31 09:56:13 :103063: <8352> <DBUG> |ike| exchange_start_ikev2 pre-connect check duplicate mapname:default-local-master-ipsecmap
Jul 31 09:56:14 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3518 SWITCH IPv6 is not configured
Jul 31 09:56:14 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3520 Recvd SWITCH IPv6 =0.0.0.0
Jul 31 09:56:19 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3518 SWITCH IPv6 is not configured
Jul 31 09:56:19 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3520 Recvd SWITCH IPv6 =0.0.0.0
Jul 31 09:56:24 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3518 SWITCH IPv6 is not configured
Jul 31 09:56:24 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3520 Recvd SWITCH IPv6 =0.0.0.0
Jul 31 09:56:27 :124230: <8405> <DBUG> |authmgr| Rx message 3099/67108864, length 122 from 127.0.0.1:8222
Jul 31 09:56:27 :124220: <8405> <DBUG> |authmgr| stm_message_handler : msg_type 3099
Jul 31 09:56:27 :124004: <8405> <DBUG> |authmgr| Got STM_AP_GLOBAL_STATE_TYPE_DELETE for ip:10.73.8.25
Jul 31 09:56:27 :124004: <8405> <DBUG> |authmgr| Sent IP down to ike ip:10.73.8.25 vpn:Yes tvpn:No
Jul 31 09:56:27 :124004: <8405> <DBUG> |authmgr| ap_global_state is null for AP IP 10.73.8.25
Jul 31 09:56:27 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3650 Auth ip down message.ip=10.73.8.25. flags 4
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| IPSEC_deleteSaByInnerIPExtIP delete IPSEC SA 10.72.0.2:(inner:10.73.8.25)
Jul 31 09:56:27 :103101: <8352> <INFO> |ike| IPSEC SA deleted for peer 10.72.0.2
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| IPSEC_delSa: Removing spi 0x59e8a000 from hash table
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| ipsec_spi_hash_tbl_entry_remove: Successfully removed IPSEC spi 0x59e8a000 from SPI hash table
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| IPSEC_delSa: Removing entry from m_hashTableOutbnd. RAP: 1 Innerip: 10.73.8.25 Dst: 10.72.0.2 Src: 10.72.0.60
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| IPSEC_delSa (RESPONDER) Outgoing=1 SADB Proto:50 SPI:2b1e5300 OppSPI:59e8a000 Dst:10.72.0.2 Src:10.72.0.60 natt:35228 Dport:0 Sport:0 Oprot:0 Mode:2 Inner:10.73.8.25 DstIP:0.0.0.0 DstIPe:255.255.255
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| arubaIPSecSetKeys:IPSECKEY proto:50 ospi:2b1e5300 ispi:59e8a000 auth:2 len:20 enc:4 len:32 add:0 out:1
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| DP SA out:1 natt:1 mode:1 proto:1 cipher:4 auth:2 spi:2b1e5300 oppspi:59e8a000 esrc:10.72.0.60 edst:10.72.0.2 dstnet:10.73.8.25 dstmask:0.0.0.0 nattport:35228 trust:0 dpd:0 ingress:0 sacl:0 family: 2
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| Deleted the IPSEC SA --- DONE !!
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| DP SA out:0 natt:1 mode:1 proto:1 cipher:4 auth:2 spi:59e8a000 oppspi:2b1e5300 esrc:10.72.0.2 edst:10.72.0.60 dstnet:0.0.0.0 dstmask:0.0.0.0 nattport:35228 trust:0 dpd:0 ingress:0 sacl:0 family: 20
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| Deleted the IPSEC SA --- DONE !!
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| IPSEC_delSa: freeing innerip:10.73.8.25
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| freeL2TPIP freeing IP 10.73.8.25 from pool
Jul 31 09:56:27 :124004: <8405> <DBUG> |authmgr| RX (sock) message of type 19, len 64
Jul 31 09:56:27 :124459: <8405> <DBUG> |authmgr| IP DN int: 10.73.8.25, ext:10.72.0.2
Jul 31 09:56:27 :124004: <8405> <DBUG> |authmgr| auth_ip_down: send IP down to SAPM for RAP with inner ip 10.73.8.25 outer ip 10.72.0.2
Jul 31 09:56:27 :124004: <8405> <DBUG> |authmgr| user_download: User 10.72.0.2 Router Acl(0)
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| IKE_resetInnerIP: Reset innerip:10.73.8.25 in IKESA
Jul 31 09:56:27 :124163: <8405> <DBUG> |authmgr| download-L3: ip=10.72.0.2 acl=2/0 role=logon, Ubwm=0, Dbwm=0 tunl=0x0, PA=0, HA=1, RO=0, VPN=0, MAC=00:00:00:00:00:00.
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| IPSEC_delSa freeing pxsa 0xa2370c
Jul 31 09:56:27 :124234: <8405> <DBUG> |authmgr| Tx message to Sibyte, blocking with ack, Opcode = 164, msglen = 596 2 user messages bundled, actions = 18, 20
Jul 31 09:56:27 :103060: <8352> <DBUG> |ike| sa.c:sa_xauth_down:2715 ikev2_sa_xauth_down success ip 0.2.0.0 flag 4
Jul 31 09:56:27 :103069: <8352> <INFO> |ike| IKE received AP DOWN for 10.73.8.25 (External 10.72.0.2)
Jul 31 09:56:27 :103060: <8352> <DBUG> |ike| ipc.c:ipc_rcvcb:3688 sa_xauth_downreturned ok for IP10.73.8.25: flag 4
Jul 31 09:56:27 :124004: <8405> <DBUG> |authmgr| IP User delete: [10.73.8.25
Jul 31 09:56:27 :124687: <8405> <DBUG> |authmgr| AP-GROUP:16 Group Name: default released.
Jul 31 09:56:27 :124234: <8405> <DBUG> |authmgr| Tx message to Sibyte, blocking with ack, Opcode = 17, msglen = 352 action = 1
Jul 31 09:56:27 :124153: <8405> <DBUG> |authmgr| Free ipuser 0x23f492c (10.73.8.25) for user 0x2353a64.
Jul 31 09:56:27 :124154: <8405> <DBUG> |authmgr| Free user 0x2353a64.
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> udp_encap_handle_message ver:2 serverInst:1 pktsize:80
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> IKE_EXAMPLE_IKE_msgRecv: ip:10.72.0.2 port:35228 server:1 len:80 numSkts:8
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> IKE_EXAMPLE_IKE_msgRecv:1369: IKE2_msgRecv Called
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> IKE2_msgRecv: dwPeerAddr: a480002 wPeerPort: 899c
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> sha1 encr=aes
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> #RECV 80 bytes from 10.72.0.2(35228) at 10.72.0.60 (1347877.228)
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> spi={0bc043b1bfd60a16 3ba9422eb38f0e7b} np=E{D}
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> exchange=INFORMATIONAL msgid=2 len=76
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> IKE2_xchgIn:1387
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> IKE2_newXchg oExchange:37 bReq:0 dwMsgId:2
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> IKE2_newXchg before delXchg
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> IKE2_delXchg Deleting exchange
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> --> R Delete: 0 IKE_ SA's
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> <-- R#SEND 80 bytes to 10.72.0.2(35228) (1347877.228)
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> IKE_SAMPLE_ikeXchgSend: server instance 1
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> cleanup_and_free_context delete ctx memory
Jul 31 09:56:27 :103063: <8352> <DBUG> |ike| 10.72.0.2:35228-> udp_encap_handle_message IKEv2 pkt status:0
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE2_updateSadb Permanently Deleting IKE_SA
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE2_updateSadb Permanently Deleting IKE_SA for peer 10.72.0.2:35228
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE2_delSa sa:0xb6597c peer:10.72.0.2:35228 id:2189892590 err:0 saflags:30100059 arflags:5
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE2_delSa before IKE2_delXchg
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE_SA (id=0x82871bee) deleted
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| , status = -8972
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE2_delSa before 2nd IKE2_delXchg
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE2_delXchg Deleting exchange
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE2_delSa: deleting IPSEC SA 10.72.0.2:35228 due to deletion of un-rekeyed IKE_SA
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE_deleteHW_state cookies:a480002:899c
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| IKE2_delSa: isarubaAp 1 isarubaCampusAp 0 isMasterLocal 0 isBOC 0 ispeeruplinkfailover 0 username 20:4c:03:3f:db:2d before calling mac_hash_tbl_delete_sa_entry
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| mac_hash_tbl_delete_sa_entry: deleting for mac 20:4c:03:3f:db:2d
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| ikev2_same_sa:
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| Cookies : Initiator cookie:0bc043b1bfd60a16 new sa Initiator cookie:0bc043b1bfd60a16
Jul 31 09:56:28 :103063: <8352> <DBUG> |ike| Cookies : Responder cookie:3ba9422eb38f0e7b new sa Responder cookie:3ba9422eb38f0e7b
Jul 31 09:56:28 :103102: <8352> <INFO> |ike| IKE SA deleted for peer 10.72.0.2

I will enclose the complete log.

I will be glad for any advice.

Attachment(s)

ipsec-log.txt   62 KB 1 version

Did you find a solution to this? I'm running into a similar issue. . IPSEC tunnel comes up then drops almost immediately. 

I suspect my Palo firewall is doing something with the traffic that I can't track down.

What is the controller image version And the RAP model?

Could you determine what Ike version is being used to try and setup the tunnel by the RAP? And does the controller image version support the said IKE version?

This may be a scenario where the controller supports one version of IKE while the RAP is using another IKE version to negotiate the tunnel.

What is the output of the command 

show crypto-local ipsec-map?

Were any changes made to the security association lifetime? The default is 300 

• 8.7 (Upgraded from 8.6.02)
• It should be using ikev2. The tunnel comes up for a brief moment then drops.
• The command you listed shows the associations between my two controllers, and my MM.
• I didn't change the lifetime. . it appears mine is 3600 or greater.

Sadly, we did not find a solution. Our Customer has two locations. It turns out, that it was not possible to connect the RAP to the Controller in the same location, but to the controller in the other location. That was our workaround.

I also suspect the firewall, cause the customer is in finance and has a two tier firewall design. We connected the RAP to the wired guest network which is behind a separate firewall and than had to pass two other firewalls to come to the controller. I believe there is something wrong between the guest firewall and the external firewall. But as I said, we never found a solution.

I found my issue was I didn't have two available public IPs. So when the nodelist was sent back to the RAP, and the RAP tried to build the second tunnel and failed...it tore down both tunnels. 

While I understand this design I wish there was more flexibility. 

In the end I spun up a standalone MD VMC to terminate the RAPS. 

Hello,

We ran into this same issue and resolved it by the following.

Our setup:
-3 Node RAP cluster
-All three controllers have a 1-1 Public IP NAT handled by Palo's
-Firmware was 8.5.0.11

The Fix:

-Login directly to one of the MD's and run "show sapm cluster nodestate". You should see "Public IP" listed with your RAP public IP's defined in the Cluster Group. In our case, our setup only displayed 0.0.0.0 in the public IP section.

- We ended up deleting all controllers out of the cluster memberships and group (Requires an outage)

-Build the cluster again and make sure all of the controllers have the same priorities (default is fine). In our case, we had different priorities set for the MD's in the cluster and suspect that may have been causing us issues as well.

-We also upgraded to 8.5.0.12 firmware while we had an outage window.

-Run the "show sapm cluster nodestate " again directly on the MD and verify the Public IP is now displaying correctly for all MD's.

-Re-provision your RAP's and you should be all set.

Hope this helps someone out!

Thank you,

Mat