Total nightmare with Hyper-V /OVH / pfSense - issues with ipsec on pfsense



  • Having major issues that is coming to a point of no return and I must get this resolved.  My tunnels are basic and I have very little traffic passing through the firewall at any given time as it is now.

    Having issues with ipsec vpn between:

    2.3 (Hyper-V) to 2.3 on supermicro quadcore limited bandwidth performance 1-2 mbit

    2.3 Hyper-V to APU with 2.2.6 1-1.5 mbit performance

    On Hyper-V server I get up/down 800mbit/800mbit and higher (Speed Test)

    On virtual machine running behind pfSense i get the same great performance of 800mbit/800mbit (Speed Test)

    Hyper-V server is a supermicro with:

    Windows 2012 R2
    Intel Xeon E5-1620 3.70GHz (Giving pfsense 2 vCPU)
    4GB Ram Allocated to pfSense

    NICS: 2 x Intel I350 Gigabit

    vswitch: LAN, WAN, CUST1, CUST2

    I am getting lots of these though:

    System:

    Jul 16 00:39:53 kernel calcru: runtime went backwards from 8791 usec to 4441 usec for pid 321 (devd)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 1889 usec to 966 usec for pid 321 (devd)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 159773 usec to 138215 usec for pid 320 (hv_kvp_daemon)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 263 usec to 133 usec for pid 308 (check_reload_status)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 263 usec to 133 usec for pid 308 (check_reload_status)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 5425 usec to 2775 usec for pid 306 (check_reload_status)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 4206 usec to 2775 usec for pid 306 (check_reload_status)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 13747 usec to 10115 usec for pid 268 (php-fpm)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 11915783 usec to 6314375 usec for pid 268 (php-fpm)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 32081 usec to 18294 usec for pid 51 (md0)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 28042 usec to 18294 usec for pid 51 (md0)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 3136 usec to 2962 usec for pid 19 (syncer)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 3799 usec to 2697 usec for pid 18 (bufdaemon)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 60 usec to 54 usec for pid 17 (idlepoll)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 1462 usec to 1069 usec for pid 8 (pagedaemon)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 18 usec to 9 usec for pid 7 (sctp_iterator)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 19 usec to 9 usec for pid 7 (sctp_iterator)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 4439 usec to 2314 usec for pid 5 (fdc0)

    Gateways:

    Jul 14 22:43:26 dpinger send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 167.114.xxx.xxx bind_addr 192.99.xxx.xxx identifier "WANGW "
    Jul 14 22:43:27 dpinger WANGW 167.114.xxx.xxx: Alarm latency 0us stddev 0us loss 100%
    Jul 14 22:43:36 dpinger WANGW 167.114.xxx.xxx: Clear latency 2014us stddev 1146us loss 6%
    Jul 15 03:08:30 dpinger send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 167.114.xxx.xxx bind_addr 192.99.xxx.xxx identifier "WANGW "
    Jul 15 03:08:33 dpinger WANGW 167.114.xxx.xxx: Alarm latency 1311us stddev 671us loss 50%
    Jul 15 03:08:42 dpinger WANGW 167.114.xxx.xxx: Clear latency 1482us stddev 853us loss 9%
    Jul 16 00:26:11 dpinger send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 167.114.xxx.xxx bind_addr 192.99.xxx.xxx identifier "WANGW "
    Jul 16 00:26:14 dpinger WANGW 167.114.xxx.xxx: Alarm latency 1377us stddev 593us loss 33%
    Jul 16 00:26:23 dpinger WANGW 167.114.xxx.xxx: Clear latency 1740us stddev 1100us loss 9%
    Jul 16 00:38:51 dpinger send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 167.114.xxx.xxx bind_addr 192.99.xxx.xxx identifier "WANGW "
    Jul 16 00:38:54 dpinger WANGW 167.114.xxx.xxx: Alarm latency 2321us stddev 996us loss 40%
    Jul 16 00:39:03 dpinger WANGW 167.114.xxx.xxx: Clear latency 1925us stddev 997us loss 9%

    ipsec

    Jul 16 00:54:19 charon 09[IKE] <con2|11>retransmit 1 of request with message ID 0
    Jul 16 00:54:19 charon 09[NET] <con2|11>sending packet: from 192.99.xxx.xxx[500] to 76.126.xxx.xxx[500] (336 bytes)
    Jul 16 00:54:25 charon 08[NET] <13> received packet: from 12.216.xxx.xxx[500] to 192.99.xxx.xxx[500] (328 bytes)
    Jul 16 00:54:25 charon 08[ENC] <13> parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) ]
    Jul 16 00:54:25 charon 08[IKE] <13> 12.216.xxx.xxx is initiating an IKE_SA
    Jul 16 00:54:25 charon 08[CFG] <13> received proposals: IKE:BLOWFISH_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 00:54:25 charon 08[CFG] <13> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 00:54:25 charon 08[IKE] <13> received proposals inacceptable
    Jul 16 00:54:25 charon 08[ENC] <13> generating IKE_SA_INIT response 0 [ N(NO_PROP) ]
    Jul 16 00:54:25 charon 08[NET] <13> sending packet: from 192.99.xxx.xxx[500] to 12.216.xxx.xxx[500] (36 bytes)
    Jul 16 00:54:26 charon 08[IKE] <con2|11>retransmit 2 of request with message ID 0
    Jul 16 00:54:26 charon 08[NET] <con2|11>sending packet: from 192.99.xxx.xxx[500] to 76.126.xxx.xxx[500] (336 bytes)
    Jul 16 00:54:37 charon 14[IKE] <con1|10>retransmit 4 of request with message ID 0
    Jul 16 00:54:37 charon 14[NET] <con1|10>sending packet: from 192.99.xxx.xxx[500] to 64.7.69.102[500] (336 bytes)
    Jul 16 00:54:39 charon 08[IKE] <con2|11>retransmit 3 of request with message ID 0
    Jul 16 00:54:39 charon 08[NET] <con2|11>sending packet: from 192.99.xxx.xxx[500] to 76.126.xxx.xxx[500] (336 bytes)
    Jul 16 00:55:02 charon 07[IKE] <con2|11>retransmit 4 of request with message ID 0
    Jul 16 00:55:02 charon 07[NET] <con2|11>sending packet: from 192.99.xxx.xxx[500] to 76.126.xxx.xxx[500] (336 bytes)
    Jul 16 00:55:19 charon 08[IKE] <con1|10>retransmit 5 of request with message ID 0
    Jul 16 00:55:19 charon 08[NET] <con1|10>sending packet: from 192.99.xxx.xxx[500] to 64.7.69.102[500] (336 bytes)
    Jul 16 00:55:44 charon 07[IKE] <con2|11>retransmit 5 of request with message ID 0
    Jul 16 00:55:44 charon 07[NET] <con2|11>sending packet: from 192.99.xxx.xxx[500] to 76.126.xxx.xxx[500] (336 bytes)
    Jul 16 00:56:35 charon 08[IKE] <con1|10>giving up after 5 retransmits
    Jul 16 00:56:35 charon 08[IKE] <con1|10>establishing IKE_SA failed, peer not responding
    Jul 16 00:57:00 charon 07[IKE] <con2|11>giving up after 5 retransmits
    Jul 16 00:57:00 charon 07[IKE] <con2|11>establishing IKE_SA failed, peer not responding
    Jul 16 00:58:50 charon 09[NET] <14> received packet: from 12.216.xxx.xxx[500] to 192.99.xxx.xxx[500] (328 bytes)
    Jul 16 00:58:50 charon 09[ENC] <14> parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) ]
    Jul 16 00:58:50 charon 09[IKE] <14> 12.216.xxx.xxx is initiating an IKE_SA
    Jul 16 00:58:50 charon 09[CFG] <14> received proposals: IKE:BLOWFISH_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 00:58:50 charon 09[CFG] <14> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 00:58:50 charon 09[IKE] <14> received proposals inacceptable
    Jul 16 00:58:50 charon 09[ENC] <14> generating IKE_SA_INIT response 0 [ N(NO_PROP) ]
    Jul 16 00:58:50 charon 09[NET] <14> sending packet: from 192.99.xxx.xxx[500] to 12.216.xxx.xxx[500] (36 bytes)
    Jul 16 01:03:15 charon 15[NET] <15> received packet: from 12.216.xxx.xxx[500] to 192.99.xxx.xxx[500] (328 bytes)
    Jul 16 01:03:15 charon 15[ENC] <15> parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) ]
    Jul 16 01:03:15 charon 15[IKE] <15> 12.216.xxx.xxx is initiating an IKE_SA
    Jul 16 01:03:15 charon 15[CFG] <15> received proposals: IKE:BLOWFISH_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 01:03:15 charon 15[CFG] <15> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 01:03:15 charon 15[IKE] <15> received proposals inacceptable
    Jul 16 01:03:15 charon 15[ENC] <15> generating IKE_SA_INIT response 0 [ N(NO_PROP) ]
    Jul 16 01:03:15 charon 15[NET] <15> sending packet: from 192.99.xxx.xxx[500] to 12.216.xxx.xxx[500] (36 bytes)
    Jul 16 01:07:40 charon 05[NET] <16> received packet: from 12.216.xxx.xxx[500] to 192.99.xxx.xxx[500] (328 bytes)
    Jul 16 01:07:40 charon 05[ENC] <16> parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) ]
    Jul 16 01:07:40 charon 05[IKE] <16> 12.216.xxx.xxx is initiating an IKE_SA
    Jul 16 01:07:40 charon 05[CFG] <16> received proposals: IKE:BLOWFISH_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 01:07:40 charon 05[CFG] <16> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 01:07:40 charon 05[IKE] <16> received proposals inacceptable
    Jul 16 01:07:40 charon 05[ENC] <16> generating IKE_SA_INIT response 0 [ N(NO_PROP) ]
    Jul 16 01:07:40 charon 05[NET] <16> sending packet: from 192.99.xxx.xxx[500] to 12.216.xxx.xxx[500] (36 bytes)</con2|11></con2|11></con1|10></con1|10></con2|11></con2|11></con1|10></con1|10></con2|11></con2|11></con2|11></con2|11></con1|10></con1|10></con2|11></con2|11></con2|11></con2|11>



  • @kapara:

    Jul 16 00:39:53 kernel calcru: runtime went backwards from 8791 usec to 4441 usec for pid 321 (devd)
    Jul 16 00:39:53 kernel calcru: runtime went backwards from 1889 usec to 966 usec for pid 321 (devd)

    Those are generally harmless, but there is a fix in 2.3.2 from Microsoft that makes it go away.

    @kapara:

    Jul 16 00:54:25 charon 08[CFG] <13> received proposals: IKE:BLOWFISH_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 00:54:25 charon 08[CFG] <13> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    Jul 16 00:54:25 charon 08[IKE] <13> received proposals inacceptable

    Right there - your config doesn't match. Blowfish on one side, 3DES on the other.