IKEv2: ipsec SPI [...] not registered for [...]

Znevna · October 8, 2020, 10:33am

So.. everything worked fine for a few months on this RB4011, until today, when random clients decided to not work anymore, they connect to the server but can’t pass traffic.
What I can see relevant in the logs is in the topic title, but why is this happening, no ideea.
Running 6.46.6.
Help.
LE: upgraded to 6.46.7, same thing.

13:00:43 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:00:43 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 5bb4be18378b4174:f4cb98cc2c50073b 
13:00:43 ipsec SPI 3b07502ccc98cbf4 not registered for CLIENT.IP.ADDR[4500] 
13:00:43 ipsec,debug ===== received 528 bytes from CLIENT.IP.ADDR[500] to SERVER.IP.ADDR[500] 
13:00:43 ipsec -> ike2 request, exchange: SA_INIT:0 CLIENT.IP.ADDR[500] c3952d17a841f992:0000000000000000 
13:00:43 ipsec ike2 respond 
13:00:43 ipsec payload seen: SA (256 bytes) 
13:00:43 ipsec payload seen: KE (136 bytes) 
13:00:43 ipsec payload seen: NONCE (52 bytes) 
13:00:43 ipsec payload seen: NOTIFY (28 bytes) 
13:00:43 ipsec payload seen: NOTIFY (28 bytes) 
13:00:43 ipsec processing payload: NONCE 
13:00:43 ipsec processing payload: SA 
13:00:43 ipsec,debug unknown auth: #13 
13:00:43 ipsec,debug unknown prf: #6 
13:00:43 ipsec,debug unknown auth: #13 
13:00:43 ipsec,debug unknown prf: #6 
13:00:43 ipsec IKE Protocol: IKE 
13:00:43 ipsec  proposal #1 
13:00:43 ipsec   enc: 3des-cbc 
13:00:43 ipsec   prf: hmac-sha1 
13:00:43 ipsec   auth: sha1 
13:00:43 ipsec   dh: modp1024 
13:00:43 ipsec  proposal #2 
13:00:43 ipsec   enc: aes256-cbc 
13:00:43 ipsec   prf: hmac-sha1 
13:00:43 ipsec   auth: sha1 
13:00:43 ipsec   dh: modp1024 
13:00:43 ipsec  proposal #3 
13:00:43 ipsec   enc: 3des-cbc 
13:00:43 ipsec   prf: hmac-sha256 
13:00:43 ipsec   auth: sha256 
13:00:43 ipsec   dh: modp1024 
13:00:43 ipsec  proposal #4 
13:00:43 ipsec   enc: aes256-cbc 
13:00:43 ipsec   prf: hmac-sha256 
13:00:43 ipsec   auth: sha256 
13:00:43 ipsec   dh: modp1024 
13:00:43 ipsec  proposal #5 
13:00:43 ipsec   enc: 3des-cbc 
13:00:43 ipsec   prf: unknown 
13:00:43 ipsec   auth: unknown 
13:00:43 ipsec   dh: modp1024 
13:00:43 ipsec  proposal #6 
13:00:43 ipsec   enc: aes256-cbc 
13:00:43 ipsec   prf: unknown 
13:00:43 ipsec   auth: unknown 
13:00:43 ipsec   dh: modp1024 
13:00:43 ipsec matched proposal: 
13:00:43 ipsec  proposal #2 
13:00:43 ipsec   enc: aes256-cbc 
13:00:43 ipsec   prf: hmac-sha1 
13:00:43 ipsec   auth: sha1 
13:00:43 ipsec   dh: modp1024 
13:00:43 ipsec processing payload: KE 
13:00:43 ipsec,debug => shared secret (size 0x80) 
[...]
13:00:43 ipsec adding payload: SA 
13:00:43 ipsec,debug => (size 0x30) 
[...]
13:00:43 ipsec adding payload: KE 
13:00:43 ipsec,debug => (size 0x88) 
[...]
13:00:43 ipsec adding payload: NONCE 
13:00:43 ipsec,debug => (size 0x1c) 
13:00:43 ipsec,debug 0000001c 6c2b020c 1c12f76b 1fab52b8 17d3daa7 e5212847 4adf26f2 
13:00:43 ipsec adding notify: NAT_DETECTION_SOURCE_IP 
13:00:43 ipsec,debug => (size 0x1c) 
13:00:43 ipsec,debug 0000001c 00004004 8f2abe6d 34ca607e 519b96ec ec6d21f6 e7b16e85 
13:00:43 ipsec adding notify: NAT_DETECTION_DESTINATION_IP 
13:00:43 ipsec,debug => (size 0x1c) 
13:00:43 ipsec,debug 0000001c 00004005 5804205d dda7c687 a7d52d4d 9bd93df1 043f0166 
13:00:43 ipsec adding payload: CERTREQ 
13:00:43 ipsec,debug => (size 0x5) 
13:00:43 ipsec,debug 00000005 04 
13:00:43 ipsec <- ike2 reply, exchange: SA_INIT:0 CLIENT.IP.ADDR[500] c3952d17a841f992:7d2a8948979076ff 
13:00:43 ipsec,debug ===== sending 301 bytes from SERVER.IP.ADDR[500] to CLIENT.IP.ADDR[500] 
13:00:43 ipsec,debug 1 times of 301 bytes message will be sent to CLIENT.IP.ADDR[500] 
13:00:43 ipsec,debug => skeyseed (size 0x14) 
13:00:43 ipsec,debug 2d83dfec 051130a9 79ffa3cd 3e934aac 547798d6 
13:00:43 ipsec,debug => keymat (size 0x14) 
13:00:43 ipsec,debug 60acabf0 d677961a d7d511e9 939e6b21 47daeaba 
13:00:43 ipsec,debug => SK_ai (size 0x14) 
13:00:43 ipsec,debug 21df5f64 4d266c11 e80d8e90 658a1a8d 4063283a 
13:00:43 ipsec,debug => SK_ar (size 0x14) 
13:00:43 ipsec,debug f4fe5ede fffb3644 b8c3b207 d251306e f708a6ef 
13:00:43 ipsec,debug => SK_ei (size 0x20) 
13:00:43 ipsec,debug 2555c543 897f842c 5d06b335 8b4c6dbc de29cbd1 8124cbf5 7a813001 b07ccfca 
13:00:43 ipsec,debug => SK_er (size 0x20) 
13:00:43 ipsec,debug 7955ab71 89939ee0 7ab3cbed 482daf76 b23f0891 6bbec076 3254b0ca 1be2b410 
13:00:43 ipsec,debug => SK_pi (size 0x14) 
13:00:43 ipsec,debug ffcea3fe 4f3cf3af 3f569695 0a16356b 7c723564 
13:00:43 ipsec,debug => SK_pr (size 0x14) 
13:00:43 ipsec,debug 66fbef5a 7de8ac5f a71ebb66 9b79c902 2f1c3f9c 
13:00:43 ipsec,info new ike2 SA (R): SERVER.IP.ADDR[500]-CLIENT.IP.ADDR[500] spi:7d2a8948979076ff:c3952d17a841f992 
13:00:43 ipsec processing payloads: VID (none found) 
13:00:43 ipsec processing payloads: NOTIFY 
13:00:43 ipsec   notify: NAT_DETECTION_SOURCE_IP 
13:00:43 ipsec   notify: NAT_DETECTION_DESTINATION_IP 
13:00:43 ipsec (NAT-T) REMOTE  
13:00:43 ipsec KA list add: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] 
13:00:44 ipsec,debug ===== received 2684 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:00:44 ipsec -> ike2 request, exchange: AUTH:1 CLIENT.IP.ADDR[4500] c3952d17a841f992:7d2a8948979076ff 
13:00:44 ipsec payload seen: ENC (2656 bytes) 
13:00:44 ipsec processing payload: ENC 
13:00:44 ipsec,debug => iv (size 0x10) 
13:00:44 ipsec,debug 764011a9 3662bb4c 7fcdee9e 0f45b585 
13:00:44 ipsec,debug => plain payload (trimmed) (first 0x100 of 0xa30) 
[...]
13:00:44 ipsec,debug decrypted 
13:00:44 ipsec payload seen: ID_I (41 bytes) 
13:00:44 ipsec payload seen: CERT (938 bytes) 
13:00:44 ipsec payload seen: CERTREQ (1205 bytes) 
13:00:44 ipsec payload seen: AUTH (264 bytes) 
13:00:44 ipsec payload seen: NOTIFY (8 bytes) 
13:00:44 ipsec payload seen: CONFIG (24 bytes) 
13:00:44 ipsec payload seen: SA (80 bytes) 
13:00:44 ipsec payload seen: TS_I (24 bytes) 
13:00:44 ipsec payload seen: TS_R (24 bytes) 
13:00:44 ipsec processing payloads: NOTIFY 
13:00:44 ipsec   notify: MOBIKE_SUPPORTED 
13:00:44 ipsec ike auth: respond 
13:00:44 ipsec processing payload: ID_I 
13:00:44 ipsec ID_I (DER DN): nexus-pc.peco.frasin 
13:00:44 ipsec processing payload: ID_R (not found) 
13:00:44 ipsec processing payload: AUTH 
13:00:44 ipsec processing payload: CERT 
13:00:44 ipsec got CERT: client.cert
13:00:44 ipsec,debug => (size 0x3a5) 
[...]
13:00:44 ipsec,debug dc7a0bb1 8d 
13:00:44 ipsec processing payloads: NOTIFY 
13:00:44 ipsec   notify: MOBIKE_SUPPORTED 
13:00:44 ipsec processing payload: AUTH 
13:00:44 ipsec requested auth method: RSA 
13:00:44 ipsec,debug => peer's auth (size 0x100) 
[...]
13:00:44 ipsec,debug => auth nonce (size 0x18) 
13:00:44 ipsec,debug 6c2b020c 1c12f76b 1fab52b8 17d3daa7 e5212847 4adf26f2 
13:00:44 ipsec,debug => SK_p (size 0x14) 
13:00:44 ipsec,debug ffcea3fe 4f3cf3af 3f569695 0a16356b 7c723564 
13:00:44 ipsec,debug => idhash (size 0x14) 
13:00:44 ipsec,debug 8f73b268 c619c6b0 732ae8f6 04b60770 37eb2096 
13:00:44 ipsec,info,account peer authorized: SERVER.IP.ADDR[4500]-CLIENT.IP.ADDR[4500] spi:7d2a8948979076ff:c3952d17a841f992 
13:00:44 ipsec processing payloads: NOTIFY 
13:00:44 ipsec   notify: MOBIKE_SUPPORTED 
13:00:44 ipsec peer wants tunnel mode 
13:00:44 ipsec processing payload: CONFIG 
13:00:44 ipsec   attribute: internal IPv4 address 
13:00:44 ipsec   attribute: internal IPv4 DNS 
13:00:44 ipsec   attribute: internal IPv4 NBNS 
13:00:44 ipsec   attribute: MS internal IPv4 server 
13:00:44 ipsec processing payload: TS_I 
13:00:44 ipsec 0.0.0.0/0 
13:00:44 ipsec processing payload: TS_R 
13:00:44 ipsec 0.0.0.0/0 
13:00:44 ipsec TSi in tunnel mode replaced with config address: 172.28.248.0/24 
13:00:44 ipsec TSr in tunnel mode replaced with split subnet: 192.168.248.0/24 
13:00:44 ipsec canditate selectors: 192.168.248.0/24 <=> 172.28.248.14 
13:00:44 ipsec processing payload: SA 
13:00:44 ipsec IKE Protocol: ESP 
13:00:44 ipsec  proposal #1 
13:00:44 ipsec   enc: aes256-cbc 
13:00:44 ipsec   auth: sha1 
13:00:44 ipsec  proposal #2 
13:00:44 ipsec   enc: 3des-cbc 
13:00:44 ipsec   auth: sha1 
13:00:44 ipsec searching for policy for selector: 192.168.248.0/24 <=> 172.28.248.14 
13:00:44 ipsec generating policy 
13:00:44 ipsec matched proposal: 
13:00:44 ipsec  proposal #1 
13:00:44 ipsec   enc: aes256-cbc 
13:00:44 ipsec   auth: sha1 
13:00:44 ipsec ike auth: finish 
13:00:44 ipsec ID_R (FQDN): [...]
13:00:44 ipsec processing payload: NONCE 
13:00:44 ipsec,debug => auth nonce (size 0x30) 
13:00:44 ipsec,debug fd6802c7 266d4437 87b8e20f c16218ba 4489ac7b ee72c982 1077f15b cb727651 
13:00:44 ipsec,debug bd5eea39 6285c61d 1eea90ba c3646564 
13:00:44 ipsec,debug => SK_p (size 0x14) 
13:00:44 ipsec,debug 66fbef5a 7de8ac5f a71ebb66 9b79c902 2f1c3f9c 
13:00:44 ipsec,debug => idhash (size 0x14) 
13:00:44 ipsec,debug ff621f18 5f833c53 8ada4d5b 69675083 56328283 
13:00:44 ipsec,debug => my auth (size 0x100) 
[...]
13:00:44 ipsec cert: server.cert
13:00:44 ipsec adding payload: CERT 
13:00:44 ipsec,debug => (first 0x100 of 0x3d7) 
[...]
13:00:44 ipsec adding payload: ID_R 
13:00:44 ipsec,debug => (size 0x21) 
13:00:44 ipsec,debug 00000021 02000000 7a332e72 61646175 74692e65 75726f2d 7465686e 69632e72 
13:00:44 ipsec,debug 6f 
13:00:44 ipsec adding payload: AUTH 
13:00:44 ipsec,debug => (first 0x100 of 0x108) 
[...]
13:00:44 ipsec prepearing internal IPv4 address 
13:00:44 ipsec prepearing internal IPv4 netmask 
13:00:44 ipsec prepearing internal IPv6 subnet 
13:00:44 ipsec adding payload: CONFIG 
13:00:44 ipsec,debug => (size 0x24) 
13:00:44 ipsec,debug 00000024 02000000 00010004 ac1cf80e 00020004 ffffff00 000d0008 c0a8f800 
13:00:44 ipsec,debug ffffff00 
13:00:44 ipsec initiator selector: 172.28.248.14 
13:00:44 ipsec adding payload: TS_I 
13:00:44 ipsec,debug => (size 0x18) 
13:00:44 ipsec,debug 00000018 01000000 07000010 0000ffff ac1cf80e ac1cf80e 
13:00:44 ipsec responder selector: 192.168.248.0/24 
13:00:44 ipsec adding payload: TS_R 
13:00:44 ipsec,debug => (size 0x18) 
13:00:44 ipsec,debug 00000018 01000000 07000010 0000ffff c0a8f800 c0a8f8ff 
13:00:44 ipsec adding payload: SA 
13:00:44 ipsec,debug => (size 0x2c) 
13:00:44 ipsec,debug 0000002c 00000028 01030403 00ac8905 0300000c 0100000c 800e0100 03000008 
13:00:44 ipsec,debug 03000002 00000008 05000000 
13:00:44 ipsec <- ike2 reply, exchange: AUTH:1 CLIENT.IP.ADDR[4500] c3952d17a841f992:7d2a8948979076ff 
13:00:44 ipsec,debug ===== sending 1644 bytes from SERVER.IP.ADDR[4500] to CLIENT.IP.ADDR[4500] 
13:00:44 ipsec,debug 1 times of 1648 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:00:44 ipsec,debug => child keymat (size 0x78) 
[...]
13:00:44 ipsec IPsec-SA established: CLIENT.IP.ADDR[4500]->SERVER.IP.ADDR[4500] spi=0xac8905 
13:00:44 ipsec IPsec-SA established: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] spi=0x150d8501 
13:00:46 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:00:46 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549 
13:00:46 ipsec SPI 49f515ff90ae4ecf not registered for CLIENT.IP.ADDR[4500] 
13:00:48 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:00:48 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 760c35ec088aba1b:e17939f2e0d7a175 
13:00:48 ipsec SPI 75a1d7e0f23979e1 not registered for CLIENT.IP.ADDR[4500] 
13:00:50 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:00:50 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 55831bbbccd4d65d:62dcc1ea15a31c5a 
13:00:50 ipsec SPI 5a1ca315eac1dc62 not registered for CLIENT.IP.ADDR[4500] 
13:00:56 ipsec,debug KA: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] 
13:00:56 ipsec,debug 1 times of 1 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:01:02 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:02 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549 
13:01:02 ipsec SPI 49f515ff90ae4ecf not registered for CLIENT.IP.ADDR[4500] 
13:01:04 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:04 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 9e399247461797c5:cc3c5c259b8d473c 
13:01:04 ipsec SPI 3c478d9b255c3ccc not registered for CLIENT.IP.ADDR[4500] 
[..]
13:01:16 ipsec,debug KA: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] 
13:01:16 ipsec,debug 1 times of 1 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:01:16 ipsec sending dpd packet 
[...]
13:01:16 ipsec payload seen: ENC (112 bytes) 
13:01:16 ipsec processing payload: ENC 
13:01:16 ipsec,debug => iv (size 0x10) 
13:01:16 ipsec,debug 8ede295c 5ff527cb 65e6db1b 56a3cab0 
13:01:16 ipsec,debug => plain payload (trimmed) (size 0x0) 
13:01:16 ipsec,debug decrypted 
13:01:16 ipsec dpd collision 
[...]
13:01:16 ipsec payload seen: ENC (128 bytes) 
13:01:16 ipsec processing payload: ENC 
13:01:16 ipsec,debug => iv (size 0x10) 
13:01:16 ipsec,debug 85980c15 f9a47347 2e940f1c a7565d3a 
13:01:16 ipsec,debug => plain payload (trimmed) (size 0x0) 
13:01:16 ipsec,debug decrypted 
13:01:16 ipsec respond: info 
13:01:16 ipsec,debug reply ignored 
13:01:31 ipsec sending dpd packet 
[...]
13:01:31 ipsec payload seen: ENC (48 bytes) 
13:01:31 ipsec processing payload: ENC 
13:01:31 ipsec,debug => iv (size 0x10) 
13:01:31 ipsec,debug ed475be6 17a15b2c 7c5539ed c00a1bdf 
13:01:31 ipsec,debug => plain payload (trimmed) (size 0x0) 
13:01:31 ipsec,debug decrypted 
13:01:31 ipsec respond: info 
13:01:31 ipsec,debug reply ignored 
13:01:32 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:32 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549 
13:01:32 ipsec SPI 49f515ff90ae4ecf not registered for CLIENT.IP.ADDR[4500] 
13:01:34 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:34 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0 
13:01:34 ipsec SPI b0f0cbdf04f8afef not registered for CLIENT.IP.ADDR[4500] 
[...]
13:01:36 ipsec,debug KA: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] 
13:01:36 ipsec,debug 1 times of 1 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:01:36 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:36 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] e5c6c59620089051:43454680f3df61a7 
13:01:36 ipsec SPI a761dff380464543 not registered for CLIENT.IP.ADDR[4500] 
13:01:36 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:36 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0 
13:01:36 ipsec SPI b0f0cbdf04f8afef not registered for CLIENT.IP.ADDR[4500] 
13:01:39 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:39 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0 
13:01:39 ipsec SPI b0f0cbdf04f8afef not registered for CLIENT.IP.ADDR[4500] 
13:01:42 ipsec sending dpd packet 
[...]
13:01:42 ipsec payload seen: ENC (64 bytes) 
13:01:42 ipsec processing payload: ENC 
13:01:42 ipsec,debug => iv (size 0x10) 
13:01:42 ipsec,debug 6d5cc273 cd489c18 61671d08 263a34a4 
13:01:42 ipsec,debug => plain payload (trimmed) (size 0x0) 
13:01:42 ipsec,debug decrypted 
13:01:42 ipsec dpd collision 
[...]
13:01:42 ipsec payload seen: ENC (80 bytes) 
13:01:42 ipsec processing payload: ENC 
13:01:42 ipsec,debug => iv (size 0x10) 
13:01:42 ipsec,debug 02176aef 5b5faf8b 65517f7e d30863b8 
13:01:42 ipsec,debug => plain payload (trimmed) (size 0x0) 
13:01:42 ipsec,debug decrypted 
13:01:42 ipsec respond: info 
13:01:42 ipsec,debug reply ignored 
13:01:43 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:43 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0 
13:01:43 ipsec SPI b0f0cbdf04f8afef not registered for CLIENT.IP.ADDR[4500] 
13:01:49 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:49 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 760c35ec088aba1b:e17939f2e0d7a175 
13:01:49 ipsec SPI 75a1d7e0f23979e1 not registered for CLIENT.IP.ADDR[4500] 
13:01:51 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:51 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0 
13:01:51 ipsec SPI b0f0cbdf04f8afef not registered for CLIENT.IP.ADDR[4500] 
[...]
13:01:55 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:55 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 780eef68084c98b9:d9c0a584d36563f1 
13:01:55 ipsec SPI f16365d384a5c0d9 not registered for CLIENT.IP.ADDR[4500] 
[...]
13:01:56 ipsec,debug KA: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] 
13:01:56 ipsec,debug 1 times of 1 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:01:59 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:01:59 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 08858a865ae5bc63:3c6a23a54e03b5d5 
13:01:59 ipsec SPI d5b5034ea5236a3c not registered for CLIENT.IP.ADDR[4500] 
[...]
13:02:05 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:02:05 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] e54b551edb87afe2:80fbcbddb8f34ac2 
13:02:05 ipsec SPI c24af3b8ddcbfb80 not registered for CLIENT.IP.ADDR[4500] 
13:02:05 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:02:05 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 9e399247461797c5:cc3c5c259b8d473c 
13:02:05 ipsec SPI 3c478d9b255c3ccc not registered for CLIENT.IP.ADDR[4500] 
[...]
13:02:07 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:02:07 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0 
13:02:07 ipsec SPI b0f0cbdf04f8afef not registered for CLIENT.IP.ADDR[4500] 
[...]
13:02:16 ipsec,debug KA: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] 
13:02:16 ipsec,debug 1 times of 1 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:02:21 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:02:21 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] fc85ac080a4e5987:f191500a5846422d 
13:02:21 ipsec SPI 2d4246580a5091f1 not registered for CLIENT.IP.ADDR[4500] 
13:02:33 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:02:33 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549 
13:02:33 ipsec SPI 49f515ff90ae4ecf not registered for CLIENT.IP.ADDR[4500] 
[...]
13:02:36 ipsec,debug KA: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] 
13:02:36 ipsec,debug 1 times of 1 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:02:38 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:02:38 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0 
13:02:38 ipsec SPI b0f0cbdf04f8afef not registered for CLIENT.IP.ADDR[4500] 
13:02:43 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:02:43 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 5bb4be18378b4174:f4cb98cc2c50073b 
13:02:43 ipsec SPI 3b07502ccc98cbf4 not registered for CLIENT.IP.ADDR[4500] 
13:02:44 ipsec sending dpd packet 
13:02:44 ipsec <- ike2 request, exchange: INFORMATIONAL:0 CLIENT.IP.ADDR[4500] c3952d17a841f992:7d2a8948979076ff 
13:02:44 ipsec,debug ===== sending 156 bytes from SERVER.IP.ADDR[4500] to CLIENT.IP.ADDR[4500] 
13:02:44 ipsec,debug 1 times of 160 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:02:49 ipsec dpd: retransmit 
13:02:49 ipsec,debug ===== sending 156 bytes from SERVER.IP.ADDR[4500] to CLIENT.IP.ADDR[4500] 
13:02:49 ipsec,debug 1 times of 160 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:02:50 ipsec,debug ===== received 76 bytes from CLIENT.IP.ADDR[4500] to SERVER.IP.ADDR[4500] 
13:02:50 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 55831bbbccd4d65d:62dcc1ea15a31c5a 
13:02:50 ipsec SPI 5a1ca315eac1dc62 not registered for CLIENT.IP.ADDR[4500] 
13:02:54 ipsec dpd: retransmit 
13:02:54 ipsec,debug ===== sending 156 bytes from SERVER.IP.ADDR[4500] to CLIENT.IP.ADDR[4500] 
13:02:54 ipsec,debug 1 times of 160 bytes message will be sent to CLIENT.IP.ADDR[4500] 
[...]
13:02:56 ipsec,debug KA: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] 
13:02:56 ipsec,debug 1 times of 1 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:02:59 ipsec dpd: retransmit 
13:02:59 ipsec,debug ===== sending 156 bytes from SERVER.IP.ADDR[4500] to CLIENT.IP.ADDR[4500] 
13:02:59 ipsec,debug 1 times of 160 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:03:04 ipsec dpd: retransmit 
13:03:04 ipsec,debug ===== sending 156 bytes from SERVER.IP.ADDR[4500] to CLIENT.IP.ADDR[4500] 
13:03:04 ipsec,debug 1 times of 160 bytes message will be sent to CLIENT.IP.ADDR[4500] 
13:03:09 ipsec dpd: max retransmit failures reached 
13:03:09 ipsec,info killing ike2 SA: SERVER.IP.ADDR[4500]-CLIENT.IP.ADDR[4500] spi:7d2a8948979076ff:c3952d17a841f992 
13:03:09 ipsec IPsec-SA killing: CLIENT.IP.ADDR[4500]->SERVER.IP.ADDR[4500] spi=0xac8905 
13:03:09 ipsec IPsec-SA killing: SERVER.IP.ADDR[4500]->CLIENT.IP.ADDR[4500] spi=0x150d8501 
13:03:09 ipsec removing generated policy

