Hello everybody,
we do have the follow problem. We have 2 cisco ISR4321/K9 (Version 15.4(3)S5). On the backup router the s2s vpn connection is stable and working on the primary router S2S VPN is working sporadically. We have checked everything and can´t find the problem. In the log we do get those messages:
021769: Jun 2 13:49:19.243 cest: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 195.243.136.117)
021770: Jun 2 13:49:19.243 cest: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 195.243.136.117)
021771: Jun 2 13:49:19.244 cest: ISAKMP: Unlocking peer struct 0x7FB18D8B68C8 for isadb_mark_sa_deleted(), count 0
021772: Jun 2 13:49:19.244 cest: Can't log the KMI message, peer is NULL
021773: Jun 2 13:49:19.244 cest: ISAKMP: Deleting peer node by peer_reap for 195.243.136.117: 7FB18D8B68C8
021774: Jun 2 13:49:19.252 cest: ISAKMP:(0):deleting node 118581412 error FALSE reason "IKE deleted"
021775: Jun 2 13:49:19.252 cest: ISAKMP:(0):deleting node 2226642458 error FALSE reason "IKE deleted"
021776: Jun 2 13:49:19.252 cest: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
021777: Jun 2 13:49:19.252 cest: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_DEST_SA
021778: Jun 2 13:49:19.252 cest: IPSEC(key_engine): got a queue event with 1 KMI message(s)
021779: Jun 2 13:49:19.669 cest: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 172.16.2.17:500, remote= 195.243.136.117:500,
local_proxy= 0.0.0.0/0.0.0.0/256/0,
remote_proxy= 0.0.0.0/0.0.0.0/256/0,
protocol= ESP, transform= esp-aes esp-sha-hmac (Tunnel),
lifedur= 3600s and 4608000kb,
spi= 0x0(0), conn_id= 0, keysize= 128, flags= 0x0
021780: Jun 2 13:49:19.669 cest: ISAKMP:(0): SA request profile is (NULL)
021781: Jun 2 13:49:19.669 cest: ISAKMP: Created a peer struct for 195.243.136.117, peer port 500
021782: Jun 2 13:49:19.670 cest: ISAKMP: New peer created peer = 0x7FB18D8B68C8 peer_handle = 0x80000099
021783: Jun 2 13:49:19.670 cest: ISAKMP: Locking peer struct 0x7FB18D8B68C8, refcount 1 for isakmp_initiator
021784: Jun 2 13:49:19.670 cest: ISAKMP: local port 500, remote port 500
021785: Jun 2 13:49:19.670 cest: ISAKMP: set new node 0 to QM_IDLE
021786: Jun 2 13:49:19.670 cest: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 7FB18746A000
021787: Jun 2 13:49:19.670 cest: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
021788: Jun 2 13:49:19.670 cest: ISAKMP:(0):found peer pre-shared key matching 195.243.136.117
021789: Jun 2 13:49:19.670 cest: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
021790: Jun 2 13:49:19.670 cest: ISAKMP:(0): constructed NAT-T vendor-07 ID
021791: Jun 2 13:49:19.670 cest: ISAKMP:(0): constructed NAT-T vendor-03 ID
021792: Jun 2 13:49:19.670 cest: ISAKMP:(0): constructed NAT-T vendor-02 ID
021793: Jun 2 13:49:19.670 cest: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
021794: Jun 2 13:49:19.670 cest: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1
021795: Jun 2 13:49:19.670 cest: ISAKMP:(0): beginning Main Mode exchange
021796: Jun 2 13:49:19.670 cest: ISAKMP:(0): sending packet to 195.243.136.117 my_port 500 peer_port 500 (I) MM_NO_STATE
021797: Jun 2 13:49:19.670 cest: ISAKMP:(0):Sending an IKE IPv4 Packet.
021798: Jun 2 13:49:23.855 cest: IPSLA-OPER_TRACE: slaCommonStatsGet:slaTagApiStatsLatest minrtt 4294967295
021799: Jun 2 13:49:28.855 cest: IPSLA-OPER_TRACE: slaCommonStatsGet:slaTagApiStatsLatest minrtt 4294967295
021800: Jun 2 13:49:29.670 cest: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
021801: Jun 2 13:49:29.670 cest: ISAKMP (0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1
021802: Jun 2 13:49:29.670 cest: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
021803: Jun 2 13:49:29.670 cest: ISAKMP:(0): sending packet to 195.243.136.117 my_port 500 peer_port 500 (I) MM_NO_STATE
021804: Jun 2 13:49:29.670 cest: ISAKMP:(0):Sending an IKE IPv4 Packet.
021805: Jun 2 13:49:33.650 cest: IPSLA-INFRA_TRACE:OPER:100 slaSchedulerEventWakeup
021806: Jun 2 13:49:33.650 cest: IPSLA-INFRA_TRACE:OPER:100 Starting an operation
021807: Jun 2 13:49:33.650 cest: IPSLA-OPER_TRACE:OPER:100 source IP:172.16.198.66
021808: Jun 2 13:49:33.650 cest: IPSLA-OPER_TRACE:OPER:100 Starting icmpecho operation - destAddr=172.16.198.65, sAddr=172.16.198.66
021809: Jun 2 13:49:33.650 cest: IPSLA-OPER_TRACE:OPER:100 Sending ID: 1539
021810: Jun 2 13:49:33.855 cest: IPSLA-OPER_TRACE: slaCommonStatsGet:slaTagApiStatsLatest minrtt 4294967295
021814: Jun 2 14:09:22.037 cest: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel1, changed state to up
021815: Jun 2 14:09:34.385 cest: %TRACK-6-STATE: 100 ip sla 100 state Down -> Up
021816: Jun 2 14:09:34.435 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Standby -> Active
021817: Jun 3 08:06:38.137 cest: %TRACK-6-STATE: 100 ip sla 100 state Up -> Down
021818: Jun 3 08:06:38.476 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Active -> Speak
021819: Jun 3 08:06:48.883 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Speak -> Standby
021820: Jun 3 08:07:38.164 cest: %TRACK-6-STATE: 100 ip sla 100 state Down -> Up
021821: Jun 3 08:07:38.614 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Standby -> Active
021822: Jun 3 08:08:38.188 cest: %TRACK-6-STATE: 100 ip sla 100 state Up -> Down
021823: Jun 3 08:08:38.444 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Active -> Speak
021824: Jun 3 08:08:48.848 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Speak -> Standby
021825: Jun 3 08:09:38.215 cest: %TRACK-6-STATE: 100 ip sla 100 state Down -> Up
021826: Jun 3 08:09:40.450 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Standby -> Active
021827: Jun 3 08:58:39.520 cest: %TRACK-6-STATE: 100 ip sla 100 state Up -> Down
021828: Jun 3 08:58:40.574 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Active -> Speak
021829: Jun 3 08:58:51.486 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Speak -> Standby
021830: Jun 3 08:59:34.543 cest: %TRACK-6-STATE: 100 ip sla 100 state Down -> Up
021831: Jun 3 08:59:34.830 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Standby -> Active
021832: Jun 3 09:02:39.625 cest: %TRACK-6-STATE: 100 ip sla 100 state Up -> Down
021833: Jun 3 09:02:40.795 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Active -> Speak
021834: Jun 3 09:02:52.803 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Speak -> Standby
021835: Jun 3 09:03:34.650 cest: %TRACK-6-STATE: 100 ip sla 100 state Down -> Up
021836: Jun 3 09:03:37.301 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Standby -> Active
021837: Jun 3 09:16:39.998 cest: %TRACK-6-STATE: 100 ip sla 100 state Up -> Down
021838: Jun 3 09:16:42.515 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Active -> Speak
021839: Jun 3 09:16:52.628 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Speak -> Standby
021840: Jun 3 09:17:35.023 cest: %TRACK-6-STATE: 100 ip sla 100 state Down -> Up
021841: Jun 3 09:17:36.642 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Standby -> Active
021842: Jun 3 09:18:40.051 cest: %TRACK-6-STATE: 100 ip sla 100 state Up -> Down
021843: Jun 3 09:18:41.834 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Active -> Speak
021844: Jun 3 09:18:52.355 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Speak -> Standby
021845: Jun 3 09:19:35.076 cest: %TRACK-6-STATE: 100 ip sla 100 state Down -> Up
021846: Jun 3 09:19:35.668 cest: %HSRP-5-STATECHANGE: GigabitEthernet0/0/0 Grp 121 state Standby -> Active
Maybe someone has an idea.
Attached also the config from the primary and backup router.
Many thanks and best regards,
Michael
