IPsec VPN tunnel to a Fritzbox after update to 2.4.4-p1



  • I hope I got the right passage:

    Dec 17 09:13:35 charon 04[IKE] <con1000|475> activating new tasks
    Dec 17 09:13:34 charon 04[IKE] <con1000|475> IKE_SA con1000[475] state change: CONNECTING => CREATED
    Dec 17 09:13:34 charon 04[IKE] <con1000|475> peer not responding, trying again (3/3)
    Dec 17 09:13:34 charon 04[IKE] <con1000|475> giving up after 5 retransmits
    Dec 17 09:12:29 charon 04[CFG] ignoring acquire, connection attempt pending
    Dec 17 09:12:29 charon 11[KNL] creating acquire job for policy 192.10.10.2/32|/0 === 86.118.66.38/32|/0 with reqid {5}
    Dec 17 09:12:19 charon 11[NET] <con1000|475> sending packet: from 192.10.10.2[500] to 86.118.66.38[500] (176 bytes)
    Dec 17 09:12:19 charon 11[IKE] <con1000|475> sending retransmit 5 of request message ID 0, seq 1
    Dec 17 09:11:37 charon 11[NET] <con1000|475> sending packet: from 192.10.10.2[500] to 86.118.66.38[500] (176 bytes)
    Dec 17 09:11:37 charon 11[IKE] <con1000|475> sending retransmit 4 of request message ID 0, seq 1
    Dec 17 09:11:14 charon 11[NET] <con1000|475> sending packet: from 192.10.10.22[500] to 86.118.66.388[500] (176 bytes)
    Dec 17 09:11:14 charon 11[IKE] <con1000|475> sending retransmit 3 of request message ID 0, seq 1
    Dec 17 09:11:01 charon 11[NET] <con1000|475> sending packet: from 192.10.10.2[500] to 886.118.66.38[500] (176 bytes)
    Dec 17 09:11:01 charon 11[IKE] <con1000|475> sending retransmit 2 of request message ID 0, seq 1
    Dec 17 09:10:53 charon 11[NET] <con1000|475> sending packet: from 192.10.10.2[500] to 86.118.66.38[500] (176 bytes)
    Dec 17 09:10:53 charon 11[IKE] <con1000|475> sending retransmit 1 of request message ID 0, seq 1
    Dec 17 09:10:49 charon 11[NET] <con1000|475> sending packet: from 192.10.10.2[500] to 86.118.66.388[500] (176 bytes)
    Dec 17 09:10:49 charon 11[ENC] <con1000|475> generating ID_PROT request 0 [ SA V V V V V ]
    Dec 17 09:10:49 charon 11[CFG] <con1000|475> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768
    Dec 17 09:10:49 charon 11[IKE] <con1000|475> IKE_SA con1000[475] state change: CREATED => CONNECTING
    Dec 17 09:10:49 charon 11[IKE] <con1000|475> initiating Main Mode IKE_SA con1000[475] to 86.118.66.38
    Dec 17 09:10:49 charon 11[IKE] <con1000|475> sending draft-ietf-ipsec-nat-t-ike-02\n vendor ID
    Dec 17 09:10:49 charon 11[IKE] <con1000|475> sending NAT-T (RFC 3947) vendor ID
    Dec 17 09:10:49 charon 11[IKE] <con1000|475> sending FRAGMENTATION vendor ID



  • @commwest Done. I hope it worked :-)


  • LAYER 8 Netgate

    OK so that is pfSense trying to reconnect and the other side is not responding.

    We'll need to see the point the tunnel is taken down. You can probably find the approximate time by searching for DESTROYED.



  • Dec 17 18:06:25 charon 07[NET] <con1000|549> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:06:25 charon 07[IKE] <con1000|549> sending retransmit 2 of request message ID 0, seq 1
    Dec 17 18:06:18 charon 07[NET] <con1000|549> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:06:18 charon 07[IKE] <con1000|549> sending retransmit 1 of request message ID 0, seq 1
    Dec 17 18:06:14 charon 07[NET] <con1000|549> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:06:14 charon 07[ENC] <con1000|549> generating ID_PROT request 0 [ SA V V V V V ]
    Dec 17 18:06:14 charon 07[CFG] <con1000|549> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> IKE_SA con1000[549] state change: CREATED => CONNECTING
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> initiating Main Mode IKE_SA con1000[549] to 82.117.73.44
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> sending draft-ietf-ipsec-nat-t-ike-02\n vendor ID
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> sending NAT-T (RFC 3947) vendor ID
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> sending FRAGMENTATION vendor ID
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> sending DPD vendor ID
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> sending XAuth vendor ID
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> activating ISAKMP_NATD task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> activating ISAKMP_CERT_POST task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> activating MAIN_MODE task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> activating ISAKMP_CERT_PRE task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> activating ISAKMP_VENDOR task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> activating new tasks
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> queueing QUICK_MODE task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> queueing ISAKMP_NATD task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> queueing ISAKMP_CERT_POST task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> queueing MAIN_MODE task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> queueing ISAKMP_CERT_PRE task
    Dec 17 18:06:14 charon 07[IKE] <con1000|549> queueing ISAKMP_VENDOR task
    Dec 17 18:06:14 charon 10[KNL] creating acquire job for policy 10.14.113.1/32|/0 === 82.117.73.44/32|/0 with reqid {5}
    Dec 17 18:05:39 charon 10[IKE] <con1000|548> IKE_SA con1000[548] state change: CONNECTING => DESTROYING
    Dec 17 18:05:39 charon 10[IKE] <con1000|548> establishing IKE_SA failed, peer not responding
    Dec 17 18:05:39 charon 10[IKE] <con1000|548> giving up after 5 retransmits
    Dec 17 18:04:24 charon 10[NET] <con1000|548> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:04:24 charon 10[IKE] <con1000|548> sending retransmit 5 of request message ID 0, seq 1
    Dec 17 18:03:42 charon 10[NET] <con1000|548> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:03:42 charon 10[IKE] <con1000|548> sending retransmit 4 of request message ID 0, seq 1
    Dec 17 18:03:18 charon 10[NET] <con1000|548> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:03:18 charon 10[IKE] <con1000|548> sending retransmit 3 of request message ID 0, seq 1
    Dec 17 18:03:05 charon 10[NET] <con1000|548> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:03:05 charon 10[IKE] <con1000|548> sending retransmit 2 of request message ID 0, seq 1
    Dec 17 18:02:58 charon 10[NET] <con1000|548> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:02:58 charon 10[IKE] <con1000|548> sending retransmit 1 of request message ID 0, seq 1
    Dec 17 18:02:54 charon 12[NET] <con1000|548> sending packet: from 10.14.113.1[500] to 82.117.73.44[500] (176 bytes)
    Dec 17 18:02:54 charon 12[ENC] <con1000|548> generating ID_PROT request 0 [ SA V V V V V ]
    Dec 17 18:02:54 charon 12[CFG] <con1000|548> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768
    Dec 17 18:02:54 charon 12[IKE] <con1000|548> IKE_SA con1000[548] state change: CREATED => CONNECTING
    Dec 17 18:02:54 charon 12[IKE] <con1000|548> initiating Main Mode IKE_SA con1000[548] to 82.117.73.44
    Dec 17 18:02:54 charon 12[IKE] <con1000|548> sending draft-ietf-ipsec-nat-t-ike-02\n vendor ID


  • LAYER 8 Netgate

    OK that catches the same thing so no good.

    See if searching for IKE_DELETE finds something more interesting.



  • If 'nothing found' is interesting... :(
    Any other guesses?


  • LAYER 8 Netgate

    Increase the logging retention for IPsec logs and/or search closer to when a disconnect happened.

    The logs will tell you who requested the delete and what happened. Without that it's a "who knows".



  • Sorry, but I'm at a loss here... changed log to raw and got some stuff, saying no acceptable encryption algorithm found.

    (ignore the obviously wrong ip addresses - they are only placeholders)

    Here we go:
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> no acceptable ENCRYPTION_ALGORITHM found
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> selecting proposal:
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> no acceptable ENCRYPTION_ALGORITHM found
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> selecting proposal:
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> no acceptable ENCRYPTION_ALGORITHM found
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> selecting proposal:
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> config: 192.12.13.1/0, received: 192.12.13.1/0 => match: 192.12.13.1/0
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> selecting traffic selectors for us:
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> config: 192.12.13.1/0, received: 192.12.13.1/0 => match: 192.12.13.1/0
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> selecting traffic selectors for other:
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> found matching child config "con1000" with prio 10
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> candidate "con1000" with prio 5+5
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> 192.12.13.1/0
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> proposing traffic selectors for other:
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> 192.12.13.1/0
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> proposing traffic selectors for us:
    Dec 17 23:36:53 charon: 11[CFG] <con1000|594> looking for a child config for 192.12.13.1/0 === 192.12.13.1/0
    Dec 17 23:36:53 charon: 11[ENC] <con1000|594> parsed QUICK_MODE request 673042099 [ HASH SA No KE ID ID ]
    Dec 17 23:36:53 charon: 11[NET] <con1000|594> received packet: from 82.110.36.24[4500] to 192.12.13.1[4500] (260 bytes)
    Dec 17 23:36:53 charon: 09[NET] <con1000|594> sending packet: from 192.12.13.1[4500] to 82.110.36.24[4500] (68 bytes)
    Dec 17 23:36:53 charon: 09[ENC] <con1000|594> generating ID_PROT response 0 [ ID HASH ]
    Dec 17 23:36:53 charon: 09[IKE] <con1000|594> IKE_SA con1000[594] state change: CONNECTING => ESTABLISHED
    Dec 17 23:36:53 charon: 09[IKE] <con1000|594> IKE_SA con1000[594] established between 192.12.13.1[192.12.13.1]...82.110.36.24[xyz.rubber.com]
    Dec 17 23:36:53 charon: 09[CFG] <594> selected peer config "con1000"
    Dec 17 23:36:53 charon: 09[CFG] <594> candidate "con1000", match: 1/20/3100 (me/other/ike)
    Dec 17 23:36:53 charon: 09[CFG] <594> candidate "bypasslan", match: 1/1/24 (me/other/ike)
    Dec 17 23:36:53 charon: 09[CFG] <594> looking for pre-shared key peer configs matching 192.12.13.1...82.110.36.24[xyz.rubber.com]
    Dec 17 23:36:53 charon: 09[ENC] <594> parsed ID_PROT request 0 [ ID HASH ]
    Dec 17 23:36:53 charon: 09[NET] <594> received packet: from 82.110.36.24[4500] to 192.12.13.1[4500] (84 bytes)
    Dec 17 23:36:53 charon: 09[NET] <594> sending packet: from 192.12.13.1[4500] to 82.110.36.24[4500] (212 bytes)
    Dec 17 23:36:53 charon: 09[ENC] <594> generating ID_PROT response 0 [ KE No NAT-D NAT-D ]
    Dec 17 23:36:53 charon: 09[CFG] <594> candidate "con1000", match: 1/1/3100 (me/other/ike)
    Dec 17 23:36:53 charon: 09[CFG] <594> candidate "bypasslan", match: 1/1/24 (me/other/ike)
    Dec 17 23:36:53 charon: 09[IKE] <594> remote host is behind NAT
    Dec 17 23:36:53 charon: 09[IKE] <594> local host is behind NAT, sending keep alives
    Dec 17 23:36:53 charon: 09[ENC] <594> parsed ID_PROT request 0 [ KE No NAT-D NAT-D ]
    Dec 17 23:36:53 charon: 09[NET] <594> received packet: from 82.110.36.24[4500] to 192.12.13.1[4500] (196 bytes)
    Dec 17 23:36:53 charon: 09[NET] <594> sending packet: from 192.12.13.1[4500] to 82.110.36.24[4500] (132 bytes)
    Dec 17 23:36:53 charon: 09[ENC] <594> generating ID_PROT response 0 [ SA V V V ]
    Dec 17 23:36:53 charon: 09[IKE] <594> sending NAT-T (RFC 3947) vendor ID
    Dec 17 23:36:53 charon: 09[IKE] <594> sending DPD vendor ID
    Dec 17 23:36:53 charon: 09[IKE] <594> sending XAuth vendor ID
    Dec 17 23:36:53 charon: 09[CFG] <594> selected proposal: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768
    Dec 17 23:36:53 charon: 09[CFG] <594> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768
    Dec 17 23:36:53 charon: 09[CFG] <594> received proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:AES_CBC_192/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:AES_CBC_256/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768, IKE:AES_CBC_192/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768, IKE:AES_CBC_128/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768, IKE:3DES_CBC/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768, IKE:DES_CBC/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768
    Dec 17 23:36:53 charon: 09[CFG] <594> proposal matches
    Dec 17 23:36:53 charon: 09[CFG] <594> selecting proposal:
    Dec 17 23:36:53 charon: 09[CFG] <594> no acceptable ENCRYPTION_ALGORITHM found
    Dec 17 23:36:53 charon: 09[CFG] <594> selecting proposal:
    Dec 17 23:36:53 charon: 09[CFG] <594> no acceptable ENCRYPTION_ALGORITHM found
    Dec 17 23:36:53 charon: 09[CFG] <594> selecting proposal:
    Dec 17 23:36:53 charon: 09[CFG] <594> no acceptable ENCRYPTION_ALGORITHM found
    Dec 17 23:36:53 charon: 09[CFG] <594> selecting proposal:
    Dec 17 23:36:53 charon: 09[IKE] <594> IKE_SA (unnamed)[594] state change: CREATED => CONNECTING
    Dec 17 23:36:53 charon: 09[IKE] <594> 82.110.36.24 is initiating a Main Mode IKE_SA
    Dec 17 23:36:53 charon: 09[ENC] <594> received unknown vendor ID: a2:22:6f:c3:64:50:0f:56:34:ff:77:db:3b:74:f4:1b
    Dec 17 23:36:53 charon: 09[IKE] <594> received draft-ietf-ipsec-nat-t-ike-03 vendor ID
    Dec 17 23:36:53 charon: 09[IKE] <594> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
    Dec 17 23:36:53 charon: 09[IKE] <594> received NAT-T (RFC 3947) vendor ID
    Dec 17 23:36:53 charon: 09[IKE] <594> received DPD vendor ID
    Dec 17 23:36:53 charon: 09[IKE] <594> received XAuth vendor ID
    Dec 17 23:36:53 charon: 09[CFG] <594> found matching ike config: 192.12.13.1...xyz.rubber.com with prio 3100
    Dec 17 23:36:53 charon: 09[CFG] <594> candidate: 192.12.13.1...xyz.rubber.com, prio 3100
    Dec 17 23:36:53 charon: 09[CFG] <594> candidate: %any...%any, prio 24
    Dec 17 23:36:53 charon: 09[CFG] <594> looking for an IKEv1 config for 192.12.13.1...82.110.36.24
    Dec 17 23:36:53 charon: 09[ENC] <594> parsed ID_PROT request 0 [ SA V V V V V V ]
    Dec 17 23:36:53 charon: 09[NET] <594> received packet: from 82.110.36.24[4500] to 192.12.13.1[4500] (496 bytes)
    Dec 17 23:36:47 charon: 09[NET] <con1000|593> sending packet: from 192.12.13.1[500] to 82.110.36.24[500] (176 bytes)
    Dec 17 23:36:47 charon: 09[IKE] <con1000|593> sending retransmit 5 of request message ID 0, seq 1
    Dec 17 23:36:05 charon: 10[NET] <con1000|593> sending packet: from 192.12.13.1[500] to 82.110.36.24[500] (176 bytes)
    Dec 17 23:36:05 charon: 10[IKE] <con1000|593> sending retransmit 4 of request message ID 0, seq 1
    Dec 17 23:35:42 charon: 10[NET] <con1000|593> sending packet: from 192.12.13.1[500] to 82.110.36.24[500] (176 bytes)
    Dec 17 23:35:42 charon: 10[IKE] <con1000|593> sending retransmit 3 of request message ID 0, seq 1

    Bought an apu-board for the "fritz-side" of the vpn connection. Better to take one variable (with poor encryption) out of the equitation and have the backups running...


  • LAYER 8 Netgate

    That looks like the fritzbox side is not allowing initiations from you to it, but it is working when that side initiates from them to you.

    The no acceptable encryption found is the other side working through its configured PFS groups. It matched at GROUP 1 (MODP_768) which is almost too weak to be useful any more:

    Dec 17 23:36:53 charon: 09[CFG] <594> selected proposal: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768
    Dec 17 23:36:53 charon: 09[CFG] <594> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768
    Dec 17 23:36:53 charon: 09[CFG] <594> received proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:AES_CBC_192/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_768, IKE:AES_CBC_256/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768, IKE:AES_CBC_192/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768, IKE:AES_CBC_128/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768, IKE:3DES_CBC/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768, IKE:DES_CBC/HMAC_MD5_96/PRF_HMAC_MD5/MODP_768
    

    Note that those logs are newest entries at the top, oldest at the bottom.

    So the logs at the bottom are your side trying to initiate and being ignored. Then you receive an initiation from them and it completes. Then it starts negotiating the Phase 2 and the logs cut off before getting to the establishment.



  • (MODP_768) which is almost too weak to be useful

    Entirely my opinion. That's why pfsense on both ends should be the best way and that is what I will do now.
    Thanks a lot anyway!



  • Here is also my log file. The disconnect happened about one minute after midnight.

    Dec 18 00:02:34 	charon 		12[CFG] vici client 2634 disconnected
    Dec 18 00:02:34 	charon 		05[CFG] vici client 2634 requests: list-sas
    Dec 18 00:02:34 	charon 		12[CFG] vici client 2634 registered for: list-sa
    Dec 18 00:02:34 	charon 		05[CFG] vici client 2634 connected
    Dec 18 00:02:21 	charon 		06[CFG] vici client 2633 disconnected
    Dec 18 00:02:21 	charon 		13[CFG] vici client 2633 requests: list-sas
    Dec 18 00:02:21 	charon 		13[CFG] vici client 2633 registered for: list-sa
    Dec 18 00:02:21 	charon 		06[CFG] vici client 2633 connected
    Dec 18 00:02:06 	charon 		16[CFG] vici client 2632 disconnected
    Dec 18 00:02:06 	charon 		06[CFG] vici client 2632 requests: list-sas
    Dec 18 00:02:06 	charon 		06[CFG] vici client 2632 registered for: list-sa
    Dec 18 00:02:06 	charon 		16[CFG] vici client 2632 connected
    Dec 18 00:01:51 	charon 		07[CFG] vici client 2631 disconnected
    Dec 18 00:01:51 	charon 		06[CFG] vici client 2631 requests: list-sas
    Dec 18 00:01:51 	charon 		07[CFG] vici client 2631 registered for: list-sa
    Dec 18 00:01:51 	charon 		06[CFG] vici client 2631 connected
    Dec 18 00:01:48 	charon 		09[CHD] <con3000|445> CHILD_SA con3000{418} state change: INSTALLED => DESTROYING
    Dec 18 00:01:48 	charon 		09[IKE] <con3000|445> IKE_SA con3000[445] state change: ESTABLISHED => DESTROYING
    Dec 18 00:01:48 	charon 		09[JOB] <con3000|445> DPD check timed out, enforcing DPD action
    Dec 18 00:01:38 	charon 		09[IKE] <con3000|445> nothing to initiate
    Dec 18 00:01:38 	charon 		09[IKE] <con3000|445> activating new tasks
    Dec 18 00:01:38 	charon 		09[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (92 bytes)
    Dec 18 00:01:38 	charon 		09[ENC] <con3000|445> generating INFORMATIONAL_V1 request 1223470614 [ HASH N(DPD) ]
    Dec 18 00:01:38 	charon 		09[IKE] <con3000|445> activating ISAKMP_DPD task
    Dec 18 00:01:38 	charon 		09[IKE] <con3000|445> activating new tasks
    Dec 18 00:01:38 	charon 		09[IKE] <con3000|445> queueing ISAKMP_DPD task
    Dec 18 00:01:38 	charon 		09[IKE] <con3000|445> sending DPD request
    Dec 18 00:01:36 	charon 		09[CFG] vici client 2630 disconnected
    Dec 18 00:01:36 	charon 		09[CFG] vici client 2630 requests: list-sas
    Dec 18 00:01:36 	charon 		09[CFG] vici client 2630 registered for: list-sa
    Dec 18 00:01:36 	charon 		08[CFG] vici client 2630 connected
    Dec 18 00:01:28 	charon 		08[IKE] <con3000|445> nothing to initiate
    Dec 18 00:01:28 	charon 		08[IKE] <con3000|445> activating new tasks
    Dec 18 00:01:28 	charon 		08[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (92 bytes)
    Dec 18 00:01:28 	charon 		08[ENC] <con3000|445> generating INFORMATIONAL_V1 request 320752580 [ HASH N(DPD) ]
    Dec 18 00:01:28 	charon 		08[IKE] <con3000|445> activating ISAKMP_DPD task
    Dec 18 00:01:28 	charon 		08[IKE] <con3000|445> activating new tasks
    Dec 18 00:01:28 	charon 		08[IKE] <con3000|445> queueing ISAKMP_DPD task
    Dec 18 00:01:28 	charon 		08[IKE] <con3000|445> sending DPD request
    Dec 18 00:01:23 	charon 		11[CFG] vici client 2629 disconnected
    Dec 18 00:01:23 	charon 		11[CFG] vici client 2629 requests: list-sas
    Dec 18 00:01:23 	charon 		08[CFG] vici client 2629 registered for: list-sa
    Dec 18 00:01:23 	charon 		14[CFG] vici client 2629 connected
    Dec 18 00:01:18 	charon 		14[IKE] <con3000|445> nothing to initiate
    Dec 18 00:01:18 	charon 		14[IKE] <con3000|445> activating new tasks
    Dec 18 00:01:18 	charon 		14[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (92 bytes)
    Dec 18 00:01:18 	charon 		14[ENC] <con3000|445> generating INFORMATIONAL_V1 request 2927126343 [ HASH N(DPD) ]
    Dec 18 00:01:18 	charon 		14[IKE] <con3000|445> activating ISAKMP_DPD task
    Dec 18 00:01:18 	charon 		14[IKE] <con3000|445> activating new tasks
    Dec 18 00:01:18 	charon 		14[IKE] <con3000|445> queueing ISAKMP_DPD task
    Dec 18 00:01:18 	charon 		14[IKE] <con3000|445> sending DPD request
    Dec 18 00:01:08 	charon 		05[IKE] <con3000|445> nothing to initiate
    Dec 18 00:01:08 	charon 		05[IKE] <con3000|445> activating new tasks
    Dec 18 00:01:08 	charon 		05[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (92 bytes)
    Dec 18 00:01:08 	charon 		05[ENC] <con3000|445> generating INFORMATIONAL_V1 request 2708381718 [ HASH N(DPD) ]
    Dec 18 00:01:08 	charon 		05[IKE] <con3000|445> activating ISAKMP_DPD task
    Dec 18 00:01:08 	charon 		05[IKE] <con3000|445> activating new tasks
    Dec 18 00:01:08 	charon 		05[IKE] <con3000|445> queueing ISAKMP_DPD task
    Dec 18 00:01:08 	charon 		05[IKE] <con3000|445> sending DPD request
    Dec 18 00:00:58 	charon 		05[IKE] <con3000|445> nothing to initiate
    Dec 18 00:00:58 	charon 		05[IKE] <con3000|445> activating new tasks
    Dec 18 00:00:58 	charon 		05[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (92 bytes)
    Dec 18 00:00:58 	charon 		05[ENC] <con3000|445> generating INFORMATIONAL_V1 request 180128396 [ HASH N(DPD) ]
    Dec 18 00:00:58 	charon 		05[IKE] <con3000|445> activating ISAKMP_DPD task
    Dec 18 00:00:58 	charon 		05[IKE] <con3000|445> activating new tasks
    Dec 18 00:00:58 	charon 		05[IKE] <con3000|445> queueing ISAKMP_DPD task
    Dec 18 00:00:58 	charon 		05[IKE] <con3000|445> sending DPD request
    Dec 18 00:00:42 	charon 		05[KNL] 10.10.10.1 appeared on em1
    Dec 18 00:00:42 	charon 		05[KNL] 10.10.10.1 disappeared from em1
    Dec 18 00:00:10 	charon 		16[CFG] vici client 2628 disconnected
    Dec 18 00:00:10 	charon 		15[CFG] vici client 2628 requests: list-sas
    Dec 18 00:00:10 	charon 		16[CFG] vici client 2628 registered for: list-sa
    Dec 18 00:00:10 	charon 		16[CFG] vici client 2628 connected
    Dec 18 00:00:00 	charon 		07[CFG] vici client 2627 disconnected
    Dec 18 00:00:00 	charon 		07[CFG] vici client 2627 requests: list-sas
    Dec 18 00:00:00 	charon 		09[CFG] vici client 2627 registered for: list-sa
    Dec 18 00:00:00 	charon 		09[CFG] vici client 2627 connected
    Dec 17 23:59:50 	charon 		06[CFG] vici client 2626 disconnected
    Dec 17 23:59:50 	charon 		09[CFG] vici client 2626 requests: list-sas
    Dec 17 23:59:50 	charon 		09[CFG] vici client 2626 registered for: list-sa
    Dec 17 23:59:50 	charon 		06[CFG] vici client 2626 connected
    Dec 17 23:59:44 	charon 		08[IKE] <con3000|445> nothing to initiate
    Dec 17 23:59:44 	charon 		08[IKE] <con3000|445> activating new tasks
    Dec 17 23:59:44 	charon 		08[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (92 bytes)
    Dec 17 23:59:44 	charon 		08[ENC] <con3000|445> generating INFORMATIONAL_V1 request 3418999340 [ HASH N(DPD) ]
    Dec 17 23:59:44 	charon 		08[IKE] <con3000|445> activating ISAKMP_DPD task
    Dec 17 23:59:44 	charon 		08[IKE] <con3000|445> activating new tasks
    Dec 17 23:59:44 	charon 		08[IKE] <con3000|445> queueing ISAKMP_DPD task
    Dec 17 23:59:44 	charon 		08[IKE] <con3000|445> sending DPD request
    Dec 17 23:59:40 	charon 		08[CFG] vici client 2625 disconnected
    Dec 17 23:59:40 	charon 		08[CFG] vici client 2625 requests: list-sas
    Dec 17 23:59:40 	charon 		11[CFG] vici client 2625 registered for: list-sa
    Dec 17 23:59:40 	charon 		08[CFG] vici client 2625 connected
    Dec 17 23:59:34 	charon 		12[IKE] <con3000|445> nothing to initiate
    Dec 17 23:59:34 	charon 		12[IKE] <con3000|445> activating new tasks
    Dec 17 23:59:34 	charon 		12[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (92 bytes)
    Dec 17 23:59:34 	charon 		12[ENC] <con3000|445> generating INFORMATIONAL_V1 request 1748552581 [ HASH N(DPD) ]
    Dec 17 23:59:34 	charon 		12[IKE] <con3000|445> activating ISAKMP_DPD task
    Dec 17 23:59:34 	charon 		12[IKE] <con3000|445> activating new tasks
    Dec 17 23:59:34 	charon 		12[IKE] <con3000|445> queueing ISAKMP_DPD task
    Dec 17 23:59:34 	charon 		12[IKE] <con3000|445> sending DPD request
    Dec 17 23:59:30 	charon 		12[CFG] vici client 2624 disconnected
    Dec 17 23:59:30 	charon 		12[CFG] vici client 2624 requests: list-sas
    Dec 17 23:59:30 	charon 		08[CFG] vici client 2624 registered for: list-sa
    Dec 17 23:59:30 	charon 		12[CFG] vici client 2624 connected
    Dec 17 23:59:24 	charon 		12[IKE] <con3000|445> nothing to initiate
    Dec 17 23:59:24 	charon 		12[IKE] <con3000|445> activating new tasks
    Dec 17 23:59:24 	charon 		12[ENC] <con3000|445> parsed INFORMATIONAL_V1 response 1660130927 [ HASH N(DPD_ACK) ]
    Dec 17 23:59:24 	charon 		12[NET] <con3000|445> received packet: from xxx.xxx.xxx.xxx (IP Fritzbox)[500] to xxx.xxx.xxx.xxx (IP pfsense)[500] (92 bytes)
    Dec 17 23:59:24 	charon 		12[IKE] <con3000|445> nothing to initiate
    Dec 17 23:59:24 	charon 		12[IKE] <con3000|445> activating new tasks
    Dec 17 23:59:24 	charon 		12[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (92 bytes)
    Dec 17 23:59:24 	charon 		12[ENC] <con3000|445> generating INFORMATIONAL_V1 request 1660130927 [ HASH N(DPD) ]
    Dec 17 23:59:24 	charon 		12[IKE] <con3000|445> activating ISAKMP_DPD task
    Dec 17 23:59:24 	charon 		12[IKE] <con3000|445> activating new tasks
    Dec 17 23:59:24 	charon 		12[IKE] <con3000|445> queueing ISAKMP_DPD task
    Dec 17 23:59:24 	charon 		12[IKE] <con3000|445> sending DPD request
    Dec 17 23:59:20 	charon 		12[CFG] vici client 2623 disconnected
    Dec 17 23:59:20 	charon 		10[CFG] vici client 2623 requests: list-sas
    Dec 17 23:59:20 	charon 		12[CFG] vici client 2623 registered for: list-sa
    Dec 17 23:59:20 	charon 		10[CFG] vici client 2623 connected
    Dec 17 23:59:02 	charon 		05[CHD] <con3000|445> CHILD_SA con3000{418} state change: INSTALLING => INSTALLED
    Dec 17 23:59:02 	charon 		05[IKE] <con3000|445> CHILD_SA con3000{418} established with SPIs c3c51713_i 5077683c_o and TS 192.168.2.0/24|/0 === 192.168.178.0/24|/0
    Dec 17 23:59:02 	charon 		05[CHD] <con3000|445> SPI 0x5077683c, src xxx.xxx.xxx.xxx (IP pfsense) dst xxx.xxx.xxx.xxx (IP Fritzbox)
    Dec 17 23:59:02 	charon 		05[CHD] <con3000|445> adding outbound ESP SA
    Dec 17 23:59:02 	charon 		05[CHD] <con3000|445> SPI 0xc3c51713, src xxx.xxx.xxx.xxx (IP Fritzbox) dst xxx.xxx.xxx.xxx (IP pfsense)
    Dec 17 23:59:02 	charon 		05[CHD] <con3000|445> adding inbound ESP SA
    Dec 17 23:59:02 	charon 		05[CHD] <con3000|445> using HMAC_SHA1_96 for integrity
    Dec 17 23:59:02 	charon 		05[CHD] <con3000|445> using AES_CBC for encryption
    Dec 17 23:59:02 	charon 		05[CHD] <con3000|445> CHILD_SA con3000{418} state change: CREATED => INSTALLING
    Dec 17 23:59:02 	charon 		05[ENC] <con3000|445> parsed QUICK_MODE request 134785801 [ HASH ]
    Dec 17 23:59:02 	charon 		05[NET] <con3000|445> received packet: from xxx.xxx.xxx.xxx (IP Fritzbox)[500] to xxx.xxx.xxx.xxx (IP pfsense)[500] (60 bytes)
    Dec 17 23:59:01 	charon 		15[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (444 bytes)
    Dec 17 23:59:01 	charon 		15[ENC] <con3000|445> generating QUICK_MODE response 134785801 [ HASH SA No KE ID ID ]
    Dec 17 23:59:01 	charon 		15[IKE] <con3000|445> received 3600s lifetime, configured 0s
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> received proposals: ESP:AES_CBC_256/HMAC_SHA2_512_256/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> proposal matches
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> selecting proposal:
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> no acceptable INTEGRITY_ALGORITHM found
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> selecting proposal:
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> config: 192.168.2.0/24|/0, received: 192.168.2.0/24|/0 => match: 192.168.2.0/24|/0
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> selecting traffic selectors for us:
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> config: 192.168.178.0/24|/0, received: 192.168.178.0/24|/0 => match: 192.168.178.0/24|/0
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> selecting traffic selectors for other:
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> found matching child config "con3000" with prio 10
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> candidate "con3000" with prio 5+5
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> 192.168.178.0/24|/0
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> proposing traffic selectors for other:
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> 192.168.2.0/24|/0
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> proposing traffic selectors for us:
    Dec 17 23:59:01 	charon 		15[CFG] <con3000|445> looking for a child config for 192.168.2.0/24|/0 === 192.168.178.0/24|/0
    Dec 17 23:59:01 	charon 		15[ENC] <con3000|445> parsed QUICK_MODE request 134785801 [ HASH SA No KE ID ID ]
    Dec 17 23:59:01 	charon 		15[NET] <con3000|445> received packet: from xxx.xxx.xxx.xxx (IP Fritzbox)[500] to xxx.xxx.xxx.xxx (IP pfsense)[500] (508 bytes)
    Dec 17 23:59:01 	charon 		15[ENC] <con3000|445> parsed INFORMATIONAL_V1 request 3490275435 [ HASH N(INITIAL_CONTACT) ]
    Dec 17 23:59:01 	charon 		15[NET] <con3000|445> received packet: from xxx.xxx.xxx.xxx (IP Fritzbox)[500] to xxx.xxx.xxx.xxx (IP pfsense)[500] (92 bytes)
    Dec 17 23:59:01 	charon 		05[NET] <con3000|445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (76 bytes)
    Dec 17 23:59:01 	charon 		05[ENC] <con3000|445> generating ID_PROT response 0 [ ID HASH ]
    Dec 17 23:59:01 	charon 		05[IKE] <con3000|445> IKE_SA con3000[445] state change: CONNECTING => ESTABLISHED
    Dec 17 23:59:01 	charon 		05[IKE] <con3000|445> IKE_SA con3000[445] established between xxx.xxx.xxx.xxx (IP pfsense)[xxx.xxx.xxx.xxx (IP pfsense)]...xxx.xxx.xxx.xxx (IP Fritzbox)[opaundoma.no-ip.biz]
    Dec 17 23:59:01 	charon 		05[CFG] <445> selected peer config "con3000"
    Dec 17 23:59:01 	charon 		05[CFG] <445> candidate "con3000", match: 1/20/3096 (me/other/ike)
    Dec 17 23:59:01 	charon 		05[CFG] <445> candidate "bypasslan", match: 1/1/24 (me/other/ike)
    Dec 17 23:59:01 	charon 		05[CFG] <445> looking for pre-shared key peer configs matching xxx.xxx.xxx.xxx (IP pfsense)...xxx.xxx.xxx.xxx (IP Fritzbox)[opaundoma.no-ip.biz]
    Dec 17 23:59:01 	charon 		05[ENC] <445> parsed ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ]
    Dec 17 23:59:01 	charon 		05[NET] <445> received packet: from xxx.xxx.xxx.xxx (IP Fritzbox)[500] to xxx.xxx.xxx.xxx (IP pfsense)[500] (108 bytes)
    Dec 17 23:59:01 	charon 		05[NET] <445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (324 bytes)
    Dec 17 23:59:01 	charon 		05[ENC] <445> generating ID_PROT response 0 [ KE No ]
    Dec 17 23:59:01 	charon 		05[CFG] <445> candidate "con3000", match: 1/1/3096 (me/other/ike)
    Dec 17 23:59:01 	charon 		05[CFG] <445> candidate "bypasslan", match: 1/1/24 (me/other/ike)
    Dec 17 23:59:01 	charon 		05[ENC] <445> parsed ID_PROT request 0 [ KE No ]
    Dec 17 23:59:01 	charon 		05[NET] <445> received packet: from xxx.xxx.xxx.xxx (IP Fritzbox)[500] to xxx.xxx.xxx.xxx (IP pfsense)[500] (308 bytes)
    Dec 17 23:59:00 	charon 		05[NET] <445> sending packet: from xxx.xxx.xxx.xxx (IP pfsense)[500] to xxx.xxx.xxx.xxx (IP Fritzbox)[500] (116 bytes)
    Dec 17 23:59:00 	charon 		05[ENC] <445> generating ID_PROT response 0 [ SA V V ]
    Dec 17 23:59:00 	charon 		05[IKE] <445> sending DPD vendor ID
    Dec 17 23:59:00 	charon 		05[IKE] <445> sending XAuth vendor ID
    Dec 17 23:59:00 	charon 		05[CFG] <445> selected proposal: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
    Dec 17 23:59:00 	charon 		05[CFG] <445> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
    Dec 17 23:59:00 	charon 		05[CFG] <445> received proposals: IKE:AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_2048, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:AES_CBC_192/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
    Dec 17 23:59:00 	charon 		05[CFG] <445> proposal matches
    Dec 17 23:59:00 	charon 		05[CFG] <445> selecting proposal:
    Dec 17 23:59:00 	charon 		05[CFG] <445> no acceptable INTEGRITY_ALGORITHM found
    Dec 17 23:59:00 	charon 		05[CFG] <445> selecting proposal:
    Dec 17 23:59:00 	charon 		05[IKE] <445> IKE_SA (unnamed)[445] state change: CREATED => CONNECTING
    Dec 17 23:59:00 	charon 		05[IKE] <445> xxx.xxx.xxx.xxx (IP Fritzbox) is initiating a Main Mode IKE_SA
    Dec 17 23:59:00 	charon 		05[IKE] <445> received DPD vendor ID
    Dec 17 23:59:00 	charon 		05[IKE] <445> received XAuth vendor ID
    Dec 17 23:59:00 	charon 		05[CFG] <445> found matching ike config: xxx.xxx.xxx.xxx (IP pfsense)...opaundoma.no-ip.biz with prio 3096
    Dec 17 23:59:00 	charon 		05[CFG] <445> candidate: xxx.xxx.xxx.xxx (IP pfsense)...opaundoma.no-ip.biz, prio 3096
    Dec 17 23:59:00 	charon 		05[CFG] <445> candidate: %any...%any, prio 24
    Dec 17 23:59:00 	charon 		05[CFG] <445> looking for an IKEv1 config for xxx.xxx.xxx.xxx (IP pfsense)...xxx.xxx.xxx.xxx (IP Fritzbox)
    Dec 17 23:59:00 	charon 		05[ENC] <445> parsed ID_PROT request 0 [ SA V V ]
    Dec 17 23:59:00 	charon 		05[NET] <445> received packet: from xxx.xxx.xxx.xxx (IP Fritzbox)[500] to xxx.xxx.xxx.xxx (IP pfsense)[500] (220 bytes)
    

    (Enclosed in text markdown to eliminate links - Derelict)



  • @kuschi: nice link you inserted instead of your ip-addresses... 👙 😂 (Firefox-User)



  • @commwest Oops, wasn't me intention.... :-O


  • LAYER 8 Netgate

    @commwest said in IPsec VPN tunnel to a Fritzbox after update to 2.4.4-p1:

    (MODP_768) which is almost too weak to be useful

    Entirely my opinion. That's why pfsense on both ends should be the best way and that is what I will do now.
    Thanks a lot anyway!

    It looks like it is trying three other (presumably stronger) PFS groups before reverting to group 1. It would not surprise me if those were 14, 5, 2.


  • LAYER 8 Netgate

    @kuschi said in IPsec VPN tunnel to a Fritzbox after update to 2.4.4-p1:

    Dec 18 00:01:48 charon 09[JOB] <con3000|445> DPD check timed out, enforcing DPD action

    They stop responding to DPD checks for whatever reason. The logs on the other side would need to be checked to see why.

    It could just be intermittent connectivity.

    But, regardless, based on the other logs, it will be down until they initiate.



  • Here is the log file from the other side: Fritzbox. Sorry part of it is in German.

    17.12.18 23:59:02 VPN-Verbindung zu VPN MCKUSCH [(IP pfsense)] IKE SA: DH14/AES-256/SHA1 IPsec SA: ESP-AES-256/SHA1/LT-3600 wurde erfolgreich hergestellt.
    17.12.18 23:58:50 VPN-Verbindung zu VPN MCKUSCH wurde getrennt. Ursache: 12 SA loss
    17.12.18 23:01:46 VPN-Verbindung zu VPN MCKUSCH [(IP pfsense)] IKE SA: DH14/AES-256/SHA1 IPsec SA: ESP-AES-256/SHA1/LT-3600 wurde erfolgreich hergestellt.
    17.12.18 23:01:44 VPN-Verbindung zu VPN MCKUSCH wurde getrennt. Ursache: 9 Dead Peer Detection
    17.12.18 22:46:40 VPN-Verbindung zu VPN MCKUSCH [(IP pfsense)] IKE SA: DH14/AES-256/SHA1 IPsec SA: ESP-AES-256/SHA1/LT-3600 wurde erfolgreich hergestellt.
    17.12.18 22:46:39 VPN-Verbindung zu VPN MCKUSCH wurde getrennt. Ursache: 9 Dead Peer Detection


  • LAYER 8 Netgate

    @kuschi said in IPsec VPN tunnel to a Fritzbox after update to 2.4.4-p1:

    17.12.18 23:59:02 VPN-Verbindung zu VPN MCKUSCH [(IP pfsense)] IKE SA: DH14/AES-256/SHA1 IPsec SA: ESP-AES-256/SHA1/LT-3600 wurde erfolgreich hergestellt.
    17.12.18 23:58:50 VPN-Verbindung zu VPN MCKUSCH wurde getrennt. Ursache: 12 SA loss
    17.12.18 23:01:46 VPN-Verbindung zu VPN MCKUSCH [(IP pfsense)] IKE SA: DH14/AES-256/SHA1 IPsec SA: ESP-AES-256/SHA1/LT-3600 wurde erfolgreich hergestellt.
    17.12.18 23:01:44 VPN-Verbindung zu VPN MCKUSCH wurde getrennt. Ursache: 9 Dead Peer Detection
    17.12.18 22:46:40 VPN-Verbindung zu VPN MCKUSCH [(IP pfsense)] IKE SA: DH14/AES-256/SHA1 IPsec SA: ESP-AES-256/SHA1/LT-3600 wurde erfolgreich hergestellt.
    17.12.18 22:46:39 VPN-Verbindung zu VPN MCKUSCH wurde getrennt. Ursache: 9 Dead Peer Detection

    17.12.18 23:59:02 VPN connection to VPN MCKUSCH [(IP pfsense)] IKE SA: DH14 / AES-256 / SHA1 IPsec SA: ESP-AES-256 / SHA1 / LT-3600 was successfully established.
    17.12.18 23:58:50 VPN connection to VPN MCKUSCH has been disconnected. Cause: 12 SA loss
    17.12.18 23:01:46 VPN connection to VPN MCKUSCH [(IP pfsense)] IKE SA: DH14 / AES-256 / SHA1 IPsec SA: ESP-AES-256 / SHA1 / LT-3600 was successfully established.
    17.12.18 23:01:44 VPN connection to VPN MCKUSCH has been disconnected. Cause: 9 dead peer detection
    17.12.18 22:46:40 VPN connection to VPN MCKUSCH [(IP pfsense)] IKE SA: DH14 / AES-256 / SHA1 IPsec SA: ESP-AES-256 / SHA1 / LT-3600 was successfully established.
    17.12.18 22:46:39 VPN connection to VPN MCKUSCH has been disconnected. Cause: 9 dead peer detection

    Doesn't tell us much.

    Need the logs from there saying why it is ignoring these:

    Dec 17 23:36:47 charon: 09[NET] <con1000|593> sending packet: from 192.12.13.1[500] to 82.110.36.24[500] (176 bytes)
    Dec 17 23:36:47 charon: 09[IKE] <con1000|593> sending retransmit 5 of request message ID 0, seq 1
    Dec 17 23:36:05 charon: 10[NET] <con1000|593> sending packet: from 192.12.13.1[500] to 82.110.36.24[500] (176 bytes)
    Dec 17 23:36:05 charon: 10[IKE] <con1000|593> sending retransmit 4 of request message ID 0, seq 1
    Dec 17 23:35:42 charon: 10[NET] <con1000|593> sending packet: from 192.12.13.1[500] to 82.110.36.24[500] (176 bytes)
    Dec 17 23:35:42 charon: 10[IKE] <con1000|593> sending retransmit 3 of request message ID 0, seq 1



  • @derelict If someone could tell me where will I find more detailed logs from the Fritzbox....



  • I had some time to dig into the Fritzbox and found some additional log files:

    BEGIN SECTION vpn VPN

    VPN avmike

    -rw-r--r-- 1 root root 16551 Dec 27 07:32 /var/tmp/ike.log
    -rw-r--r-- 1 root root 20579 Dec 27 06:22 /var/tmp/ike.old
    2018-12-27 05:28:24 avmike:wolke_neighbour_renew_sa 1 SAs
    2018-12-27 05:28:25 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 220 IC c7b118c56587c471 RC 00000000 0000 SA flags=
    2018-12-27 05:28:25 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 116 IC c7b118c56587c471 RC d66c8871d64ba1bd 0000 SA flags=
    2018-12-27 05:28:25 avmike:identity protection mode VPN MCKUSCH: selected lifetime: 3600 sec(no notify)
    2018-12-27 05:28:25 avmike:VPN MCKUSCH receive VENDOR ID Payload: XAUTH
    2018-12-27 05:28:25 avmike:VPN MCKUSCH receive VENDOR ID Payload: DPD
    2018-12-27 05:28:25 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 308 IC c7b118c56587c471 RC d66c8871d64ba1bd 0000 KEY flags=
    2018-12-27 05:28:25 avmike:< create_sa(appl=dsld,cname=VPN MCKUSCH)
    2018-12-27 05:28:25 avmike:VPN MCKUSCH: Phase 2 waiting
    2018-12-27 05:28:25 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 324 IC c7b118c56587c471 RC d66c8871d64ba1bd 0000 KEY flags=
    2018-12-27 05:28:25 avmike:VPN MCKUSCH: add phase 1 SA: DH14/AES-256/SHA1/3600sec id:187
    2018-12-27 05:28:25 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC c7b118c56587c471 RC d66c8871d64ba1bd 0000 IDENTIFICATION flags=e
    2018-12-27 05:28:25 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 76 IC c7b118c56587c471 RC d66c8871d64ba1bd 0000 IDENTIFICATION flags=e
    2018-12-27 05:28:25 avmike:VPN MCKUSCH: Phase 1 ready
    2018-12-27 05:28:25 avmike:VPN MCKUSCH: current=(IP pfsense) new=(IP pfsense)
    2018-12-27 05:28:25 avmike:VPN MCKUSCH: start waiting connections
    2018-12-27 05:28:25 avmike:VPN MCKUSCH: Phase 2 starting (start waiting)
    2018-12-27 05:28:26 avmike:>>> quickmode [(IP pfsense)] VPN MCKUSCH: V1.0 508 IC c7b118c56587c471 RC d66c8871d64ba1bd b79b46b HASH flags=e
    2018-12-27 05:28:26 avmike:<<< quickmode[(IP pfsense)] VPN MCKUSCH: V1.0 444 IC c7b118c56587c471 RC d66c8871d64ba1bd b79b46b HASH flags=e
    2018-12-27 05:28:26 avmike:>>> quickmode [(IP pfsense)] VPN MCKUSCH: V1.0 60 IC c7b118c56587c471 RC d66c8871d64ba1bd b79b46b HASH flags=e
    2018-12-27 05:28:26 avmike:VPN MCKUSCH: Phase 2 ready
    2018-12-27 05:28:26 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: 4750E80D LT: 3600 I/O: IN
    2018-12-27 05:28:26 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: C8CD6F95 LT: 3600 I/O: OUT
    2018-12-27 05:28:26 avmike:< cb_sa_created(name=VPN MCKUSCH,id=186,...,flags=0x00002101)
    2018-12-27 05:28:26 avmike:VPN MCKUSCH: start waiting connections
    2018-12-27 05:28:26 avmike:VPN MCKUSCH: NO waiting connections
    2018-12-27 05:28:36 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC c7b118c56587c471 RC d66c8871d64ba1bd 1520852e HASH flags=e
    2018-12-27 05:28:36 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC c7b118c56587c471 RC d66c8871d64ba1bd 1520852e HASH flags=e
    2018-12-27 05:28:46 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC c7b118c56587c471 RC d66c8871d64ba1bd d8578e17 HASH flags=e
    2018-12-27 05:28:56 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC c7b118c56587c471 RC d66c8871d64ba1bd 2310d460 HASH flags=e
    2018-12-27 05:29:06 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC c7b118c56587c471 RC d66c8871d64ba1bd 1ca9e35a HASH flags=e
    2018-12-27 05:29:16 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC c7b118c56587c471 RC d66c8871d64ba1bd 1fcb9fb2 HASH flags=e
    2018-12-27 05:29:26 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC c7b118c56587c471 RC d66c8871d64ba1bd 4a845476 HASH flags=e
    2018-12-27 05:34:24 avmike:VPN MCKUSCH: del phase 1 SA 186
    2018-12-27 05:34:25 avmike:< delete_sa(appl=dsld,cname=VPN MCKUSCH,id=185,what=7,reason=Lifetime expired)
    2018-12-27 05:34:25 avmike:FreeIPsecSA: spi=FB204F02 protocol=3 iotype=1
    2018-12-27 05:34:25 avmike:FreeIPsecSA: spi=C9852197 protocol=3 iotype=2
    2018-12-27 06:22:25 avmike:wolke_neighbour_renew_sa 1 SAs
    2018-12-27 06:22:25 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 220 IC 6872414bef8f5559 RC 00000000 0000 SA flags=
    2018-12-27 06:22:25 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 116 IC 6872414bef8f5559 RC 6511773149bee334 0000 SA flags=
    2018-12-27 06:22:25 avmike:identity protection mode VPN MCKUSCH: selected lifetime: 3600 sec(no notify)
    2018-12-27 06:22:25 avmike:VPN MCKUSCH receive VENDOR ID Payload: XAUTH
    2018-12-27 06:22:25 avmike:VPN MCKUSCH receive VENDOR ID Payload: DPD
    2018-12-27 06:22:26 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 308 IC 6872414bef8f5559 RC 6511773149bee334 0000 KEY flags=
    2018-12-27 06:22:26 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 324 IC 6872414bef8f5559 RC 6511773149bee334 0000 KEY flags=
    2018-12-27 06:22:26 avmike:VPN MCKUSCH: add phase 1 SA: DH14/AES-256/SHA1/3600sec id:188
    2018-12-27 06:22:26 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 0000 IDENTIFICATION flags=e
    2018-12-27 06:22:26 avmike:< create_sa(appl=dsld,cname=VPN MCKUSCH)
    2018-12-27 06:22:26 avmike:VPN MCKUSCH: Phase 2 waiting
    2018-12-27 06:22:26 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 76 IC 6872414bef8f5559 RC 6511773149bee334 0000 IDENTIFICATION flags=e
    2018-12-27 06:22:26 avmike:VPN MCKUSCH: Phase 1 ready
    2018-12-27 06:22:26 avmike:VPN MCKUSCH: current=(IP pfsense) new=(IP pfsense)
    2018-12-27 06:22:26 avmike:VPN MCKUSCH: start waiting connections
    2018-12-27 06:22:26 avmike:VPN MCKUSCH: Phase 2 starting (start waiting)
    2018-12-27 06:22:26 avmike:>>> quickmode [(IP pfsense)] VPN MCKUSCH: V1.0 508 IC 6872414bef8f5559 RC 6511773149bee334 9a91fdf1 HASH flags=e
    2018-12-27 06:22:26 avmike:<<< quickmode[(IP pfsense)] VPN MCKUSCH: V1.0 444 IC 6872414bef8f5559 RC 6511773149bee334 9a91fdf1 HASH flags=e
    2018-12-27 06:22:27 avmike:>>> quickmode [(IP pfsense)] VPN MCKUSCH: V1.0 60 IC 6872414bef8f5559 RC 6511773149bee334 9a91fdf1 HASH flags=e
    2018-12-27 06:22:27 avmike:VPN MCKUSCH: Phase 2 ready
    2018-12-27 06:22:27 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: 86D44AE1 LT: 3600 I/O: IN
    2018-12-27 06:22:27 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: C2365320 LT: 3600 I/O: OUT
    2018-12-27 06:22:27 avmike:< cb_sa_created(name=VPN MCKUSCH,id=187,...,flags=0x00002101)
    2018-12-27 06:22:27 avmike:VPN MCKUSCH: start waiting connections
    2018-12-27 06:22:27 avmike:VPN MCKUSCH: NO waiting connections
    2018-12-27 06:22:37 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 a8fa1dd1 HASH flags=e
    2018-12-27 06:22:37 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 a8fa1dd1 HASH flags=e
    2018-12-27 06:22:47 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 2b5f8cc7 HASH flags=e
    2018-12-27 06:22:57 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 2549e835 HASH flags=e
    2018-12-27 06:23:07 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 751f7fab HASH flags=e
    2018-12-27 06:23:17 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 2c07e412 HASH flags=e
    2018-12-27 06:23:27 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 279a5e57 HASH flags=e
    2018-12-27 06:28:25 avmike:VPN MCKUSCH: del phase 1 SA 187
    2018-12-27 06:28:26 avmike:< delete_sa(appl=dsld,cname=VPN MCKUSCH,id=186,what=7,reason=Lifetime expired)
    2018-12-27 06:28:26 avmike:FreeIPsecSA: spi=4750E80D protocol=3 iotype=1
    2018-12-27 06:28:26 avmike:FreeIPsecSA: spi=C8CD6F95 protocol=3 iotype=2
    2018-12-27 06:55:18 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 6872414bef8f5559 RC 6511773149bee334 2c1e5ef7 HASH flags=e
    2018-12-27 07:16:26 avmike:wolke_neighbour_renew_sa 1 SAs
    2018-12-27 07:16:26 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 220 IC 928c71fe2ff76662 RC 00000000 0000 SA flags=
    2018-12-27 07:16:26 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 116 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 0000 SA flags=
    2018-12-27 07:16:26 avmike:identity protection mode VPN MCKUSCH: selected lifetime: 3600 sec(no notify)
    2018-12-27 07:16:26 avmike:VPN MCKUSCH receive VENDOR ID Payload: XAUTH
    2018-12-27 07:16:26 avmike:VPN MCKUSCH receive VENDOR ID Payload: DPD
    2018-12-27 07:16:26 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 308 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 0000 KEY flags=
    2018-12-27 07:16:27 avmike:< create_sa(appl=dsld,cname=VPN MCKUSCH)
    2018-12-27 07:16:27 avmike:VPN MCKUSCH: Phase 2 waiting
    2018-12-27 07:16:28 avmike:>r> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 308 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 0000 KEY flags=
    2018-12-27 07:16:28 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 324 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 0000 KEY flags=
    2018-12-27 07:16:29 avmike:VPN MCKUSCH: add phase 1 SA: DH14/AES-256/SHA1/3600sec id:189
    2018-12-27 07:16:29 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 0000 IDENTIFICATION flags=e
    2018-12-27 07:16:29 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 76 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 0000 IDENTIFICATION flags=e
    2018-12-27 07:16:29 avmike:VPN MCKUSCH: Phase 1 ready
    2018-12-27 07:16:29 avmike:VPN MCKUSCH: current=(IP pfsense) new=(IP pfsense)
    2018-12-27 07:16:29 avmike:VPN MCKUSCH: start waiting connections
    2018-12-27 07:16:29 avmike:VPN MCKUSCH: Phase 2 starting (start waiting)
    2018-12-27 07:16:29 avmike:>>> quickmode [(IP pfsense)] VPN MCKUSCH: V1.0 508 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 2bf7fa9 HASH flags=e
    2018-12-27 07:16:29 avmike:<<< quickmode[(IP pfsense)] VPN MCKUSCH: V1.0 444 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 2bf7fa9 HASH flags=e
    2018-12-27 07:16:29 avmike:>>> quickmode [(IP pfsense)] VPN MCKUSCH: V1.0 60 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 2bf7fa9 HASH flags=e
    2018-12-27 07:16:29 avmike:VPN MCKUSCH: Phase 2 ready
    2018-12-27 07:16:29 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: CBD62308 LT: 3600 I/O: IN
    2018-12-27 07:16:29 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: C05403E4 LT: 3600 I/O: OUT
    2018-12-27 07:16:29 avmike:< cb_sa_created(name=VPN MCKUSCH,id=188,...,flags=0x00002101)
    2018-12-27 07:16:29 avmike:VPN MCKUSCH: start waiting connections
    2018-12-27 07:16:29 avmike:VPN MCKUSCH: NO waiting connections
    2018-12-27 07:16:40 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 2b4fccd5 HASH flags=e
    2018-12-27 07:16:40 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 2b4fccd5 HASH flags=e
    2018-12-27 07:16:50 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 f64d9069 HASH flags=e
    2018-12-27 07:17:00 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 9a87db77 HASH flags=e
    2018-12-27 07:17:10 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 69880609 HASH flags=e
    2018-12-27 07:17:20 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 51824bd9 HASH flags=e
    2018-12-27 07:17:30 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 bf9c6d0f HASH flags=e
    2018-12-27 07:17:48 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 7a749f0 HASH flags=e
    2018-12-27 07:17:58 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 65e2e2ed HASH flags=e
    2018-12-27 07:18:08 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 bf211ecc HASH flags=e
    2018-12-27 07:18:18 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 96681b4f HASH flags=e
    2018-12-27 07:18:28 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 f62169fb HASH flags=e
    2018-12-27 07:22:26 avmike:VPN MCKUSCH: del phase 1 SA 188
    2018-12-27 07:22:27 avmike:< delete_sa(appl=dsld,cname=VPN MCKUSCH,id=187,what=7,reason=Lifetime expired)
    2018-12-27 07:22:27 avmike:FreeIPsecSA: spi=86D44AE1 protocol=3 iotype=1
    2018-12-27 07:22:27 avmike:FreeIPsecSA: spi=C2365320 protocol=3 iotype=2
    2018-12-27 07:22:50 avmike:< cb_sa_deleted(name=VPN MCKUSCH,id=188,what=3)
    2018-12-27 07:22:50 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 76 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 5812faab HASH flags=e
    2018-12-27 07:22:50 avmike:FreeIPsecSA: spi=CBD62308 protocol=3 iotype=1
    2018-12-27 07:22:50 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 76 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 498d3042 HASH flags=e
    2018-12-27 07:22:50 avmike:FreeIPsecSA: spi=C05403E4 protocol=3 iotype=2
    2018-12-27 07:22:50 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 928c71fe2ff76662 RC 8bac593a23c18ae1 b0282d8d HASH flags=e
    2018-12-27 07:22:50 avmike:VPN MCKUSCH: del phase 1 SA 189
    2018-12-27 07:22:55 avmike:< add(appl=dsld,cname=VPN MCKUSCH,localip=(IP Fritzbox), remoteip=255.255.255.255, p1ss=dh14/aes/sha, p2ss=esp-aes256-3des-sha/ah-no/comp-lzs-no/pfs p1mode=2 keepalive_ip=0.0.0.0 flags=0x40001 tunnel no_xauth no_cfgmode no_nat_t no_certsrv_server_auth)
    2018-12-27 07:22:55 avmike:new neighbour VPN MCKUSCH:
    2018-12-27 07:22:55 avmike:< create_sa(appl=dsld,cname=VPN MCKUSCH)
    2018-12-27 07:22:55 avmike:VPN MCKUSCH: Phase 1 starting
    2018-12-27 07:22:55 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 220 IC 83b4f0f722b753b4 RC 00000000 0000 SA flags=
    2018-12-27 07:22:55 avmike:VPN MCKUSCH: Warning: source changed from 0.0.0.0:500 to (IP pfsense):500
    2018-12-27 07:22:55 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 116 IC 83b4f0f722b753b4 RC 84484486b407c0a8 0000 SA flags=
    2018-12-27 07:22:55 avmike:identity protection mode VPN MCKUSCH: selected lifetime: 3600 sec(no notify)
    2018-12-27 07:22:55 avmike:VPN MCKUSCH receive VENDOR ID Payload: XAUTH
    2018-12-27 07:22:55 avmike:VPN MCKUSCH receive VENDOR ID Payload: DPD
    2018-12-27 07:22:55 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 308 IC 83b4f0f722b753b4 RC 84484486b407c0a8 0000 KEY flags=
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: Warning: source changed from 0.0.0.0:500 to (IP pfsense):500
    2018-12-27 07:22:56 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 324 IC 83b4f0f722b753b4 RC 84484486b407c0a8 0000 KEY flags=
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: add phase 1 SA: DH14/AES-256/SHA1/3600sec id:1
    2018-12-27 07:22:56 avmike:>>> identity protection mode [(IP pfsense)] VPN MCKUSCH: V1.0 108 IC 83b4f0f722b753b4 RC 84484486b407c0a8 0000 IDENTIFICATION flags=e
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: Warning: source changed from 0.0.0.0:500 to (IP pfsense):500
    2018-12-27 07:22:56 avmike:<<< identity protection mode[(IP pfsense)] VPN MCKUSCH: V1.0 76 IC 83b4f0f722b753b4 RC 84484486b407c0a8 0000 IDENTIFICATION flags=e
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: Phase 1 ready
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: current=0.0.0.0 new=(IP pfsense)
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: no valid sa, reseting initialcontactdone flag
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: sending initial contact message
    2018-12-27 07:22:56 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 940ec48 HASH flags=e
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: start waiting connections
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: Phase 2 starting (start waiting)
    2018-12-27 07:22:56 avmike:>>> quickmode [(IP pfsense)] VPN MCKUSCH: V1.0 508 IC 83b4f0f722b753b4 RC 84484486b407c0a8 bb9dcb6a HASH flags=e
    2018-12-27 07:22:56 avmike:<<< quickmode[(IP pfsense)] VPN MCKUSCH: V1.0 444 IC 83b4f0f722b753b4 RC 84484486b407c0a8 bb9dcb6a HASH flags=e
    2018-12-27 07:22:56 avmike:>>> quickmode [(IP pfsense)] VPN MCKUSCH: V1.0 60 IC 83b4f0f722b753b4 RC 84484486b407c0a8 bb9dcb6a HASH flags=e
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: Phase 2 ready
    2018-12-27 07:22:56 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: 59C898BB LT: 3600 I/O: IN
    2018-12-27 07:22:56 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: C9FC517F LT: 3600 I/O: OUT
    2018-12-27 07:22:56 avmike:< cb_sa_created(name=VPN MCKUSCH,id=1,...,flags=0x00002101)
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: start waiting connections
    2018-12-27 07:22:56 avmike:VPN MCKUSCH: NO waiting connections
    2018-12-27 07:23:07 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 cd4fbd83 HASH flags=e
    2018-12-27 07:23:07 avmike:>r> infomode [(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 cd4fbd83 HASH flags=e
    2018-12-27 07:25:40 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 e17cc7d6 HASH flags=e
    2018-12-27 07:25:50 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 e6b964ba HASH flags=e
    2018-12-27 07:26:00 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 4d99e03e HASH flags=e
    2018-12-27 07:26:16 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 40692e24 HASH flags=e
    2018-12-27 07:26:26 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 5a1176a4 HASH flags=e
    2018-12-27 07:26:40 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 e4d053b9 HASH flags=e
    2018-12-27 07:26:50 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 fc62b165 HASH flags=e
    2018-12-27 07:27:00 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 5767b485 HASH flags=e
    2018-12-27 07:27:10 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 15a82a23 HASH flags=e
    2018-12-27 07:27:20 avmike:<<< infomode[(IP pfsense)] VPN MCKUSCH: V1.0 92 IC 83b4f0f722b753b4 RC 84484486b407c0a8 200be361 HASH flags=e



  • I had another opportunity to test the connections from the side of the Fritzbox and from the side of the pfsense box:

    • pfsense box shows connection inactive, Fritzbox shows connection active: traffic direction from Fritzbox to pfsense works, e.g. ping / trace route. pfsense box changes status to connection active
    • pfsense box shows connection inactive, Fritzbox shows connection active: traffic direction from pfsense box to Fritzbox does not work. Traffic times out, ping/ trace route shows no result