Znevna · October 8, 2020, 7:08pm

During the day one more client failed to have a functional VPN.
Only Windows clients affected so far, since I mostly have Windows clients with a few exceptions it might be just a matter of time.
What can cause these? software? hardware going bad?
I can see the SAs getting installed after the clients connect but I see nothing in there that looks like the ones in the SPI error.
What am I missing? Is it looking for the wrong SPI? why? ..

sindy · October 8, 2020, 7:30pm

I’ve also seen other glitches in IPsec after some months of continuous operation on other RouterOS versions… sniff the traffic while the issue occurs, generate the supout.rif and send both to support. Then first just disable the peer and re-enable it, and if that doesn’t help, reboot the router.

Znevna · October 8, 2020, 7:45pm

I’ve rebooted, updated from 6.46.6 to 6.46.7, disabled/enabled the peer on the server, redone the affected client’s identities and mode-confs, nothing helped so far. Now I’m just waiting for calls to switch the nonfunctional ones to an alternate connection to the server until I sort this out.
I was thinking to swap the router and redo the current config on it but that doesn’t find the problem that might occur again in a few months.
I didn’t know what was happening at first, the first sign was that windows wasn’t getting the split-subnet sent to it, added it manually (since I’ve seen this fail before) still nothing, then I’ve set the logging rule to see what’s happening where I saw those SPI errors.
I’ll try gathering data for support tomorrow.
Thanks!

