IPSEC VPN Phase 2 is not working after Software Upgrade "NOTIFY INVALID_ID_INFO protocol 1"

[Drew1815]

Hi All,

I had a number of IPSEC VTI VPN tunnels up and working prior to an IOS router upgrade.

The device is a c3945 and was previous running:

c3900e-universalk9-mz.SPA.154-3.M3.bin

and upgrade to:

c3900e-universalk9-mz.SPA.157-3.M4b.bin

All except one IPSEC VPN Tunnel re-established after the upgrade. Debugs from the failed one indicates that Phase 1 ISAKMP re-connects successfully, however fails during the Phase 2 QM1 phase:

==================================================================================

Jul 31 2019 10:48:41.176 AEST: ISAKMP-PAK: (12353):received packet from 10.100.10.1 dport 500 sport 500 Global (I) QM_IDLE
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):set new node 1786953385 to QM_IDLE
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):processing HASH payload. message ID = 1786953385
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):processing NOTIFY INVALID_ID_INFO protocol 1
spi 0, message ID = 1786953385, sa = 0x2A866820
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):peer does not do paranoid keepalives.
Jul 31 2019 10:48:41.176 AEST: ISAKMP-ERROR: (12353):deleting SA reason "Recevied fatal informational" state (I) QM_IDLE (peer 10.100.10.1)
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):deleting node 1786953385 error FALSE reason "Informational (in) state 1"
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

Jul 31 2019 10:48:41.176 AEST: IPSEC(key_engine): got a queue event with 1 KMI message(s)
Jul 31 2019 10:48:41.176 AEST: IPSEC(ipsec_get_crypto_session_id):
Invalid Payload Id
Jul 31 2019 10:48:41.176 AEST: IPSec: Key engine got a KEY_MGR_CHECK_MORE_SAS message
Jul 31 2019 10:48:41.176 AEST: %CRYPTO-6-ISAKMP_MANUAL_DELETE: IKE SA manually deleted. Do 'clear crypto sa peer 10.100.10.1' to manually clear IPSec SA's covered by this IKE SA.
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):set new node 1148347237 to QM_IDLE

==============================================================================

Searches on the forum + online for the following:

1) "NOTIFY INVALID_ID_INFO protocol  1"

2) "ISAKMP-ERROR:deleting SA reason "Recevied fatal informational" state (I) QM_IDLE"

3) "CRYPTO-6-ISAKMP_MANUAL_DELETE: IKE SA manually deleted. Do 'clear crypto sa peer"

Indicates that a couple of possible reasons could be:

1) Missing PFS configuration

2) Mis-match in the IPSEC Transformation-set

3) ISAKMP Keepalives not set

These have been re-checked, so I'm a little lost what may be causing this issue as this was all working prior.

The other side of the VPN tunnel is a Sophos UTM v9.

There is a snippet of the Cisco c3945 relevant config:

######################################################## 

!
!
crypto isakmp policy 5
encr aes 256
hash sha256
authentication pre-share
group 14
lifetime 28800
!

crypto isakmp key 6 <removed> address 10.100.10.1

crypto isakmp keepalive 10

!

crypto ipsec transform-set ClientX esp-aes 256 esp-sha256-hmac
mode tunnel

!

crypto ipsec profile ClientX_VPN
set transform-set ClientX 
set pfs group14
!

!
interface Tunnel3
description <removed> Connectivity
ip vrf forwarding <removed>
ip address <172.x.x.x> 255.255.255.252
ip access-group ClientX-VPN in
ip mtu 1400
ip tcp adjust-mss 1360
load-interval 30
tunnel source Loopback10
tunnel mode ipsec ipv4
tunnel destination 10.100.10.1
tunnel protection ipsec profile ClientX_VPN
!

Here is a snippet of the debug cycle:

#####################################################################

