05-11-2017 11:12 AM
Dears,
I have a site to site VPN between PAN 7.1.6 and Cisco ASA 8.2.5, I'm receiving a lot of Invalid SPI error. I tried to reset the VPN many times and still having the same issue. This issue by the way is casusing a lot of packet dropes in the VPN
'IKE protocol notification message received: INVALID-SPI (11).'
Did any one faced a similer issue or have an idea on how to mitigate such issue ?
05-11-2017 01:14 PM
Hi,
Please post an output of the below command:
> tail lines 50 mp-log ikemgr.log
05-11-2017 02:17 PM
The output of the command:
2017-05-11 23:12:11 [INFO]: SADB_ADD ul_proto=255 src=196.3.15.6[500] dst=37.200.227.2[500] satype=ESP samode=tunl spi=0x82DA0798 authtype=SHA1 enctype=AES256 enclen=32 lifetime soft time=23699 bytes=4718592000 hard time=28800 bytes=4718592000
2017-05-11 23:12:11 [INFO]: IPsec-SA established: ESP/Tunnel 37.200.227.2[500]->196.3.15.6[500] spi=2404262458(0x8f4e223a)
2017-05-11 23:12:11 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 196.3.15.6[500]-37.200.227.2[500] SPI:0x8F4E223A/0x82DA0798 lifetime 28800 Sec lifesize 4608000 KB <====
2017-05-11 23:12:11 [INFO]: keymirror add start ++++++++++++++++
2017-05-11 23:12:11 [INFO]: keymirror add for gw 0x62, tn 165, selfSPI 8F4E223A, retcode 0.
2017-05-11 23:12:12 [INFO]: keymirror del start ----------------
2017-05-11 23:12:12 [INFO]: keymirror del for gw 62, tn 165, selfSPI DE59D8F2, retcode 0.
2017-05-11 23:12:12 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 196.3.15.6[500]-37.200.227.2[500] SPI:0xDE59D8F2/0x895B2115 <====
2017-05-11 23:12:12 [INFO]: SADB_DELETE ul_proto=0 src=196.3.15.6[500] dst=37.200.227.2[500] satype=ESP spi=0xDE59D8F2
2017-05-11 23:12:12 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xDE59D8F2
2017-05-11 23:12:13 [PROTO_NOTIFY]: ====> PHASE-2 NEGOTIATION STARTED AS RESPONDER, (QUICK MODE) <====
====> Initiated SA: 196.3.15.6[500]-37.200.227.2[500] message id:0x53707D24 <====
2017-05-11 23:12:13 [PROTO_NOTIFY]: ====> PHASE-2 NEGOTIATION SUCCEEDED AS RESPONDER, (QUICK MODE) <====
====> Established SA: 196.3.15.6[500]-37.200.227.2[500] message id:0x53707D24, SPI:0x88E48F13/0x45A3A41B <====
2017-05-11 23:12:13 [INFO]: SADB_UPDATE ul_proto=255 src=37.200.227.2[500] dst=196.3.15.6[500] satype=ESP samode=tunl spi=0x88E48F13 authtype=SHA1 enctype=AES256 enclen=32 lifetime soft time=28800 bytes=4718592000 hard time=28800 bytes=4718592000
2017-05-11 23:12:13 [INFO]: SADB_ADD ul_proto=255 src=196.3.15.6[500] dst=37.200.227.2[500] satype=ESP samode=tunl spi=0x45A3A41B authtype=SHA1 enctype=AES256 enclen=32 lifetime soft time=24717 bytes=4718592000 hard time=28800 bytes=4718592000
2017-05-11 23:12:13 [INFO]: IPsec-SA established: ESP/Tunnel 37.200.227.2[500]->196.3.15.6[500] spi=2296680211(0x88e48f13)
2017-05-11 23:12:13 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 196.3.15.6[500]-37.200.227.2[500] SPI:0x88E48F13/0x45A3A41B lifetime 28800 Sec lifesize 4608000 KB <====
2017-05-11 23:12:13 [INFO]: keymirror add start ++++++++++++++++
2017-05-11 23:12:13 [INFO]: keymirror add for gw 0x62, tn 238, selfSPI 88E48F13, retcode 0.
2017-05-11 23:12:13 [INFO]: keymirror del start ----------------
2017-05-11 23:12:13 [INFO]: keymirror del for gw 62, tn 238, selfSPI BED9420E, retcode 0.
2017-05-11 23:12:13 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 196.3.15.6[500]-37.200.227.2[500] SPI:0xBED9420E/0x6676265D <====
2017-05-11 23:12:13 [INFO]: SADB_DELETE ul_proto=0 src=196.3.15.6[500] dst=37.200.227.2[500] satype=ESP spi=0xBED9420E
2017-05-11 23:12:13 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xBED9420E
2017-05-11 23:12:15 [PROTO_NOTIFY]: ====> PHASE-2 NEGOTIATION STARTED AS RESPONDER, (QUICK MODE) <====
====> Initiated SA: 196.3.15.6[500]-37.200.227.2[500] message id:0x53573711 <====
2017-05-11 23:12:15 [PROTO_NOTIFY]: ====> PHASE-2 NEGOTIATION SUCCEEDED AS RESPONDER, (QUICK MODE) <====
====> Established SA: 196.3.15.6[500]-37.200.227.2[500] message id:0x53573711, SPI:0xAB25A184/0x4B96A1DB <====
2017-05-11 23:12:15 [INFO]: SADB_UPDATE ul_proto=255 src=37.200.227.2[500] dst=196.3.15.6[500] satype=ESP samode=tunl spi=0xAB25A184 authtype=SHA1 enctype=AES256 enclen=32 lifetime soft time=28800 bytes=4718592000 hard time=28800 bytes=4718592000
2017-05-11 23:12:15 [INFO]: SADB_ADD ul_proto=255 src=196.3.15.6[500] dst=37.200.227.2[500] satype=ESP samode=tunl spi=0x4B96A1DB authtype=SHA1 enctype=AES256 enclen=32 lifetime soft time=24531 bytes=4718592000 hard time=28800 bytes=4718592000
2017-05-11 23:12:15 [INFO]: IPsec-SA established: ESP/Tunnel 37.200.227.2[500]->196.3.15.6[500] spi=2871370116(0xab25a184)
2017-05-11 23:12:15 [PROTO_NOTIFY]: ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 196.3.15.6[500]-37.200.227.2[500] SPI:0xAB25A184/0x4B96A1DB lifetime 28800 Sec lifesize 4608000 KB <====
2017-05-11 23:12:15 [INFO]: keymirror add start ++++++++++++++++
2017-05-11 23:12:15 [INFO]: keymirror add for gw 0x62, tn 239, selfSPI AB25A184, retcode 0.
2017-05-11 23:12:16 [INFO]: keymirror del start ----------------
2017-05-11 23:12:16 [INFO]: keymirror del for gw 62, tn 239, selfSPI D27B0ECA, retcode 0.
2017-05-11 23:12:16 [PROTO_NOTIFY]: ====> IPSEC KEY DELETED <====
====> Deleted SA: 196.3.15.6[500]-37.200.227.2[500] SPI:0xD27B0ECA/0xEF3B3C45 <====
2017-05-11 23:12:16 [INFO]: SADB_DELETE ul_proto=0 src=196.3.15.6[500] dst=37.200.227.2[500] satype=ESP spi=0xD27B0ECA
2017-05-11 23:12:16 [INFO]: received PFKEY_DELETE seq=0 satype=ESP spi=0xD27B0ECA
2017-05-11 23:12:18 [PROTO_NOTIFY]: notification message 11:INVALID-SPI, doi=1 proto_id=3 spi=27f42f2f(size=4).
2017-05-11 23:12:24 [PROTO_NOTIFY]: notification message 11:INVALID-SPI, doi=1 proto_id=3 spi=27f42f2f(size=4).
2017-05-11 23:12:36 [PROTO_NOTIFY]: notification message 11:INVALID-SPI, doi=1 proto_id=3 spi=728a83a3(size=4).
2017-05-11 23:12:36 [PROTO_NOTIFY]: notification message 36136:R-U-THERE, doi=1 proto_id=1 spi=ab1b78c39120cd9e 7be127d67dcd5923 (size=16).
05-11-2017 02:53 PM
by the way i'm facing VPN disconnections with all IPSEC with ASA on the other side.
05-11-2017 02:58 PM - edited 05-11-2017 03:01 PM
How are your proxy id's settings looks like? Are they matching? DPD setting (timers) should also match. Can you please confirm this
05-11-2017 03:08 PM
Proxy ID's are exactly matching ASA and i'm working with same Proxy ID's for Two years.
DPD, is disables on most of the Tunnels.
VPN tunnels with PAN in both side are ok and stable
only tunnels with ASA on the other side is haveving this flapping issue with INvaldi SPI error since yesterday.
05-11-2017 03:19 PM
Can you turn on debug to and post detailed logs please:
> debug ike global on debug
> tail lines 50 mp-log ikemgr.log
> debug ike global on normal
What has changed since yesterday? Pinging experts
05-11-2017 03:28 PM
nothing changed since yesterday. VPNs start flapping and making invalid SPI's suddenly. i tried many times to clear and re-initae phase1/2 and it is not solving the issues.
Below is the output of the debug
017-05-12 00:24:19 [DEBUG]: isakmp.c:1076:isakmp_handler():
ecf11b57 0e2169a4 6811d477 4daf87fa 08100501 061f6af2 0000004c 6b708b02
7fb7c9b7 b21999bb 97d209dc 124f53ea abadb25d a15a8096 b4472dca 69492c15
c9ce9d8c 825930a0 e9ccfcbf
2017-05-12 00:24:19 [DEBUG]: isakmp_inf.c:147:isakmp_info_recv(): receive Information.
2017-05-12 00:24:19 [DEBUG]: oakley.c:3285:oakley_newiv2(): compute IV for phase2
2017-05-12 00:24:19 [DEBUG]: oakley.c:3286:oakley_newiv2(): phase1 last IV:
2017-05-12 00:24:19 [DEBUG]: oakley.c:3287:oakley_newiv2():
7e308bb0 e98cf67c 313f58d6 8905368e 061f6af2
2017-05-12 00:24:19 [DEBUG]: algorithm.c:432:alg_oakley_hashdef(): hash(sha1)
2017-05-12 00:24:19 [DEBUG]: algorithm.c:575:alg_oakley_encdef(): encryption(aes)
2017-05-12 00:24:19 [DEBUG]: oakley.c:3320:oakley_newiv2(): phase2 IV computed:
2017-05-12 00:24:19 [DEBUG]: oakley.c:3321:oakley_newiv2():
16642745 6538b8ca 6149ca00 0de65355
2017-05-12 00:24:19 [DEBUG]: oakley.c:3367:oakley_do_decrypt(): begin decryption.
2017-05-12 00:24:19 [DEBUG]: algorithm.c:575:alg_oakley_encdef(): encryption(aes)
2017-05-12 00:24:19 [DEBUG]: oakley.c:3381:oakley_do_decrypt(): IV was saved for next processing:
2017-05-12 00:24:19 [DEBUG]: oakley.c:3383:oakley_do_decrypt():
69492c15 c9ce9d8c 825930a0 e9ccfcbf
2017-05-12 00:24:19 [DEBUG]: algorithm.c:575:alg_oakley_encdef(): encryption(aes)
2017-05-12 00:24:19 [DEBUG]: oakley.c:3418:oakley_do_decrypt(): with key:
2017-05-12 00:24:19 [DEBUG]: oakley.c:3419:oakley_do_decrypt():
75f46e88 8d518f70 9ab77070 975a9c5e 8c845ba6 e76c6dc0 7996f617 5342164b
2017-05-12 00:24:19 [DEBUG]: oakley.c:3424:oakley_do_decrypt(): decrypted payload by IV:
2017-05-12 00:24:19 [DEBUG]: oakley.c:3425:oakley_do_decrypt():
16642745 6538b8ca 6149ca00 0de65355
2017-05-12 00:24:19 [DEBUG]: oakley.c:3427:oakley_do_decrypt(): decrypted payload, but not trimed.
2017-05-12 00:24:19 [DEBUG]: oakley.c:3429:oakley_do_decrypt():
0b000018 9fbfea03 b973f072 9c240c7b 39f00f03 7be11c3e 00000010 00000001
0304000b 728a83a3 00000000 00000000
2017-05-12 00:24:19 [DEBUG]: oakley.c:3438:oakley_do_decrypt(): padding len=0
2017-05-12 00:24:19 [DEBUG]: oakley.c:3470:oakley_do_decrypt(): decrypted.
2017-05-12 00:24:19 [DEBUG]: oakley.c:3471:oakley_do_decrypt():
ecf11b57 0e2169a4 6811d477 4daf87fa 08100501 061f6af2 0000004c 0b000018
9fbfea03 b973f072 9c240c7b 39f00f03 7be11c3e 00000010 00000001 0304000b
728a83a3 00000000 00000000
2017-05-12 00:24:19 [DEBUG]: oakley.c:3345:oakley_delivm(): IV freed
2017-05-12 00:24:19 [DEBUG]: oakley.c:696:oakley_compute_hash1(): HASH with:
2017-05-12 00:24:19 [DEBUG]: oakley.c:697:oakley_compute_hash1():
061f6af2 00000010 00000001 0304000b 728a83a3
2017-05-12 00:24:19 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:24:19 [DEBUG]: oakley.c:706:oakley_compute_hash1(): HASH computed:
2017-05-12 00:24:19 [DEBUG]: oakley.c:707:oakley_compute_hash1():
9fbfea03 b973f072 9c240c7b 39f00f03 7be11c3e
2017-05-12 00:24:19 [DEBUG]: isakmp_inf.c:262:isakmp_info_recv(): hash validated.
2017-05-12 00:24:19 [DEBUG]: ikev1.c:2876:isakmp_parsewoh(): begin.
2017-05-12 00:24:19 [DEBUG]: ikev1.c:2903:isakmp_parsewoh(): seen nptype=8(hash)
2017-05-12 00:24:19 [DEBUG]: ikev1.c:2903:isakmp_parsewoh(): seen nptype=11(notify)
2017-05-12 00:24:19 [DEBUG]: ikev1.c:2942:isakmp_parsewoh(): succeed.
2017-05-12 00:24:19 [PROTO_NOTIFY]: isakmp_inf.c:1161:isakmp_info_recv_n(): notification message 11:INVALID-SPI, doi=1 proto_id=3 spi=728a83a3(size=4).
05-11-2017 03:34 PM - edited 05-11-2017 03:36 PM
Enable the debug and reset the tunnel so all info will be captured:
> test vpn ipsec-sa tunnel (your tunnel to ASA)
Do you know if something is changed on the ASA end?
05-11-2017 03:48 PM
i'm managing also ASA's and nothing changed on them.
> test vpn ipsec-sa tunnel EB-Tunnel
Initiate 27 IPSec SA for tunnel EB-Tunnel.
debug result
ahmed@EGY-PAN1(active)> tail lines 50 mp-log ikemgr.log
03b82e6b 5d9ebfa7 aac3cfc1 d383b28b 1c7d2f24 32852e74 aa6d81db fe34f90c
e7037f6a 55eea2c6 56
2017-05-12 00:45:51 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:45:51 [DEBUG]: algorithm.c:715:alg_ipsec_encdef(): encryption(aes)
2017-05-12 00:45:51 [DEBUG]: oakley.c:438:oakley_compute_keymat_x(): encklen=256 authklen=160
2017-05-12 00:45:51 [DEBUG]: oakley.c:445:oakley_compute_keymat_x(): generating 640 bits of key (dupkeymat=4)
2017-05-12 00:45:51 [DEBUG]: oakley.c:463:oakley_compute_keymat_x(): generating K1...K4 for KEYMAT.
2017-05-12 00:45:51 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:45:51 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:45:51 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:45:51 [DEBUG]: oakley.c:524:oakley_compute_keymat_x():
92da37e6 c12465ab 81a54471 2c8a176c 5dbab54e 40c77cf7 beb6827b a0fe2e30
93cfe56f 120a7515 812cb12c e15e01e6 6972e00a 77cfb87b 618856b0 bf3fdcc5
e1d6f033 5509dfad 70a0c652 200d74ba
2017-05-12 00:45:51 [DEBUG]: oakley.c:405:oakley_compute_keymat_x(): KEYMAT compute with
2017-05-12 00:45:51 [DEBUG]: oakley.c:406:oakley_compute_keymat_x():
035cd631 519ebfa7 aac3cfc1 d383b28b 1c7d2f24 32852e74 aa6d81db fe34f90c
e7037f6a 55eea2c6 56
2017-05-12 00:45:51 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:45:51 [DEBUG]: algorithm.c:715:alg_ipsec_encdef(): encryption(aes)
2017-05-12 00:45:51 [DEBUG]: oakley.c:438:oakley_compute_keymat_x(): encklen=256 authklen=160
2017-05-12 00:45:51 [DEBUG]: oakley.c:445:oakley_compute_keymat_x(): generating 640 bits of key (dupkeymat=4)
2017-05-12 00:45:51 [DEBUG]: oakley.c:463:oakley_compute_keymat_x(): generating K1...K4 for KEYMAT.
2017-05-12 00:45:51 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:45:51 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:45:51 [DEBUG]: algorithm.c:515:alg_oakley_hmacdef(): hmac(hmac_sha1)
2017-05-12 00:45:51 [DEBUG]: oakley.c:524:oakley_compute_keymat_x():
825feeb2 a88877da d8c7223b 3e4b6b40 ac77fdd1 4d5fffae d5a04cf7 21a5ac04
2790f019 574088ff a570bc0f 6cd4c0c8 75d61784 6c981861 7d024f4e 1779b5df
7cb69b4b 6c7d91c4 2b14766a 15c7a8ef
2017-05-12 00:45:51 [DEBUG]: oakley.c:333:oakley_compute_keymat(): KEYMAT computed.
2017-05-12 00:45:51 [PROTO_NOTIFY]: ikev1.c:2593:log_ph2established(): ====> PHASE-2 NEGOTIATION SUCCEEDED AS RESPONDER, (QUICK MODE) <====
====> Established SA: 196.3.15.6[500]-5.32.40.145[500] message id:0xE94D529A, SPI:0xB82E6B5D/0x5CD63151 <====
2017-05-12 00:45:51 [DEBUG]: isakmp_quick.c:1823:quick_r3prep(): call pk_sendupdate
2017-05-12 00:45:51 [DEBUG]: algorithm.c:715:alg_ipsec_encdef(): encryption(aes)
2017-05-12 00:45:51 [INFO]: ike_pfkey.c:490:sadb_log_add(): SADB_UPDATE ul_proto=255 src=5.32.40.145[500] dst=196.3.15.6[500] satype=ESP samode=tunl spi=0xB82E6B5D authtype=SHA1 enctype=AES256 enclen=32 lifetime soft time=28800 bytes=4718592000 hard time=28800 bytes=4718592000
2017-05-12 00:45:51 [DEBUG]: isakmp_quick.c:1828:quick_r3prep(): pfkey update sent.
2017-05-12 00:45:51 [DEBUG]: algorithm.c:715:alg_ipsec_encdef(): encryption(aes)
2017-05-12 00:45:51 [INFO]: ike_pfkey.c:490:sadb_log_add(): SADB_ADD ul_proto=255 src=196.3.15.6[500] dst=5.32.40.145[500] satype=ESP samode=tunl spi=0x5CD63151 authtype=SHA1 enctype=AES256 enclen=32 lifetime soft time=25146 bytes=4718592000 hard time=28800 bytes=4718592000
2017-05-12 00:45:51 [DEBUG]: pfkey.c:1215:ikev1_update_response(): pfkey UPDATE succeeded: ESP/Tunnel 5.32.40.145[500]->196.3.15.6[500] spi=3090049885(0xb82e6b5d)
2017-05-12 00:45:51 [INFO]: pfkey.c:1220:ikev1_update_response(): IPsec-SA established: ESP/Tunnel 5.32.40.145[500]->196.3.15.6[500] spi=3090049885(0xb82e6b5d)
2017-05-12 00:45:51 [PROTO_NOTIFY]: ikev1.c:2642:log_ipseckeyinstalled(): ====> IPSEC KEY INSTALLATION SUCCEEDED <====
====> Installed SA: 196.3.15.6[500]-5.32.40.145[500] SPI:0xB82E6B5D/0x5CD63151 lifetime 28800 Sec lifesize 4608000 KB <====
2017-05-12 00:45:51.038 +0200 debug: ifmon_request_put(daemon/panike_sysd_if.c:1391): 16 write to pipe: keymirror_add
2017-05-12 00:45:51 [DEBUG]: isakmp_quick.c:1835:quick_r3prep(): pfkey add sent.
2017-05-12 00:45:51.039 +0200 debug: ifmon_request_get(daemon/panike_sysd_if.c:1407): 16 read from pipe, msg type 4
2017-05-12 00:45:51.039 +0200 debug: pan_msg_process(daemon/panike_sysd_if.c:1529): request from pipe: keymirror_add
2017-05-12 00:45:51 [INFO]: keymgr_keymirror.c:82:ike_do_keymirror_add(): keymirror add start ++++++++++++++++
2017-05-12 00:45:51.039 +0200 debug: keymgr_keydb_insert(ikemgr/keymgr_db.c:108): keymgr: key insert called for tid:1711276032
2017-05-12 00:45:51 [INFO]: keymgr_keymirror.c:86:ike_do_keymirror_add(): keymirror add for gw 0x45, tn 102, selfSPI B82E6B5D, retcode 0.
05-11-2017 05:09 PM
What if you apply commands below at ASA side to clear and resync SAs.
clear crypto isakmp
clear crypto sa
05-11-2017 05:25 PM
i have tried many times to clear SA's (Phase1/2) and re-initae the VPN's but the same error appreares again and again.
05-11-2017 10:55 PM
How does this behave? All traffic stops passing through that VPN? Does it recover eventually? Does it happen periodically?
Check time on both devices. And check SPIs for this tunnel on both sides when this error starts happening. Compare them if they match.
05-12-2017 02:40 AM
i'm seeing this log once the problem started
iph1->ivm == NULL
02-03-2021 06:39 PM
I'm also facing this issue. Was a solution found for this?
Click Accept as Solution to acknowledge that the answer to your question has been provided.
The button appears next to the replies on topics you’ve started. The member who gave the solution and all future visitors to this topic will appreciate it!
These simple actions take just seconds of your time, but go a long way in showing appreciation for community members and the LIVEcommunity as a whole!
The LIVEcommunity thanks you for your participation!