Znevna · October 9, 2020, 10:49am

Well, I can’t reproduce this. Yesterday I had 3 clients with this problem, today all 3 work fine.
Nothing usefull I can send to support.
I can’t see any other lines like that in the logs either.
How is that SPI hash computed? what could’ve caused ipsec to look for the wrong one for some clients? date? phase of moon? beats me.
I’ll set my bot to notify me if it ever sees something like this in the logs, like I’ve set it up to catch the sides changing for this: http://forum.mikrotik.com/t/ikev2-between-mikrotiks-sides-switching-initiator-responder/141848/14
Now I have to look for parsing logs examples. Back to work!
LE: I do have some logs from yesterday, I’ll send those in full (what I saved atleast.)
Overnight thought: could it also be caused by the hardware encryption/decription part of the chip?

Znevna · October 9, 2020, 12:11pm

So, I’ve had a closer look even in the logs above, notice this:

13:00:46 ipsec -> ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549
13:00:46 ipsec SPI 49f515ff90ae4ecf not registered for CLIENT.IP.ADDR[4500]

In the first line:
cf 4e ae 90 ff 15 f5 49
And the error: (reversed of the above, is it normal?)
49 f5 15 ff 90 ae 4e cf

sindy · October 9, 2020, 12:29pm

Of course it is not. But as you say that it only happens sometimes, the sniff is very important to find out where to complain - in Riga or in Redmond. So nothing to do but wait until it happens again. But it may also be that only the log message swaps the order, and in reality the difference is bigger (the cf 4e ae 90 ff 15 f5 49 is a completely other value than what was negotiated).

