IPsec to Cisco ASA - Intermittent Resets
-
I have a pfsense 2.3.4 connecting to a Cisco ASA. I have recently been experiencing an intermittent problem with our tunnel dropping the connection for a second then reconnecting. This happens anywhere from 4 - 12 hours apart, but with no pattern. I've verified that the settings match on both sides and that ASA's timeout feature was disabled. I am still at a loss. From analyzing the logs, all I can tell is that the ASA is sending a kill/delete signal to the CHILD_SA and there are a lot of "no matching CHILD_SA config found" entries in our pfsense log. I've recently enabled the recommended debugging log settings and will submit examples when the instance occurs again.
Another problem that has recently arose is the tunnel seems to "freeze". Meaning, that it is still connected, but no traffic seems to go through. I am seeing a lot of log entries similar to this:
2017-08-24 09:51:50,System0.Info,10.3.1.2,Aug 24 09:51:50 charon: 16[CFG] vici client 562 connected 2017-08-24 09:51:50,Daemon.Info,10.3.1.2,Aug 24 09:51:50 charon: 16[CFG] vici client 562 connected 2017-08-24 09:51:50,System0.Info,10.3.1.2,Aug 24 09:51:50 charon: 11[CFG] vici client 562 registered for: list-sa 2017-08-24 09:51:50,Daemon.Info,10.3.1.2,Aug 24 09:51:50 charon: 11[CFG] vici client 562 registered for: list-sa 2017-08-24 09:51:50,System0.Info,10.3.1.2,Aug 24 09:51:50 charon: 08[CFG] vici client 562 requests: list-sas 2017-08-24 09:51:50,Daemon.Info,10.3.1.2,Aug 24 09:51:50 charon: 08[CFG] vici client 562 requests: list-sas 2017-08-24 09:51:50,System0.Info,10.3.1.2,Aug 24 09:51:50 charon: 11[CFG] vici client 562 disconnected 2017-08-24 09:51:50,Daemon.Info,10.3.1.2,Aug 24 09:51:50 charon: 11[CFG] vici client 562 disconnected
If it helps, this is the error we are receiving from the ASA:
2017-08-24 04:59:46,Local4.Error,*.*.99.1,"Aug 24 2017 03:14:39: %ASA-3-713902: Group = *.*.*.254, IP = *.*.*.254, QM FSM error (P2 struct &0x761f2778, mess id 0x8e3d61d0)!" 2017-08-24 04:59:46,Local4.Debug,*.*.99.1,"Aug 24 2017 03:14:39: %ASA-7-715065: Group = *.*.*.254, IP = *.*.*.254, IKE QM Initiator FSM error history (struct &0x761f2778) <state>, <event>: QM_DONE, EV_ERROR-->QM_WAIT_MSG2, EV_TIMEOUT-->QM_WAIT_MSG2, NullEvent-->QM_SND_MSG1, EV_SND_MSG-->QM_SND_MSG1, EV_START_TMR-->QM_SND_MSG1, EV_RESEND_MSG-->QM_WAIT_MSG2, EV_TIMEOUT-->QM_WAIT_MSG2, NullEvent"</event></state>
-
Today we had another disruption preceded by a lot of these log entries:
2017-08-29 08:29:55,Daemon.Info,10.3.1.2,Aug 29 08:29:55 charon: 13[ENC] <con2000|5> generating INFORMATIONAL_V1 request 817940652 [ HASH N(INVAL_HASH) ] 2017-08-29 08:29:55,Daemon.Info,10.3.1.2,Aug 29 08:29:55 charon: 13[NET] <con2000|5> sending packet: from *.*.*.254[500] to *.*.*.66[500] (76 bytes) 2017-08-29 08:29:55,Daemon.Info,10.3.1.2,Aug 29 08:29:55 charon: 13[IKE] <con2000|5> QUICK_MODE request with message ID 1339927066 processing failed 2017-08-29 08:29:59,Daemon.Info,10.3.1.2,Aug 29 08:29:59 charon: 13[NET] <con2000|5> received packet: from *.*.*.66[500] to *.*.*.254[500] (172 bytes) 2017-08-29 08:29:59,Daemon.Info,10.3.1.2,"Aug 29 08:29:59 charon: 13[IKE] <con2000|5> received retransmit of request with ID 2091090257, but no response to retransmit" 2017-08-29 08:30:03,Daemon.Info,10.3.1.2,Aug 29 08:30:03 charon: 13[NET] <con2000|5> received packet: from *.*.*.66[500] to *.*.*.254[500] (172 bytes) 2017-08-29 08:30:03,Daemon.Info,10.3.1.2,Aug 29 08:30:03 charon: 13[ENC] <con2000|5> parsed QUICK_MODE request 1339927066 [ HASH SA No ID ID ] 2017-08-29 08:30:03,Daemon.Info,10.3.1.2,Aug 29 08:30:03 charon: 13[ENC] <con2000|5> received HASH payload does not match 2017-08-29 08:30:03,Daemon.Info,10.3.1.2,Aug 29 08:30:03 charon: 13[IKE] <con2000|5> integrity check failed</con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5>
Other log entries that looked suspicious are:
2017-08-29 08:40:39,Daemon.Info,10.3.1.2,Aug 29 08:40:39 charon: 14[ENC] <con2000|5> generating INFORMATIONAL_V1 request 3211985302 [ HASH N(PLD_MAL) ] 2017-08-29 08:40:39,Daemon.Info,10.3.1.2,Aug 29 08:40:39 charon: 14[NET] <con2000|5> sending packet: from *.*.*.254[500] to *.*.*.66[500] (76 bytes) 2017-08-29 08:40:39,Daemon.Info,10.3.1.2,Aug 29 08:40:39 charon: 14[IKE] <con2000|5> QUICK_MODE request with message ID 3438183006 processing failed 2017-08-29 08:40:47,Daemon.Info,10.3.1.2,Aug 29 08:40:47 charon: 10[NET] <con2000|5> received packet: from *.*.*.66[500] to *.*.*.254[500] (172 bytes) 2017-08-29 08:40:47,Daemon.Info,10.3.1.2,"Aug 29 08:40:47 charon: 10[ENC] <con2000|5> invalid HASH_V1 payload length, decryption failed?" 2017-08-29 08:40:47,Daemon.Info,10.3.1.2,Aug 29 08:40:47 charon: 10[ENC] <con2000|5> could not decrypt payloads 2017-08-29 08:40:47,Daemon.Info,10.3.1.2,Aug 29 08:40:47 charon: 10[IKE] <con2000|5> message parsing failed</con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5>
2017-08-29 08:43:06,Daemon.Info,10.3.1.2,Aug 29 08:43:06 charon: 05[ENC] <con2000|5> generating INFORMATIONAL_V1 request 1187213230 [ HASH N(INVAL_HASH) ] 2017-08-29 08:43:06,Daemon.Info,10.3.1.2,Aug 29 08:43:06 charon: 05[NET] <con2000|5> sending packet: from *.*.*.254[500] to *.*.*.66[500] (76 bytes) 2017-08-29 08:43:06,Daemon.Info,10.3.1.2,Aug 29 08:43:06 charon: 05[IKE] <con2000|5> QUICK_MODE request with message ID 879409864 processing failed 2017-08-29 08:43:07,Daemon.Info,10.3.1.2,Aug 29 08:43:07 charon: 05[NET] <con2000|5> received packet: from *.*.*.66[500] to *.*.*.254[500] (172 bytes) 2017-08-29 08:43:07,Daemon.Info,10.3.1.2,"Aug 29 08:43:07 charon: 05[IKE] <con2000|5> received retransmit of request with ID 2426813154, but no response to retransmit" 2017-08-29 08:43:14,Daemon.Info,10.3.1.2,Aug 29 08:43:14 charon: 05[NET] <con2000|5> received packet: from *.*.*.66[500] to *.*.*.254[500] (76 bytes) 2017-08-29 08:43:14,Daemon.Info,10.3.1.2,Aug 29 08:43:14 charon: 05[ENC] <con2000|5> parsed INFORMATIONAL_V1 request 3155446242 [ HASH D ] 2017-08-29 08:43:14,Daemon.Info,10.3.1.2,Aug 29 08:43:14 charon: 05[IKE] <con2000|5> received DELETE for ESP CHILD_SA with SPI a559aaa0 2017-08-29 08:43:14,Daemon.Info,10.3.1.2,"Aug 29 08:43:14 charon: 05[IKE] <con2000|5> CHILD_SA not found, ignored"</con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5></con2000|5>