Phase 2 : "invalid HASH_V1 payload length" error



  • I have a really strange problem, establishing VPN tunnel between pfSense 2.3.2-RELEASE-p1 and Sophos SG (based on Astaro, uses Pluto as IKE daemon).
    I have 2 local networks (pfSense side) and 3 distant networks (Sophos side). If I configure two firewalls with such 6 phases 2 - the tunnel does not work. But if I leave just one configured network in Sophos configuration (for pfSense side) - the tunnel works correctly. It works for both present networks separately, but not in the same time. The networks are completely different (10.192.20.0/24 and 192.168.32.0/24).
    When the tunnel is down I can see in logs that Phase 1 and Phase 2 negotiations are successful for phase 1 and for all phases 2 present, BUT in pfSense logs I se the following errors:

    Jan 11 18:07:24 firewall charon: 11[NET] <con1000|6> received packet: from sss.sss.214.38[500] to sss.sss.188.161[500] (68 bytes)
    Jan 11 18:07:24 firewall charon: 11[ENC] <con1000|6> invalid HASH_V1 payload length, decryption failed?
    Jan 11 18:07:24 firewall charon: 11[ENC] <con1000|6> could not decrypt payloads
    Jan 11 18:07:24 firewall charon: 11[IKE] <con1000|6> message parsing failed
    Jan 11 18:07:24 firewall charon: 11[ENC] <con1000|6> generating INFORMATIONAL_V1 request 83928482 [ HASH N(PLD_MAL) ]
    Jan 11 18:07:24 firewall charon: 11[NET] <con1000|6> sending packet: from sss.sss.188.161[500] to sss.sss.214.38[500] (84 bytes)
    Jan 11 18:07:24 firewall charon: 11[IKE] <con1000|6> QUICK_MODE request with message ID 820365128 processing failed
    

    Evidently, Sophos does not know what to do with such packet and just drops PAYLOAD_MALFORMED. It continues to send packets (the tunnel is 'up'), but pfSense cannot decrypt them.
    Once again, if I use just ONE network (only Sophos configuration is changed!) on pfSense side - the tunnel works correctly, for both networks. So there is no problem with PSK, choosing proposals etc.
    Looks like a bug, but where? Pluto?
    Any ideas?



  • @peter2121 said in Phase 2 : "invalid HASH_V1 payload length" error:

    invalid HASH_V1 payload length

    It seems that we touched the issue explained here:
    https://wiki.strongswan.org/issues/1120
    So, we need to increase a number of simultaneous phase 2 negotiations in StrongSWan config:
    https://wiki.strongswan.org/issues/1128
    Is it possible on pfSense?
    PS
    I think to update the version to 2.4.4 this evening, so it would be interesting to see the instructions for both 2.3.2 and 2.4.4 versions.



  • @peter2121
    Hey
    I correctly understand that it is a question here about this setting ?
    Charon.max_ikev1_exchanges = 3
    Maximum number of IKEv1 phase 2 exchange for IKE_SA store state and
    he track at the same time.

    If so, you should do so
    Diagnostics/Edit File
    Open the file /etc/inc / vpn.inc
    Looking for here's a snippet
    0_1547570076831_c09778d1-59ab-49fc-80e5-c62674f683d4-image.png

    Make it so (Do not delete anything, add only one line)

    0_1547569738819_65815783-0426-4ec5-9d59-259fc9802e60-image.png

    Save file
    Continue
    VPN/IPSEC/IPSEC tunnels / Edit phase 1 entry / (Change nothing) / Save
    Apply changes
    Restart service
    and check



  • @peter2121 Wanted to know if my decision helped ?



  • @konstanti said in Phase 2 : "invalid HASH_V1 payload length" error:

    @peter2121 Wanted to know if my decision helped ?

    Thank you, I could change StrongSWan parameters using your advise.
    I still have problems with my tunnels though :(
    Probably, there are several problems, I've just eliminated the first one.



  • @konstanti Setting the key max_ikey1_exchanges = 6 fixed my problem with

    invalid HASH_V1 payload length, decryption failed?
    

    and consequently this error message:

    no matching CHILD_SA config found
    

    Will this change in /etc/inc/vpn.inc be retained after reboots and such?

    Thanks!



  • @cukal

    These changes will persist until the system is updated
    After you update the file vpn.inc will be overwritten
    And all the changes will have to be made again



  • @Konstanti Thanks for your reply.
    Is there a specific reason the number of max_ikey1_exchanges is 6?
    I'm seeing some issues with a public IP where multiple P1's (with P2's) are enabled but each time with different remote peers.
    Problem I'm having is a P1 with 5 P2's, that connection still logs invalid HASH_V1 payload length, decryption failed?

    Thanks!



  • @cukal
    The first post of this topic says that there are 6 phases 2. Therefore, I wrote that it is necessary to specify this number



  • @Konstanti Thanks for pointing that out to me ;)

    2.4.4-p2 is messing up IPSec tunnels for me.

    Using the max_ikey1_exchanges fixes it for a while but after a P1 renegotiation (set to 3600) the invalid HASH_V1 payload length, decryption failed? returns. When manually disconnecting the P1 it reconnects and a single P2 is created. Disconnecting a second time and all 3 P2's are again present.
    This config has been working for months on 2.4.3-p1.

    Where should I start looking?



  • I apologize for replying to this old topic, but I'm having the same issue I think. I'm on 2.4.4-p1. I have already bumped the max_ikev1_exchanges
    value to 50, but the errors keep happening, and the tunnel restarts every 2 minutes.
    @cukal Have you been able to find a solution for this?
    Thank you



  • Hey guys!
    I am also having this issue for about 3 weeks now. I just tried the max_ikey1_exchanges configuration and will monitor to see if it solves this problem.

    Another problem is that my IPSEC simply stops working (as per logs below) and I have to manually disconnect and connect for it to get back to normal.

    "Nov 18 10:53:32 srvfw02 charon: 11[ENC] <con5000|36> generating INFORMATIONAL_V1 request 662765406 [ HASH N(DPD_ACK) ]
    Nov 18 10:53:32 srvfw02 charon: 11[NET] <con5000|36> sending packet: from 187.32.1.97[4500] to 3.93.27.107[4500] (92 bytes)
    Nov 18 10:53:35 srvfw02 charon: 13[CFG] received stroke: terminate 'con5000[36]'
    Nov 18 10:53:35 srvfw02 charon: 05[IKE] <con5000|36> closing CHILD_SA con5001{1951} with SPIs c390bb8a_i (89106592 bytes) 5164593c_o (47764912 bytes) and TS 10.16.0.0/16|/0 === 172.31.0.0/16|/0
    Nov 18 10:53:35 srvfw02 charon: 05[IKE] <con5000|36> sending DELETE for ESP CHILD_SA with SPI c390bb8a
    Nov 18 10:53:35 srvfw02 charon: 05[ENC] <con5000|36> generating INFORMATIONAL_V1 request 2488498287 [ HASH D ]
    Nov 18 10:53:35 srvfw02 charon: 05[NET] <con5000|36> sending packet: from 187.32.1.97[4500] to 3.93.27.107[4500] (76 bytes)
    Nov 18 10:53:35 srvfw02 charon: 05[IKE] <con5000|36> closing CHILD_SA con5000{1952} with SPIs ce3c4bc6_i (21092379 bytes) fc4266f4_o (33628104 bytes) and TS 172.23.1.0/24|/0 === 172.31.0.0/16|/0
    Nov 18 10:53:35 srvfw02 charon: 05[IKE] <con5000|36> sending DELETE for ESP CHILD_SA with SPI ce3c4bc6
    Nov 18 10:53:35 srvfw02 charon: 05[ENC] <con5000|36> generating INFORMATIONAL_V1 request 2855744199 [ HASH D ]
    Nov 18 10:53:35 srvfw02 charon: 05[NET] <con5000|36> sending packet: from 187.32.1.97[4500] to 3.93.27.107[4500] (76 bytes)
    Nov 18 10:53:35 srvfw02 charon: 05[IKE] <con5000|36> closing CHILD_SA con5005{1953} with SPIs cf46097b_i (56835850 bytes) 0a395ec7_o (2706984 bytes) and TS 172.23.1.0/24|/0 === 172.32.0.0/16|/0
    Nov 18 10:53:35 srvfw02 charon: 05[IKE] <con5000|36> sending DELETE for ESP CHILD_SA with SPI cf46097b
    Nov 18 10:53:35 srvfw02 charon: 05[ENC] <con5000|36> generating INFORMATIONAL_V1 request 305020778 [ HASH D ]
    Nov 18 10:53:35 srvfw02 charon: 05[NET] <con5000|36> sending packet: from 187.32.1.97[4500] to 3.93.27.107[4500] (76 bytes)
    Nov 18 10:53:35 srvfw02 charon: 05[IKE] <con5000|36> closing CHILD_SA con5003{1954} with SPIs c8ddb24b_i (51622786 bytes) 66b80f1d_o (1483641528 bytes) and TS 10.0.0.0/16|/0 === 172.32.0.0/16|/0
    Nov 18 10:53:35 srvfw02 charon: 05[IKE] <con5000|36> sending DELETE for ESP CHILD_SA with SPI c8ddb24b"



  • @armandelli
    Hello
    Looks like you're showing the result of the command
    ipsec down con5000[36]



  • @Konstanti thanks for the reply!

    So it might be that those log lines refer to the moment I manually disconnected the ipsec.
    Next time the problem happens I will check the log messages before applying the manual disconnect/connect.

    Since the environment is in production and affecting many users, I have to restablish the service as soon as possible, not giving me much time to troubleshoot in real time.

    Thanks again!



  • @armandelli
    Ideally, you should show the phase 1 and phase 2 settings
    And the output of the command
    ipsec statusall

    and need logs of the second side of the connection



  • @Konstanti thanks for the reply!

    The logs from the other side I´ll see what I can do, as they are AWS VPC managed by a third party company.

    Regarding my pfsense box, here goes the output of ipsec statusall (with public IP information ommited):

    Status of IKE charon daemon (strongSwan 5.7.1, FreeBSD 11.2-RELEASE-p10, amd64):
    uptime: 9 days, since Nov 10 11:04:39 2019
    worker threads: 11 of 16 idle, 5/0/0/0 working, job queue: 0/0/0/0, scheduled: 7
    loaded plugins: charon unbound aes des blowfish rc2 sha2 sha1 md4 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey ipseckey pem openssl fips-prf curve25519 xcbc cmac hmac curl attr kernel-pfkey kernel-pfroute resolve socket-default stroke vici updown eap-identity eap-sim eap-md5 eap-mschapv2 eap-dynamic eap-radius eap-tls eap-ttls eap-peap xauth-generic xauth-eap whitelist addrblock counters
    Listening IP addresses:
    179.x.x.x
    179.x.x.x
    179.x.x.x
    179.x.x.x
    172.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    187.x.x.x
    172.23.1.254
    10.0.10.51
    10.0.10.1
    10.13.8.254
    192.168.10.1
    10.16.1.254
    10.16.3.254
    10.16.5.254
    10.16.7.254
    10.16.9.254
    192.168.3.1
    10.250.250.1
    172.16.10.253
    Connections:
    bypasslan: %any...%any IKEv1/2
    bypasslan: local: uses public key authentication
    bypasslan: remote: uses public key authentication
    bypasslan: child: 172.23.1.0/24|/0 === 172.23.1.0/24|/0 PASS
    con3000: 187.x.x.x...pa01.engesoftware.com.br IKEv1, dpddelay=10s
    con3000: local: [187.x.x.x] uses pre-shared key authentication
    con3000: remote: [201.x.x.x] uses pre-shared key authentication
    con3000: child: 10.0.0.0/16|/0 === 10.221.1.0/24|/0 TUNNEL, dpdaction=restart
    con3001: child: 10.16.4.0/23|/0 === 10.221.1.0/24|/0 TUNNEL, dpdaction=restart
    con3002: child: 10.15.1.0/24|/0 === 10.221.1.0/24|/0 TUNNEL, dpdaction=restart
    con4000: 187.x.x.x...pa02.engesoftware.com.br IKEv1, dpddelay=10s
    con4000: local: [187.x.x.x] uses pre-shared key authentication
    con4000: remote: [23.x.x.x] uses pre-shared key authentication
    con4000: child: 10.0.0.0/16|/0 === 10.222.1.0/24|/0 TUNNEL, dpdaction=restart
    con5000: 187.x.x.x...3.x.x.x IKEv1, dpddelay=10s
    con5000: local: [187.x.x.x] uses pre-shared key authentication
    con5000: remote: [3.x.x.x] uses pre-shared key authentication
    con5000: child: 172.23.1.0/24|/0 === 172.31.0.0/16|/0 TUNNEL, dpdaction=restart
    con5001: child: 10.16.0.0/16|/0 === 172.31.0.0/16|/0 TUNNEL, dpdaction=restart
    con5002: child: 10.0.0.0/16|/0 === 172.31.0.0/16|/0 TUNNEL, dpdaction=restart
    con5003: child: 10.0.0.0/16|/0 === 172.32.0.0/16|/0 TUNNEL, dpdaction=restart
    con5004: child: 10.16.0.0/16|/0 === 172.32.0.0/16|/0 TUNNEL, dpdaction=restart
    con5005: child: 172.23.1.0/24|/0 === 172.32.0.0/16|/0 TUNNEL, dpdaction=restart
    Shunted Connections:
    bypasslan: 172.23.1.0/24|/0 === 172.23.1.0/24|/0 PASS
    Routed Connections:
    con5005{2024}: ROUTED, TUNNEL, reqid 17
    con5005{2024}: 172.23.1.0/24|/0 === 172.32.0.0/16|/0
    con5004{2023}: ROUTED, TUNNEL, reqid 186
    con5004{2023}: 10.16.0.0/16|/0 === 172.32.0.0/16|/0
    con5003{2022}: ROUTED, TUNNEL, reqid 15
    con5003{2022}: 10.0.0.0/16|/0 === 172.32.0.0/16|/0
    con5002{2021}: ROUTED, TUNNEL, reqid 7
    con5002{2021}: 10.0.0.0/16|/0 === 172.31.0.0/16|/0
    con5001{2020}: ROUTED, TUNNEL, reqid 6
    con5001{2020}: 10.16.0.0/16|/0 === 172.31.0.0/16|/0
    con5000{2019}: ROUTED, TUNNEL, reqid 5
    con5000{2019}: 172.23.1.0/24|/0 === 172.31.0.0/16|/0
    con4000{2018}: ROUTED, TUNNEL, reqid 185
    con4000{2018}: 10.0.0.0/16|/0 === 10.222.1.0/24|/0
    con3002{2017}: ROUTED, TUNNEL, reqid 184
    con3002{2017}: 10.15.1.0/24|/0 === 10.221.1.0/24|/0
    con3001{2016}: ROUTED, TUNNEL, reqid 183
    con3001{2016}: 10.16.4.0/23|/0 === 10.221.1.0/24|/0
    con3000{2015}: ROUTED, TUNNEL, reqid 182
    con3000{2015}: 10.0.0.0/16|/0 === 10.221.1.0/24|/0
    Security Associations (1 up, 0 connecting):
    con5000[49]: ESTABLISHED 93 minutes ago, 187.x.x.x[187.x.x.x]...3.x.x.x[3.x.x.x]
    con5000[49]: IKEv1 SPIs: KEY-HERE, pre-shared key reauthentication in 6 hours
    con5000[49]: IKE proposal: AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
    con5000{2222}: REKEYED, TUNNEL, reqid 5, expires in 9 minutes
    con5000{2222}: 172.23.1.0/24|/0 === 172.31.0.0/16|/0
    con5001{2223}: REKEYED, TUNNEL, reqid 6, expires in 9 minutes
    con5001{2223}: 10.16.0.0/16|/0 === 172.31.0.0/16|/0
    con5003{2224}: REKEYED, TUNNEL, reqid 15, expires in 10 minutes
    con5003{2224}: 10.0.0.0/16|/0 === 172.32.0.0/16|/0
    con5002{2225}: REKEYED, TUNNEL, reqid 7, expires in 10 minutes
    con5002{2225}: 10.0.0.0/16|/0 === 172.31.0.0/16|/0
    con5005{2226}: REKEYED, TUNNEL, reqid 17, expires in 12 minutes
    con5005{2226}: 172.23.1.0/24|/0 === 172.32.0.0/16|/0
    con5004{2227}: INSTALLED, TUNNEL, reqid 186, ESP in UDP SPIs: c7b077d2_i c0a07721_o
    con5004{2227}: AES_CBC_128/HMAC_SHA1_96/MODP_1024, 440631522 bytes_i (1377274 pkts, 2012s ago), 4248 bytes_o (35 pkts, 140s ago), rekeying in 12 minutes
    con5004{2227}: 10.16.0.0/16|/0 === 172.32.0.0/16|/0
    con5001{2228}: INSTALLED, TUNNEL, reqid 6, ESP in UDP SPIs: c8454966_i d7de6570_o
    con5001{2228}: AES_CBC_128/HMAC_SHA1_96/MODP_1024, 24261301 bytes_i (54194 pkts, 5s ago), 0 bytes_o, rekeying in 35 minutes
    con5001{2228}: 10.16.0.0/16|/0 === 172.31.0.0/16|/0
    con5005{2229}: INSTALLED, TUNNEL, reqid 17, ESP in UDP SPIs: cf2e87d9_i c1b4b270_o
    con5005{2229}: AES_CBC_128/HMAC_SHA1_96/MODP_1024, 51835711 bytes_i (75994 pkts, 14s ago), 0 bytes_o, rekeying in 39 minutes
    con5005{2229}: 172.23.1.0/24|/0 === 172.32.0.0/16|/0
    con5000{2230}: INSTALLED, TUNNEL, reqid 5, ESP in UDP SPIs: c726e7a7_i a92840e7_o
    con5000{2230}: AES_CBC_128/HMAC_SHA1_96/MODP_1024, 32458073 bytes_i (102776 pkts, 6s ago), 0 bytes_o, rekeying in 39 minutes
    con5000{2230}: 172.23.1.0/24|/0 === 172.31.0.0/16|/0
    con5003{2231}: INSTALLED, TUNNEL, reqid 15, ESP in UDP SPIs: c195cada_i fbb87765_o
    con5003{2231}: AES_CBC_128/HMAC_SHA1_96/MODP_1024, 25662881 bytes_i (109438 pkts, 5s ago), 0 bytes_o, rekeying in 46 minutes
    con5003{2231}: 10.0.0.0/16|/0 === 172.32.0.0/16|/0
    con5002{2232}: INSTALLED, TUNNEL, reqid 7, ESP in UDP SPIs: cdca2ae8_i 0a0ec023_o
    con5002{2232}: AES_CBC_128/HMAC_SHA1_96/MODP_1024, 508394 bytes_i (6233 pkts, 0s ago), 0 bytes_o, rekeying in 45 minutes
    con5002{2232}: 10.0.0.0/16|/0 === 172.31.0.0/16|/0

    Regarding Phase 1 and 2 configuration, it´s a lot of stuff and maybe it will pollute the post. Could you specify which part or configuration item would be interesting to look at regarding the issue at hand?

    Thanks again my friend!

    Andre.



  • @armandelli said in Phase 2 : "invalid HASH_V1 payload length" error:

    Regarding Phase 1 and 2 configuration, it´s a lot of stuff and maybe it will pollute the post. Could you specify which part or configuration item would be interesting to look at regarding the issue at hand?
    Thanks again my friend!

    Hello
    This is quite enough to understand how everything is set up
    Now it is necessary to see logs at that moment when there is a failure .



  • @Konstanti follows attached part of the ipsec log.

    The loss of connection was reported at around 10:53 and almost immediately I applied the disconnect/connect workaround to restablish the service. Hope this helps. error-vpn-18Nov.txt

    I am currently monitoring the connection in order to retrieve more precise logs in real time.

    Tks a lot!



  • @gchialli said in Phase 2 : "invalid HASH_V1 payload length" error:

    I apologize for replying to this old topic, but I'm having the same issue I think. I'm on 2.4.4-p1. I have already bumped the max_ikev1_exchanges
    value to 50, but the errors keep happening, and the tunnel restarts every 2 minutes.
    @cukal Have you been able to find a solution for this?
    Thank you

    Hello,
    Just wanted to update the forum that my issue got resolved. It was caused by one proxy-id configured with the wrong prefix-length on the other side.
    Thanks


Log in to reply