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.