IPSEC unstable connection - 2.3.1_5



  • Hallo zusammen,

    ich habe 2 pfsense (Carp mit FW1=active / FW2=passive) mit der Version 2.3.1_5 Release. Diese stellen eine IPSEC Verbindung zu einer weiteren PFSense her mit Version 2.2.6.

    Nun habe ich das Problem das seit gestern die IPSEC Verbindung zwischendrin immer wieder nicht funktioniert. Ein Ping ergibt folgendes: erreichbar -> mittendrin Request Timeout -> dauert eine Zeit -> kurzzeitig wieder erreichbar -> Request Timeout.

    Das Problem bestand auch mit der Version 2.3.1_1 und nach dem Update auf Version 2.3.1_5 ebenfalls. Vorher gab es damit keine Probleme und alles lief seit Wochen stabil, auch mit der 2.3.1_1. Normaler Internetverkehr läuft ohne Probleme. Die FW1 und FW2 können beide ping zu google usw. problem erreichen. Es sind 2 Leitungen vorhanden WAN1 und WAN2. IPSEC läuft Standard über WAN1.

    Logs der FW-Extern:

    Jul 8 13:42:00 charon: 11[ENC] <con1|8>parsed INFORMATIONAL response 5 [ ]
    Jul 8 13:42:00 charon: 11[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:42:00 charon: 11[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (96 bytes)
    Jul 8 13:42:00 charon: 11[ENC] <con1|8>generating INFORMATIONAL request 5 [ ]
    Jul 8 13:42:00 charon: 11[IKE] <con1|8>sending DPD request
    Jul 8 13:41:45 charon: 15[KNL] <con1|8>unable to query SAD entry with SPI cae62a3e: No such file or directory (2)
    Jul 8 13:41:45 charon: 15[KNL] <con1|8>unable to query SAD entry with SPI ccc73f2f: No such file or directory (2)
    Jul 8 13:41:45 charon: 15[KNL] <con1|8>unable to query SAD entry with SPI c2445fda: No such file or directory (2)
    Jul 8 13:41:45 charon: 15[KNL] <con1|8>unable to query SAD entry with SPI c179da28: No such file or directory (2)
    Jul 8 13:41:40 charon: 12[ENC] <con1|8>parsed INFORMATIONAL response 4 [ ]
    Jul 8 13:41:40 charon: 12[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:41:40 charon: 12[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (96 bytes)
    Jul 8 13:41:40 charon: 12[ENC] <con1|8>generating INFORMATIONAL request 4 [ ]
    Jul 8 13:41:40 charon: 12[IKE] <con1|8>sending DPD request
    Jul 8 13:41:30 charon: 12[ENC] <con1|8>parsed INFORMATIONAL response 3 [ ]
    Jul 8 13:41:30 charon: 12[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:41:30 charon: 12[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (96 bytes)
    Jul 8 13:41:30 charon: 12[ENC] <con1|8>generating INFORMATIONAL request 3 [ ]
    Jul 8 13:41:30 charon: 12[IKE] <con1|8>sending DPD request
    Jul 8 13:41:20 charon: 09[ENC] <con1|8>parsed INFORMATIONAL response 2 [ ]
    Jul 8 13:41:20 charon: 09[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:41:20 charon: 09[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (96 bytes)
    Jul 8 13:41:20 charon: 09[ENC] <con1|8>generating INFORMATIONAL request 2 [ ]
    Jul 8 13:41:20 charon: 09[IKE] <con1|8>sending DPD request
    Jul 8 13:41:10 charon: 09[ENC] <con1|8>parsed INFORMATIONAL response 1 [ ]
    Jul 8 13:41:10 charon: 09[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:41:10 charon: 09[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (96 bytes)
    Jul 8 13:41:10 charon: 09[ENC] <con1|8>generating INFORMATIONAL request 1 [ ]
    Jul 8 13:41:10 charon: 09[IKE] <con1|8>sending DPD request
    Jul 8 13:41:00 charon: 09[ENC] <con1|8>parsed INFORMATIONAL response 0 [ ]
    Jul 8 13:41:00 charon: 09[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:41:00 charon: 09[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (96 bytes)
    Jul 8 13:41:00 charon: 09[ENC] <con1|8>generating INFORMATIONAL request 0 [ ]
    Jul 8 13:41:00 charon: 09[IKE] <con1|8>sending DPD request
    Jul 8 13:40:49 charon: 04[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (416 bytes)
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>generating CREATE_CHILD_SA response 5 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>CHILD_SA con1{17} established with SPIs c12b1cba_i c7cfcf12_o and TS 10.226.238.0/23|/0 === 10.10.10.0/24|/0 10.10.20.0/24|/0 10.10.110.0/24|/0 10.10.120.0/24|/0
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>parsed CREATE_CHILD_SA request 5 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Jul 8 13:40:49 charon: 04[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (416 bytes)
    Jul 8 13:40:49 charon: 04[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (416 bytes)
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>generating CREATE_CHILD_SA response 4 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>CHILD_SA con1{16} established with SPIs ce06a51d_i cae62a3e_o and TS 10.226.238.0/23|/0 === 10.10.10.0/24|/0 10.10.20.0/24|/0 10.10.110.0/24|/0 10.10.120.0/24|/0
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>parsed CREATE_CHILD_SA request 4 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Jul 8 13:40:49 charon: 04[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (416 bytes)
    Jul 8 13:40:49 charon: 04[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (416 bytes)
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>generating CREATE_CHILD_SA response 3 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>CHILD_SA con1{15} established with SPIs c2d4a728_i ccc73f2f_o and TS 10.226.238.0/23|/0 === 10.10.10.0/24|/0 10.10.20.0/24|/0 10.10.110.0/24|/0 10.10.120.0/24|/0
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>parsed CREATE_CHILD_SA request 3 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Jul 8 13:40:49 charon: 04[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (416 bytes)
    Jul 8 13:40:49 charon: 04[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (416 bytes)
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>generating CREATE_CHILD_SA response 2 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>CHILD_SA con1{14} established with SPIs c2c06d8b_i c2445fda_o and TS 10.226.238.0/23|/0 === 10.10.10.0/24|/0 10.10.20.0/24|/0 10.10.110.0/24|/0 10.10.120.0/24|/0
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>parsed CREATE_CHILD_SA request 2 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Jul 8 13:40:49 charon: 04[NET] <con1|8>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (416 bytes)
    Jul 8 13:40:49 charon: 04[NET] <con1|8>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (336 bytes)
    Jul 8 13:40:49 charon: 04[ENC] <con1|8>generating IKE_AUTH response 1 [ IDr AUTH N(ESP_TFC_PAD_N) SA TSi TSr N(AUTH_LFT) ]
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>CHILD_SA con1{13} established with SPIs c400d2d6_i c179da28_o and TS 10.226.238.0/23|/0 === 10.10.10.0/24|/0 10.10.20.0/24|/0 10.10.110.0/24|/0 10.10.120.0/24|/0
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>maximum IKE_SA lifetime 28335s
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>scheduling reauthentication in 27795s
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>IKE_SA con1[8] established between 46.182.150.187[46.182.150.187]…87.128.103.38[marpinion.de]
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>authentication of '46.182.150.187' (myself) with pre-shared key
    Jul 8 13:40:49 charon: 04[IKE] <con1|7>destroying duplicate IKE_SA for peer 'marpinion.de', received INITIAL_CONTACT
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
    Jul 8 13:40:49 charon: 04[IKE] <con1|8>authentication of 'marpinion.de' with pre-shared key successful
    Jul 8 13:40:49 charon: 04[CFG] <con1|8>selected peer config 'con1'
    Jul 8 13:40:49 charon: 04[CFG] <8> looking for peer configs matching 46.182.150.187[46.182.150.187]…87.128.103.38[marpinion.de]
    Jul 8 13:40:49 charon: 04[ENC] <8> parsed IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(ESP_TFC_PAD_N) SA TSi TSr N(MULT_AUTH) N(EAP_ONLY) ]
    Jul 8 13:40:49 charon: 04[NET] <8> received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (368 bytes)
    Jul 8 13:40:49 charon: 04[NET] <8> sending packet: from 46.182.150.187[500] to 87.128.103.38[500] (336 bytes)
    Jul 8 13:40:49 charon: 04[ENC] <8> generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(MULT_AUTH) ]
    Jul 8 13:40:49 charon: 04[IKE] <8> remote host is behind NAT
    Jul 8 13:40:49 charon: 04[IKE] <8> 87.128.103.38 is initiating an IKE_SA
    Jul 8 13:40:49 charon: 04[ENC] <8> parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
    Jul 8 13:40:49 charon: 04[NET] <8> received packet: from 87.128.103.38[500] to 46.182.150.187[500] (336 bytes)
    Jul 8 13:40:38 charon: 04[NET] <con1|7>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (96 bytes)</con1|7></con1|8></con1|8></con1|8></con1|7></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8></con1|8>

    Logs der FW1:

    Time Process PID Message
    Jul 8 13:34:31 charon 03[NET] <con2|2>sending packet: from 10.10.1.1[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:34:31 charon 03[IKE] <con2|2>retransmit 2 of request with message ID 5
    Jul 8 13:34:24 charon 03[NET] <con2|2>sending packet: from 10.10.1.1[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:34:24 charon 03[IKE] <con2|2>retransmit 1 of request with message ID 5
    Jul 8 13:34:23 charon 13[KNL] <con2|2>unable to query SAD entry with SPI c9da925d: No such file or directory (2)
    Jul 8 13:34:23 charon 13[KNL] <con2|2>unable to query SAD entry with SPI cba332b4: No such file or directory (2)
    Jul 8 13:34:23 charon 13[KNL] <con2|2>unable to query SAD entry with SPI cf56d157: No such file or directory (2)</con2|2></con2|2></con2|2>

    Jul 8 13:34:20 charon 12[NET] <con2|2>sending packet: from 10.10.1.1[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:34:20 charon 12[ENC] <con2|2>generating INFORMATIONAL request 5 [ ]
    Jul 8 13:34:20 charon 12[IKE] <con2|2>sending DPD request
    Jul 8 13:34:08 charon 12[NET] <con2|2>sending packet: from 10.10.1.1[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:34:08 charon 12[ENC] <con2|2>generating INFORMATIONAL response 16 [ ]
    Jul 8 13:34:08 charon 12[ENC] <con2|2>parsed INFORMATIONAL request 16 [ ]
    Jul 8 13:34:08 charon 12[NET] <con2|2>received packet: from 46.182.150.187[4500] to 10.10.1.1[4500] (96 bytes)
    Jul 8 13:33:58 charon 12[NET] <con2|2>sending packet: from 10.10.1.1[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:33:58 charon 12[ENC] <con2|2>generating INFORMATIONAL response 15 [ ]
    Jul 8 13:33:58 charon 12[ENC] <con2|2>parsed INFORMATIONAL request 15 [ ]
    Jul 8 13:33:58 charon 12[NET] <con2|2>received packet: from 46.182.150.187[4500] to 10.10.1.1[4500] (96 bytes)
    Jul 8 13:33:48 charon 12[NET] <con2|2>sending packet: from 10.10.1.1[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 13:33:48 charon 12[ENC] <con2|2>generating INFORMATIONAL response 14 [ ]</con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2></con2|2>

    Wisst ihr wo ich noch nachsehen könnte? Bisherige Suchen haben mir nichts gebracht.

    Lg



  • Nachdem ich nun die Modems geupdatet habe auf die aktuellste Firmware und überall mehrere Neutarts durchführt habe scheint die Verbindung stabiler zu laufen. Wie lange muss sich noch zeigen.

    Allerdings habe ich immer noch folgendes im Log der FW1 recht häufig:

    Jul 8 14:41:29 charon 04[ENC] <con2|1>parsed INFORMATIONAL request 73 [ ]
    Jul 8 14:41:29 charon 04[NET] <con2|1>received packet: from 46.182.150.187[4500] to 10.10.1.1[4500] (96 bytes)
    Jul 8 14:41:25 charon 16[KNL] <con2|1>unable to query SAD entry with SPI c64d75c7: No such file or directory (2)
    Jul 8 14:41:25 charon 16[KNL] <con2|1>unable to query SAD entry with SPI c89f5115: No such file or directory (2)
    Jul 8 14:41:19 charon 08[KNL] <con2|1>unable to query SAD entry with SPI c64d75c7: No such file or directory (2)
    Jul 8 14:41:19 charon 08[KNL] <con2|1>unable to query SAD entry with SPI c89f5115: No such file or directory (2)</con2|1></con2|1></con2|1></con2|1>

    Jul 8 14:41:19 charon 08[NET] <con2|1>sending packet: from 10.10.1.1[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 14:41:19 charon 08[ENC] <con2|1>generating INFORMATIONAL response 72 [ ]
    Jul 8 14:41:19 charon 08[ENC] <con2|1>parsed INFORMATIONAL request 72 [ ]
    Jul 8 14:41:19 charon 08[NET] <con2|1>received packet: from 46.182.150.187[4500] to 10.10.1.1[4500] (96 bytes)</con2|1></con2|1></con2|1></con2|1></con2|1></con2|1>

    Was ist das? Irgendwie finde ich dazu nicht wirklich etwas…

    EDIT:
    zwischendurch habe ich mal wieder 2-3 Request Timeout. Dann ist wieder alles ok. Zu der Zeit passiert in den Logs gar nichts bis auf:

    FW1:

    Time Process PID Message
    Jul 8 14:48:14 charon 08[NET] <con2|1>sending packet: from 10.10.1.1[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 14:48:14 charon 08[ENC] <con2|1>generating INFORMATIONAL response 113 [ ]
    Jul 8 14:48:14 charon 08[ENC] <con2|1>parsed INFORMATIONAL request 113 [ ]</con2|1></con2|1></con2|1>

    FW-Extern:

    Jul 8 14:48:23 charon: 05[ENC] <con1|88>parsed INFORMATIONAL response 114 [ ]
    Jul 8 14:48:23 charon: 05[NET] <con1|88>received packet: from 87.128.103.38[4500] to 46.182.150.187[4500] (96 bytes)
    Jul 8 14:48:23 charon: 11[NET] <con1|88>sending packet: from 46.182.150.187[4500] to 87.128.103.38[4500] (96 bytes)
    Jul 8 14:48:23 charon: 11[ENC] <con1|88>generating INFORMATIONAL request 114 [ ]
    Jul 8 14:48:23 charon: 11[IKE] <con1|88>sending DPD request
    Jul 8 14:48:13 charon: 11[ENC] <con1|88>parsed INFORMATIONAL response 113 [ ]</con1|88></con1|88></con1|88></con1|88></con1|88></con1|88>


Log in to reply