Jul 31 2019 10:48:39.471 AEST: IPSEC:(SESSION ID = 760) (key_engine) request timer fired: count = 2,
(identity) local= <Removed>:0, remote= 10.100.10.1:0,
local_proxy= 0.0.0.0/0.0.0.0/256/0,
remote_proxy= 0.0.0.0/0.0.0.0/256/0
Jul 31 2019 10:48:39.912 AEST: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= <Removed>:500, remote= 10.100.10.1: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 256 esp-sha256-hmac (Tunnel),
lifedur= 28800s and 4608000kb,
spi= 0x0(0), conn_id= 0, keysize= 256, flags= 0x0
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):SA request profile is (NULL)
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):Found a peer struct for 10.100.10.1, peer port 500
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):Locking peer struct 0x22F8F254, refcount 1 for isakmp_initiator
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):local port 500, remote port 500
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):set new node 0 to QM_IDLE
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):Find a dup sa in the avl tree during calling isadb_insert sa = 2A866820
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):Can not start Aggressive mode, trying Main mode.
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):found peer pre-shared key matching 10.100.10.1
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):Old State = IKE_READY New State = IKE_I_MM1

Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):beginning Main Mode exchange
Jul 31 2019 10:48:39.912 AEST: ISAKMP-PAK: (0):sending packet to 10.100.10.1 my_port 500 peer_port 500 (I) MM_NO_STATE
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):Sending an IKE IPv4 Packet.
Jul 31 2019 10:48:39.912 AEST: ISAKMP: (0):DPD received KMI message.

Jul 31 2019 10:48:40.220 AEST: ISAKMP-PAK: (0):received packet from 10.100.10.1 dport 500 sport 500 Global (I) MM_NO_STATE
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Old State = IKE_I_MM1 New State = IKE_I_MM2

Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):processing SA payload. message ID = 0
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):processing vendor id payload
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):vendor ID seems Unity/DPD but major 91 mismatch
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):processing vendor id payload
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):vendor ID is Unity
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):processing vendor id payload
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):vendor ID seems Unity/DPD but major 215 mismatch
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):vendor ID is XAUTH
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):processing vendor id payload
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):vendor ID is DPD
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):found peer pre-shared key matching 10.100.10.1
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):local preshared key found
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Scanning profiles for xauth ...
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Checking ISAKMP transform 1 against priority 5 policy
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0): encryption AES-CBC
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0): keylength of 256
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0): hash SHA256
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0): default group 14
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0): auth pre-share
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0): life type in seconds
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0): life duration (basic) of 28800
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):atts are acceptable. Next payload is 0
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Acceptable atts:actual life: 28800
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Acceptable atts:life: 0
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Basic life_in_seconds:28800
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Returning Actual lifetime: 28800
Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Started lifetime timer: 28800.

Jul 31 2019 10:48:40.220 AEST: ISAKMP: (0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Jul 31 2019 10:48:40.222 AEST: ISAKMP: (0):Old State = IKE_I_MM2 New State = IKE_I_MM2

Jul 31 2019 10:48:40.222 AEST: ISAKMP-PAK: (0):sending packet to 10.100.10.1 my_port 500 peer_port 500 (I) MM_SA_SETUP
Jul 31 2019 10:48:40.222 AEST: ISAKMP: (0):Sending an IKE IPv4 Packet.
Jul 31 2019 10:48:40.222 AEST: ISAKMP: (0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Jul 31 2019 10:48:40.222 AEST: ISAKMP: (0):Old State = IKE_I_MM2 New State = IKE_I_MM3

Jul 31 2019 10:48:40.560 AEST: ISAKMP-PAK: (0):received packet from 10.100.10.1 dport 500 sport 500 Global (I) MM_SA_SETUP
Jul 31 2019 10:48:40.560 AEST: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Jul 31 2019 10:48:40.560 AEST: ISAKMP: (0):Old State = IKE_I_MM3 New State = IKE_I_MM4

Jul 31 2019 10:48:40.560 AEST: ISAKMP: (0):processing KE payload. message ID = 0
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (0):processing NONCE payload. message ID = 0
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (0):found peer pre-shared key matching 10.100.10.1
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):Old State = IKE_I_MM4 New State = IKE_I_MM4

Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):SA is doing
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):pre-shared key authentication using id type ID_IPV4_ADDR
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):ID payload
next-payload : 8
type : 1
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353): address : <Removed>
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353): protocol : 17
port : 500
length : 12
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):Total payload length: 12
Jul 31 2019 10:48:40.562 AEST: ISAKMP-PAK: (12353):sending packet to 10.100.10.1 my_port 500 peer_port 500 (I) MM_KEY_EXCH
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):Sending an IKE IPv4 Packet.
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Jul 31 2019 10:48:40.562 AEST: ISAKMP: (12353):Old State = IKE_I_MM4 New State = IKE_I_MM5

