invalid HASH_V1 payload length, decryption failed after registering several P2's
-
I'm getting really strange issues with 2.4.4-p2 and IPSec tunnels. At first none of the tunnels with more than 1 P2 would come up.
Applying the fix from https://forum.netgate.com/topic/139536/phase-2-invalid-hash_v1-payload-length-error/10 fixed it somewhat but the behaviour varies a lot, I tried entering different values formax_ikey1_exchanges
and although the result is that at least 1 P2 is registered it does not do much to register all 4 consentintly.I'm seeing errors in the log file with regard to
invalid HASH_V1 payload length, decryption failed?.
Below is a log from when it fails after is already configured 3 P2's. (remote is redacted to 100.100.100.100 and local public is redacted to 200.200.200.200)
It configures 3 (out fo 4) P2's but then will suddenly throwinvalid HASH_V1 payload length, decryption failed?.
.However, and this is the strange part: clicking on Disconnect and Connect a few times I get each time a different number of registered P2's, sometimes it can even register all 4, sometimes 3 or sometimes just 1.
During the P1 lifetime all is well, traffic gets routed etc but when P1 reneg is up it's again pretty random how many P2's it can register.
Didn't have this problem with 2.4.3-p2 and it's really doing my head in...
Thanks for any help!
Jan 28 17:27:28 pfsense2 charon: 13[NET] <37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (108 bytes) Jan 28 17:27:28 pfsense2 charon: 13[ENC] <37> parsed ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ] Jan 28 17:27:28 pfsense2 charon: 13[CFG] <37> looking for pre-shared key peer configs matching 172.16.0.110...100.100.100.100[100.100.100.100] Jan 28 17:27:28 pfsense2 charon: 13[CFG] <37> candidate "con3000", match: 1/20/3100 (me/other/ike) Jan 28 17:27:28 pfsense2 charon: 13[CFG] <37> selected peer config "con3000" Jan 28 17:27:28 pfsense2 charon: 13[IKE] <con3000|37> IKE_SA con3000[37] established between 172.16.0.110[200.200.200.200]...100.100.100.100[100.100.100.100] Jan 28 17:27:28 pfsense2 charon: 13[IKE] <con3000|37> IKE_SA con3000[37] state change: CONNECTING => ESTABLISHED Jan 28 17:27:28 pfsense2 charon: 13[IKE] <con3000|37> scheduling reauthentication in 3584s Jan 28 17:27:28 pfsense2 charon: 13[IKE] <con3000|37> maximum IKE_SA lifetime 3594s Jan 28 17:27:28 pfsense2 charon: 13[ENC] <con3000|37> generating ID_PROT response 0 [ ID HASH ] Jan 28 17:27:28 pfsense2 charon: 13[NET] <con3000|37> sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] (92 bytes) Jan 28 17:27:28 pfsense2 charon: 04[NET] sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] waiting for data on sockets Jan 28 17:27:28 pfsense2 charon: 03[NET] received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] waiting for data on sockets Jan 28 17:27:28 pfsense2 charon: 03[NET] received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] waiting for data on sockets Jan 28 17:27:28 pfsense2 charon: 03[NET] received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] waiting for data on sockets Jan 28 17:27:28 pfsense2 charon: 13[NET] <con3000|37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (380 bytes) Jan 28 17:27:28 pfsense2 charon: 13[ENC] <con3000|37> parsed QUICK_MODE request 470394056 [ HASH SA No KE ID ID ] Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> looking for a child config for 172.17.2.0/24|/0 === 10.31.0.0/22|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> 10.132.121.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> 10.0.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> 10.11.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> 10.31.0.0/22|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> candidate "con3003" with prio 5+5 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> found matching child config "con3003" with prio 10 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> selecting traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> config: 10.31.0.0/22|/0, received: 10.31.0.0/22|/0 => match: 10.31.0.0/22|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> selecting traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> config: 172.17.2.0/24|/0, received: 172.17.2.0/24|/0 => match: 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> no acceptable INTEGRITY_ALGORITHM found Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> no acceptable INTEGRITY_ALGORITHM found Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> proposal matches Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> received proposals: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> configured proposals: ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP Jan 28 17:27:28 pfsense2 charon: 13[CFG] <con3000|37> selected proposal: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ Jan 28 17:27:28 pfsense2 charon: 13[LIB] <con3000|37> size of DH secret exponent: 1535 bits Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> got SPI cb786f0f Jan 28 17:27:28 pfsense2 charon: 13[ENC] <con3000|37> generating QUICK_MODE response 470394056 [ HASH SA No KE ID ID ] Jan 28 17:27:28 pfsense2 charon: 13[NET] <con3000|37> sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] (396 bytes) Jan 28 17:27:28 pfsense2 charon: 04[NET] sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] Jan 28 17:27:28 pfsense2 charon: 15[NET] <con3000|37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (380 bytes) Jan 28 17:27:28 pfsense2 charon: 15[ENC] <con3000|37> parsed QUICK_MODE request 1896057272 [ HASH SA No KE ID ID ] Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> looking for a child config for 172.17.2.0/24|/0 === 10.11.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> 10.132.121.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> 10.0.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> 10.11.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> candidate "con3002" with prio 5+5 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> 10.31.0.0/22|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> found matching child config "con3002" with prio 10 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> selecting traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> config: 10.11.0.0/21|/0, received: 10.11.0.0/21|/0 => match: 10.11.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> selecting traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> config: 172.17.2.0/24|/0, received: 172.17.2.0/24|/0 => match: 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> no acceptable INTEGRITY_ALGORITHM found Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> no acceptable INTEGRITY_ALGORITHM found Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> proposal matches Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> received proposals: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> configured proposals: ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP Jan 28 17:27:28 pfsense2 charon: 15[CFG] <con3000|37> selected proposal: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ Jan 28 17:27:28 pfsense2 charon: 15[LIB] <con3000|37> size of DH secret exponent: 1535 bits Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> got SPI c60728d1 Jan 28 17:27:28 pfsense2 charon: 15[ENC] <con3000|37> generating QUICK_MODE response 1896057272 [ HASH SA No KE ID ID ] Jan 28 17:27:28 pfsense2 charon: 15[NET] <con3000|37> sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] (396 bytes) Jan 28 17:27:28 pfsense2 charon: 03[NET] received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] waiting for data on sockets Jan 28 17:27:28 pfsense2 charon: 09[NET] <con3000|37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (380 bytes) Jan 28 17:27:28 pfsense2 charon: 09[ENC] <con3000|37> parsed QUICK_MODE request 3026735026 [ HASH SA No KE ID ID ] Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> looking for a child config for 172.17.2.0/24|/0 === 10.0.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> 10.132.121.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> 10.0.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> candidate "con3001" with prio 5+5 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> 10.11.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> 10.31.0.0/22|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> found matching child config "con3001" with prio 10 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> selecting traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> config: 10.0.0.0/21|/0, received: 10.0.0.0/21|/0 => match: 10.0.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> selecting traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> config: 172.17.2.0/24|/0, received: 172.17.2.0/24|/0 => match: 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> no acceptable INTEGRITY_ALGORITHM found Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> no acceptable INTEGRITY_ALGORITHM found Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> proposal matches Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> received proposals: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ Jan 28 17:27:28 pfsense2 charon: 04[NET] sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> configured proposals: ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP Jan 28 17:27:28 pfsense2 charon: 09[CFG] <con3000|37> selected proposal: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ Jan 28 17:27:28 pfsense2 charon: 09[LIB] <con3000|37> size of DH secret exponent: 1535 bits Jan 28 17:27:28 pfsense2 charon: 09[KNL] <con3000|37> got SPI cd991df4 Jan 28 17:27:28 pfsense2 charon: 09[ENC] <con3000|37> generating QUICK_MODE response 3026735026 [ HASH SA No KE ID ID ] Jan 28 17:27:28 pfsense2 charon: 09[NET] <con3000|37> sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] (396 bytes) Jan 28 17:27:28 pfsense2 charon: 04[NET] sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] waiting for data on sockets Jan 28 17:27:28 pfsense2 charon: 15[NET] <con3000|37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (76 bytes) Jan 28 17:27:28 pfsense2 charon: 15[ENC] <con3000|37> parsed QUICK_MODE request 470394056 [ HASH ] Jan 28 17:27:28 pfsense2 charon: 15[CHD] <con3000|37> CHILD_SA con3003{58} state change: CREATED => INSTALLING Jan 28 17:27:28 pfsense2 charon: 15[CHD] <con3000|37> using AES_CBC for encryption Jan 28 17:27:28 pfsense2 charon: 15[CHD] <con3000|37> using HMAC_SHA2_256_128 for integrity Jan 28 17:27:28 pfsense2 charon: 15[CHD] <con3000|37> adding inbound ESP SA Jan 28 17:27:28 pfsense2 charon: 15[CHD] <con3000|37> SPI 0xcb786f0f, src 100.100.100.100 dst 172.16.0.110 Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> deleting SAD entry with SPI cb786f0f Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> deleted SAD entry with SPI cb786f0f Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> adding SAD entry with SPI cb786f0f and reqid {22} Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> using encryption algorithm AES_CBC with key size 256 Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> using integrity algorithm HMAC_SHA2_256_128 with key size 256 Jan 28 17:27:28 pfsense2 charon: 15[CHD] <con3000|37> adding outbound ESP SA Jan 28 17:27:28 pfsense2 charon: 15[CHD] <con3000|37> SPI 0xac510665, src 172.16.0.110 dst 100.100.100.100 Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> adding SAD entry with SPI ac510665 and reqid {22} Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> using encryption algorithm AES_CBC with key size 256 Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> using integrity algorithm HMAC_SHA2_256_128 with key size 256 Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> adding policy 10.31.0.0/22|/0 === 172.17.2.0/24|/0 in Jan 28 17:27:28 pfsense2 charon: 15[KNL] <con3000|37> adding policy 172.17.2.0/24|/0 === 10.31.0.0/22|/0 out Jan 28 17:27:28 pfsense2 charon: 15[IKE] <con3000|37> CHILD_SA con3003{58} established with SPIs cb786f0f_i ac510665_o and TS 172.17.2.0/24|/0 === 10.31.0.0/22|/0 Jan 28 17:27:28 pfsense2 charon: 15[CHD] <con3000|37> CHILD_SA con3003{58} state change: INSTALLING => INSTALLED Jan 28 17:27:28 pfsense2 charon: 13[NET] <con3000|37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (76 bytes) Jan 28 17:27:28 pfsense2 charon: 13[ENC] <con3000|37> parsed QUICK_MODE request 1896057272 [ HASH ] Jan 28 17:27:28 pfsense2 charon: 13[CHD] <con3000|37> CHILD_SA con3002{59} state change: CREATED => INSTALLING Jan 28 17:27:28 pfsense2 charon: 13[CHD] <con3000|37> using AES_CBC for encryption Jan 28 17:27:28 pfsense2 charon: 13[CHD] <con3000|37> using HMAC_SHA2_256_128 for integrity Jan 28 17:27:28 pfsense2 charon: 13[CHD] <con3000|37> adding inbound ESP SA Jan 28 17:27:28 pfsense2 charon: 13[CHD] <con3000|37> SPI 0xc60728d1, src 100.100.100.100 dst 172.16.0.110 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> deleting SAD entry with SPI c60728d1 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> deleted SAD entry with SPI c60728d1 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> adding SAD entry with SPI c60728d1 and reqid {23} Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> using encryption algorithm AES_CBC with key size 256 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> using integrity algorithm HMAC_SHA2_256_128 with key size 256 Jan 28 17:27:28 pfsense2 charon: 13[CHD] <con3000|37> adding outbound ESP SA Jan 28 17:27:28 pfsense2 charon: 13[CHD] <con3000|37> SPI 0xac510668, src 172.16.0.110 dst 100.100.100.100 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> adding SAD entry with SPI ac510668 and reqid {23} Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> using encryption algorithm AES_CBC with key size 256 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> using integrity algorithm HMAC_SHA2_256_128 with key size 256 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> adding policy 10.11.0.0/21|/0 === 172.17.2.0/24|/0 in Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> adding policy 172.17.2.0/24|/0 === 10.11.0.0/21|/0 out Jan 28 17:27:28 pfsense2 charon: 13[IKE] <con3000|37> CHILD_SA con3002{59} established with SPIs c60728d1_i ac510668_o and TS 172.17.2.0/24|/0 === 10.11.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 13[CHD] <con3000|37> CHILD_SA con3002{59} state change: INSTALLING => INSTALLED Jan 28 17:27:28 pfsense2 charon: 05[NET] <con3000|37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (380 bytes) Jan 28 17:27:28 pfsense2 charon: 05[ENC] <con3000|37> parsed QUICK_MODE request 2633624910 [ HASH SA No KE ID ID ] Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> looking for a child config for 172.17.2.0/24|/0 === 10.132.121.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> 10.132.121.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> candidate "con3000" with prio 5+5 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> 10.0.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> 10.11.0.0/21|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposing traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposing traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> 10.31.0.0/22|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> found matching child config "con3000" with prio 10 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> selecting traffic selectors for other: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> config: 10.132.121.0/24|/0, received: 10.132.121.0/24|/0 => match: 10.132.121.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> selecting traffic selectors for us: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> config: 172.17.2.0/24|/0, received: 172.17.2.0/24|/0 => match: 172.17.2.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> no acceptable INTEGRITY_ALGORITHM found Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> no acceptable INTEGRITY_ALGORITHM found Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> selecting proposal: Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> proposal matches Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> received proposals: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> configured proposals: ESP:AES_CBC_256/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_MD5_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_384_192/MODP_1536/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_512_256/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP_1536/NO_EXT_SEQ, ESP:AES_GCM_16_128/MODP Jan 28 17:27:28 pfsense2 charon: 05[CFG] <con3000|37> selected proposal: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ Jan 28 17:27:28 pfsense2 charon: 05[LIB] <con3000|37> size of DH secret exponent: 1535 bits Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> got SPI c2f4d92e Jan 28 17:27:28 pfsense2 charon: 05[ENC] <con3000|37> generating QUICK_MODE response 2633624910 [ HASH SA No KE ID ID ] Jan 28 17:27:28 pfsense2 charon: 05[NET] <con3000|37> sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] (396 bytes) Jan 28 17:27:28 pfsense2 charon: 04[NET] sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] waiting for data on sockets Jan 28 17:27:28 pfsense2 charon: 05[NET] <con3000|37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (76 bytes) Jan 28 17:27:28 pfsense2 charon: 05[ENC] <con3000|37> invalid HASH_V1 payload length, decryption failed? Jan 28 17:27:28 pfsense2 charon: 05[ENC] <con3000|37> could not decrypt payloads Jan 28 17:27:28 pfsense2 charon: 05[IKE] <con3000|37> message parsing failed Jan 28 17:27:28 pfsense2 charon: 05[ENC] <con3000|37> generating INFORMATIONAL_V1 request 1428140749 [ HASH N(PLD_MAL) ] Jan 28 17:27:28 pfsense2 charon: 05[NET] <con3000|37> sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] (92 bytes) Jan 28 17:27:28 pfsense2 charon: 05[IKE] <con3000|37> QUICK_MODE request with message ID 3026735026 processing failed Jan 28 17:27:28 pfsense2 charon: 04[NET] sending packet: from 172.16.0.110[4500] to 100.100.100.100[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] Jan 28 17:27:28 pfsense2 charon: 03[NET] waiting for data on sockets Jan 28 17:27:28 pfsense2 charon: 05[NET] <con3000|37> received packet: from 100.100.100.100[4500] to 172.16.0.110[4500] (76 bytes) Jan 28 17:27:28 pfsense2 charon: 05[ENC] <con3000|37> parsed QUICK_MODE request 2633624910 [ HASH ] Jan 28 17:27:28 pfsense2 charon: 05[CHD] <con3000|37> CHILD_SA con3000{61} state change: CREATED => INSTALLING Jan 28 17:27:28 pfsense2 charon: 05[CHD] <con3000|37> using AES_CBC for encryption Jan 28 17:27:28 pfsense2 charon: 05[CHD] <con3000|37> using HMAC_SHA2_256_128 for integrity Jan 28 17:27:28 pfsense2 charon: 05[CHD] <con3000|37> adding inbound ESP SA Jan 28 17:27:28 pfsense2 charon: 05[CHD] <con3000|37> SPI 0xc2f4d92e, src 100.100.100.100 dst 172.16.0.110 Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> deleting SAD entry with SPI c2f4d92e Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> deleted SAD entry with SPI c2f4d92e Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> adding SAD entry with SPI c2f4d92e and reqid {24} Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> using encryption algorithm AES_CBC with key size 256 Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> using integrity algorithm HMAC_SHA2_256_128 with key size 256 Jan 28 17:27:28 pfsense2 charon: 05[CHD] <con3000|37> adding outbound ESP SA Jan 28 17:27:28 pfsense2 charon: 05[CHD] <con3000|37> SPI 0xac510666, src 172.16.0.110 dst 100.100.100.100 Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> adding SAD entry with SPI ac510666 and reqid {24} Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> using encryption algorithm AES_CBC with key size 256 Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> using integrity algorithm HMAC_SHA2_256_128 with key size 256 Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> adding policy 10.132.121.0/24|/0 === 172.17.2.0/24|/0 in Jan 28 17:27:28 pfsense2 charon: 05[KNL] <con3000|37> adding policy 172.17.2.0/24|/0 === 10.132.121.0/24|/0 out Jan 28 17:27:28 pfsense2 charon: 05[IKE] <con3000|37> CHILD_SA con3000{61} established with SPIs c2f4d92e_i ac510666_o and TS 172.17.2.0/24|/0 === 10.132.121.0/24|/0 Jan 28 17:27:28 pfsense2 charon: 05[CHD] <con3000|37> CHILD_SA con3000{61} state change: INSTALLING => INSTALLED Jan 28 17:27:28 pfsense2 charon: 09[CFG] vici client 279 connected Jan 28 17:27:28 pfsense2 charon: 05[CFG] vici client 279 registered for: list-sa Jan 28 17:27:28 pfsense2 charon: 13[CFG] vici client 279 requests: list-sas Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> querying SAD entry with SPI cb786f0f Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> querying SAD entry with SPI ac510665 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> querying SAD entry with SPI c60728d1 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> querying SAD entry with SPI ac510668 Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> querying SAD entry with SPI c2f4d92e Jan 28 17:27:28 pfsense2 charon: 13[KNL] <con3000|37> querying SAD entry with SPI ac510666
-
This is ipsec statusall output:
Status of IKE charon daemon (strongSwan 5.7.1, FreeBSD 11.2-RELEASE-p6, amd64): uptime: 45 minutes, since Jan 28 17:13:41 2019 worker threads: 11 of 16 idle, 5/0/0/0 working, job queue: 0/0/0/0, scheduled: 37 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: 172.16.0.110 Connections: con3000: 172.16.0.110...100.100.100.100 IKEv1, dpddelay=10s con3000: local: [200.200.200.200] uses pre-shared key authentication con3000: remote: [100.100.100.100] uses pre-shared key authentication con3000: child: 172.17.2.0/24|/0 === 10.132.121.0/24|/0 TUNNEL, dpdaction=clear con3001: child: 172.17.2.0/24|/0 === 10.0.0.0/21|/0 TUNNEL, dpdaction=clear con3002: child: 172.17.2.0/24|/0 === 10.11.0.0/21|/0 TUNNEL, dpdaction=clear con3003: child: 172.17.2.0/24|/0 === 10.31.0.0/22|/0 TUNNEL, dpdaction=clear Security Associations (1 up, 0 connecting): con3000[37]: ESTABLISHED 31 minutes ago, 172.16.0.110[200.200.200.200]...100.100.100.100[100.100.100.100] con3000[37]: IKEv1 SPIs: cb1564ac1f3158ca_i 9cfd2d0f9f0ce781_r*, pre-shared key reauthentication in 28 minutes con3000[37]: IKE proposal: AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_1536 con3000[37]: Tasks passive: QUICK_MODE con3003{58}: INSTALLED, TUNNEL, reqid 22, ESP in UDP SPIs: cb786f0f_i ac510665_o con3003{58}: AES_CBC_256/HMAC_SHA2_256_128/MODP_1536, 0 bytes_i (0 pkts, 1888s ago), 0 bytes_o (0 pkts, 1888s ago), rekeying in 28 minutes con3003{58}: 172.17.2.0/24|/0 === 10.31.0.0/22|/0 con3002{59}: INSTALLED, TUNNEL, reqid 23, ESP in UDP SPIs: c60728d1_i ac510668_o con3002{59}: AES_CBC_256/HMAC_SHA2_256_128/MODP_1536, 2016 bytes_i (24 pkts, 205s ago), 3744 bytes_o (24 pkts, 205s ago), rekeying in 28 minutes con3002{59}: 172.17.2.0/24|/0 === 10.11.0.0/21|/0 con3000{61}: INSTALLED, TUNNEL, reqid 24, ESP in UDP SPIs: c2f4d92e_i ac510666_o con3000{61}: AES_CBC_256/HMAC_SHA2_256_128/MODP_1536, 168 bytes_i (2 pkts, 1283s ago), 4056 bytes_o (26 pkts, 245s ago), rekeying in 28 minutes con3000{61}: 172.17.2.0/24|/0 === 10.132.121.0/24|/0
-
I click disconnect & reconnect a few times and with some luck out of 6 clicks it will register/enable the 4 P2's.