Znevna · October 9, 2020, 12:48pm

The logs above are hard to follow as I didn’t realize until after posting them that I had one working machine behind that IP and one not working. So parts with the same client.addr are ok and others not. LE: the one with port 1024 was working and the one with 4500 was not.
The other machine behind that IP stopped working later yesterday anyway.
Consistent in them is what I’ve caught above, the error line always contains the last part reversed of the informational exchange above it.
I did send a log to support, which also contains logs from another IP that has only one client behind it, and that one not working, easier to follow, noticed them about which one is it.
I wouldn’t blame Redmond yet, as all the other Win machines were fine.
And.. I’ve seen reversed stuff in ROS before…

sindy · October 9, 2020, 1:38pm

Yeah, me too, but what I strongly suspect is that the reverse printout is limited to the error message, not to the actual matching of the SPI to the list of known ones. So a minor issue, not the root cause.

What pulls my eyes to outside the Tik is that there are several such packets coming from the same remote IP, and several SPI tuples repeating through them, and some come at the same second:

13:00:43 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 5bb4be18378b4174:f4cb98cc2c50073b
13:00:46 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549
13:00:48 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 760c35ec088aba1b:e17939f2e0d7a175
13:00:50 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 55831bbbccd4d65d:62dcc1ea15a31c5a
13:01:02 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549
13:01:04 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 9e399247461797c5:cc3c5c259b8d473c
13:01:32 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549
13:01:34 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0
13:01:36 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] e5c6c59620089051:43454680f3df61a7
13:01:36 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0
13:01:39 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0
13:01:43 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0
13:01:49 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 760c35ec088aba1b:e17939f2e0d7a175
13:01:51 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0
13:01:55 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 780eef68084c98b9:d9c0a584d36563f1
13:01:59 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 08858a865ae5bc63:3c6a23a54e03b5d5
13:02:05 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] e54b551edb87afe2:80fbcbddb8f34ac2
13:02:05 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 9e399247461797c5:cc3c5c259b8d473c
13:02:07 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0
13:02:21 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] fc85ac080a4e5987:f191500a5846422d
13:02:33 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] b11fd45efa9bc4fa:cf4eae90ff15f549
13:02:38 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 156ac3e7a99519dc:efaff804dfcbf0b0
13:02:43 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 5bb4be18378b4174:f4cb98cc2c50073b
13:02:50 ipsec → ike2 request, exchange: INFORMATIONAL:2 CLIENT.IP.ADDR[4500] 55831bbbccd4d65d:62dcc1ea15a31c5a

I’m not sure whether the fact that they are INFORMATIONAL means that the SPI values are in the payload or whether Mikrotik parses the packet (to find out that it is an INFORMATIONAL or other one) before checking the match of the SPI pair.

If you permit logging of the packet contents, it is possible to use Wireshark to see the decrypted payload if you pre-process the RouterOS log accordingly.

But my assumption is some network overload, causing the Mikrotik’s responses to not reach the initiator, which thus tries multiple connections attempts and re-transmits packets belonging to the old ones. I cannot imagine how Mikrotik would be parsing the incoming traffic with same actual SPI tuples differently but systematically generate several repeating patterns.

Or a NAT/firewall on that site may have gone mad.