Jul 31 2019 10:48:40.868 AEST: ISAKMP-PAK: (12353):received packet from 10.100.10.1 dport 500 sport 500 Global (I) MM_KEY_EXCH
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):processing ID payload. message ID = 0
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):ID payload
next-payload : 8
type : 1
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353): address : 10.100.10.1
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353): protocol : 0
port : 0
length : 12
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (0):peer matches *none* of the profiles
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):processing HASH payload. message ID = 0
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):SA authentication status:
authenticated
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):SA has been authenticated with 10.100.10.1
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):Old State = IKE_I_MM5 New State = IKE_I_MM6

Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):Old State = IKE_I_MM6 New State = IKE_I_MM6

Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):Old State = IKE_I_MM6 New State = IKE_P1_COMPLETE

Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):IKE_DPD is enabled, initializing timers
Jul 31 2019 10:48:40.868 AEST: ISAKMP: (12353):beginning Quick Mode exchange, M-ID of 3752682523
Jul 31 2019 10:48:40.870 AEST: ISAKMP: (12353):QM Initiator gets spi
Jul 31 2019 10:48:40.870 AEST: ISAKMP-PAK: (12353):sending packet to 10.100.10.1 my_port 500 peer_port 500 (I) QM_IDLE
Jul 31 2019 10:48:40.870 AEST: ISAKMP: (12353):Sending an IKE IPv4 Packet.
Jul 31 2019 10:48:40.870 AEST: ISAKMP: (12353):Node 3752682523, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
Jul 31 2019 10:48:40.870 AEST: ISAKMP: (12353):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
Jul 31 2019 10:48:40.870 AEST: ISAKMP: (12353):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
Jul 31 2019 10:48:40.870 AEST: ISAKMP: (12353):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

Jul 31 2019 10:48:41.168 AEST: ISAKMP: (0):retransmission skipped for phase 1 (time since last transmission 222)
Jul 31 2019 10:48:41.176 AEST: ISAKMP-PAK: (12353):received packet from 10.100.10.1 dport 500 sport 500 Global (I) QM_IDLE
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):set new node 1786953385 to QM_IDLE
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):processing HASH payload. message ID = 1786953385
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):processing NOTIFY INVALID_ID_INFO protocol 1
spi 0, message ID = 1786953385, sa = 0x2A866820
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):peer does not do paranoid keepalives.
Jul 31 2019 10:48:41.176 AEST: ISAKMP-ERROR: (12353):deleting SA reason "Recevied fatal informational" state (I) QM_IDLE (peer 10.100.10.1)
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):deleting node 1786953385 error FALSE reason "Informational (in) state 1"
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

Jul 31 2019 10:48:41.176 AEST: IPSEC(key_engine): got a queue event with 1 KMI message(s)
Jul 31 2019 10:48:41.176 AEST: IPSEC(ipsec_get_crypto_session_id):
Invalid Payload Id
Jul 31 2019 10:48:41.176 AEST: IPSec: Key engine got a KEY_MGR_CHECK_MORE_SAS message
Jul 31 2019 10:48:41.176 AEST: %CRYPTO-6-ISAKMP_MANUAL_DELETE: IKE SA manually deleted. Do 'clear crypto sa peer 10.100.10.1' to manually clear IPSec SA's covered by this IKE SA.
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):set new node 1148347237 to QM_IDLE
Jul 31 2019 10:48:41.176 AEST: ISAKMP-PAK: (12353):sending packet to 10.100.10.1 my_port 500 peer_port 500 (I) QM_IDLE
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Sending an IKE IPv4 Packet.
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):purging node 1148347237
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Old State = IKE_P1_COMPLETE New State = IKE_DEST_SA

Jul 31 2019 10:48:41.176 AEST: ISAKMP-ERROR: (12353):deleting SA reason "Recevied fatal informational" state (I) QM_IDLE (peer 10.100.10.1)
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (0):Unlocking peer struct 0x22F8F254 for isadb_mark_sa_deleted(), count 0
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):deleting node -542284773 error FALSE reason "IKE deleted"
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Jul 31 2019 10:48:41.176 AEST: ISAKMP: (12353):Old State = IKE_DEST_SA New State = IKE_DEST_SA

Jul 31 2019 10:48:41.482 AEST: ISAKMP-PAK: (12353):received packet from 10.100.10.1 dport 500 sport 500 Global (I) MM_NO_STATE

============================================================================================

Any clues or hints on where to investigate next would be most appreciated.

All thoughts welcome.

Thanking you

Regards

Drew

[robert morann]

did you manage to find the issue ?