After two sites upgrade to 157, IPSEC tunnel will not connect

cwensink · 8 July 2021 16:55

I have two sites, both have IPFire Routers that recently upgraded to 157. I have an IPSec Tunnel configured to go between the locations. I rebooted the main office IPFire at Midnight last night, and since then the tunnels have not come back up.

I have tried re-configuring new connections using Open VPN, they do not connect. I tried configuring a new tunnel using IPSec with certs for authentication instead of the PSK, they do not connect.

in /var/log/messages on the main sites ipfire I am getting:

Jul  8 11:44:36 ipfire charon: 01[CFG] received stroke: terminate 'XXXXXX'
Jul  8 11:44:36 ipfire charon: 07[IKE] destroying IKE_SA in state CONNECTING without notification
Jul  8 11:44:36 ipfire charon: 12[CFG] rereading secrets
Jul  8 11:44:36 ipfire charon: 12[CFG] loading secrets from '/etc/ipsec.secrets'
Jul  8 11:44:36 ipfire charon: 12[CFG] loading secrets from '/etc/ipsec.user.secrets'
Jul  8 11:44:36 ipfire charon: 12[CFG]   loaded RSA private key from '/var/ipfire/certs/hostkey.pem'
Jul  8 11:44:36 ipfire charon: 12[CFG] rereading ca certificates from '/etc/ipsec.d/cacerts'
Jul  8 11:44:36 ipfire charon: 12[CFG]   loaded ca certificate "C=US, ST=WI, L=XXX, O=XXXX, OU=XX, CN=XXXXX CA, E=XXXXXXXXXXX" from '/etc/ipsec.d/cacerts/3dparootcert.pem'
Jul  8 11:44:36 ipfire charon: 12[CFG]   loaded ca certificate "C=US, ST=XXI, L=XXXXXXXXXX, O=XXXX, Inc., OU=IS, CN=Five Star Plastics, Inc. CA, E=XXXXXXXXXXXXXXXXXXX" from '/etc/ipsec.d/cacerts/cacert.pem'
Jul  8 11:44:36 ipfire charon: 12[CFG] rereading aa certificates from '/etc/ipsec.d/aacerts'
Jul  8 11:44:36 ipfire charon: 12[CFG] rereading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Jul  8 11:44:36 ipfire charon: 12[CFG] rereading attribute certificates from '/etc/ipsec.d/acerts'
Jul  8 11:44:36 ipfire charon: 12[CFG] rereading crls from '/etc/ipsec.d/crls'
Jul  8 11:44:36 ipfire charon: 12[CFG]   loaded crl from '/etc/ipsec.d/crls/cacrl.pem'
Jul  8 11:44:36 ipfire charon: 12[LIB]   crl from Feb 09 15:29:01 2021 is not newer - existing crl from Feb 09 15:29:01 2021 retained
Jul  8 11:44:36 ipfire charon: 05[CFG] received stroke: delete connection 'XXXXX'
Jul  8 11:44:36 ipfire charon: 05[CFG] deleted connection 'XXXXX'
Jul  8 11:44:36 ipfire charon: 09[CFG] received stroke: add connection 'XXXX'
Jul  8 11:44:36 ipfire charon: 09[CFG]   loaded certificate "C=US, ST=XX, O=XXXXXXXXXX, OU=IS, CN=ipfire.inside.five-star-plastics.com" from '/var/ipfire/certs/hostcert.pem'
Jul  8 11:44:36 ipfire charon: 09[CFG]   id 'XXXXXXX' not confirmed by certificate, defaulting to 'C=XX, ST=XX, O=XXXXXXXX, OU=IS, CN=XXXXXXXXXXXXXXXXXXXXXXXX'
Jul  8 11:44:36 ipfire charon: 09[CFG]   loaded certificate "C=XX, ST=XX, O=XXXX, OU=XX, CN=XXXXXXXXXXXXXXXXXXXXXXXXXXXX" from '/var/ipfire/certs/FSP3DPACERTcert.pem'
Jul  8 11:44:36 ipfire charon: 09[CFG]   id 'XXXXXXXX' not confirmed by certificate, defaulting to 'C=XX, ST=XX, O=XXXX, OU=XX, CN=XXXXXXXX'
Jul  8 11:44:36 ipfire charon: 09[CFG] added configuration 'XXXX'
Jul  8 11:44:36 ipfire charon: 10[CFG] received stroke: initiate 'XXXX'
Jul  8 11:44:36 ipfire charon: 10[IKE] initiating IKE_SA FSP3DPACERT[2] to XXXXXXX
Jul  8 11:44:36 ipfire charon: 10[IKE] initiating IKE_SA FSP3DPACERT[2] to 69.XXXXXXX
Jul  8 11:44:36 ipfire charon: 10[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Jul  8 11:44:36 ipfire charon: 10[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)
Jul  8 11:44:36 ipfire charon: 13[CFG] received stroke: initiate 'XXXXXXXX'
Jul  8 11:44:40 ipfire charon: 15[IKE] retransmit 1 of request with message ID 0
Jul  8 11:44:40 ipfire charon: 15[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)
Jul  8 11:44:47 ipfire charon: 15[IKE] retransmit 2 of request with message ID 0
Jul  8 11:44:47 ipfire charon: 15[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)
Jul  8 11:45:00 ipfire charon: 10[IKE] retransmit 3 of request with message ID 0
Jul  8 11:45:00 ipfire charon: 10[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)
Jul  8 11:45:24 ipfire charon: 05[IKE] retransmit 4 of request with message ID 0
Jul  8 11:45:24 ipfire charon: 05[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)

The remote office IPFire has the same messages with the IP addresses in the other order.

I cannot ping the IP address from on office to another, but both internet connections are working and online.

Any thoughts on why the connections just do not want to come up?

Chris

pmueller · 8 July 2021 17:07

Hi,

I think these lines are the most interesting ones here:

cwensink:

Jul  8 11:44:40 ipfire charon: 15[IKE] retransmit 1 of request with message ID 0
Jul  8 11:44:40 ipfire charon: 15[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)
Jul  8 11:44:47 ipfire charon: 15[IKE] retransmit 2 of request with message ID 0
Jul  8 11:44:47 ipfire charon: 15[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)
Jul  8 11:45:00 ipfire charon: 10[IKE] retransmit 3 of request with message ID 0
Jul  8 11:45:00 ipfire charon: 10[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)
Jul  8 11:45:24 ipfire charon: 05[IKE] retransmit 4 of request with message ID 0
Jul  8 11:45:24 ipfire charon: 05[NET] sending packet: from 104.XXX[500] to 69.XXX[500] (5076 bytes)

This means the machine behind the public IP address starting with 69 does not even respond to UDP packets on port 500.

Such a thing can happen if IPFire is behind a dial-up connection with a dynamic IP address, and the dynamic DNS name configured failed to update.

If so, could you run

ddns update-all --force

on that system and tell us if this makes any difference.

Thanks, and best regards,
Peter Müller

cwensink · 8 July 2021 18:28

The connection with the IP of 69 is on a Dedicated Fiber connection 75 Mbps up and down. They did have a DHCP assigned address, but we just upgraded and paid for a static address due to these problems. The router has been rebooted and the red interface is assigned the static address from the provider (via DHCP). The new address is put into the IPSEC configuration on both sides, and this is the result. Is it common for UDP port 500 to be blocked by an ISP?

I will run the command at the remote site and post the result back shortly

Chris

cwensink · 8 July 2021 18:53

I ran the command on the remote IPFire, no output from running it, I enabled and disabled the connections on both sides and refreshed the VPN connection, still says connecting … on both sides.

Logs output:

Local:

Jul  8 13:34:43 ipfire charon: 14[IKE] retransmit 3 of request with message ID 0
Jul  8 13:34:43 ipfire charon: 14[NET] sending packet: from 104.XXXXXX[500] to 69.XXXXXXXXXXXXX[500] (5076 bytes)
Jul  8 13:34:56 ipfire charon: 11[CFG] received stroke: terminate 'FSP3DPACERT'
Jul  8 13:34:56 ipfire charon: 14[IKE] destroying IKE_SA in state CONNECTING without notification
Jul  8 13:34:56 ipfire charon: 06[CFG] rereading secrets
Jul  8 13:34:56 ipfire charon: 06[CFG] loading secrets from '/etc/ipsec.secrets'
Jul  8 13:34:56 ipfire charon: 06[CFG] loading secrets from '/etc/ipsec.user.secrets'
Jul  8 13:34:56 ipfire charon: 06[CFG]   loaded RSA private key from '/var/ipfire/certs/hostkey.pem'
Jul  8 13:34:56 ipfire charon: 06[CFG] rereading ca certificates from '/etc/ipsec.d/cacerts'
Jul  8 13:34:56 ipfire charon: 06[CFG]   loaded ca certificate "C=US, ST=XX, L=XXXXXX, O=XXXX, OU=XX, CN=XX CA, E=XXXXXXXXXXX" from '/etc/ipsec.d/cacerts/3dparootcert.pem'
Jul  8 13:34:56 ipfire charon: 06[CFG]   loaded ca certificate "C=US, ST=XX, L=XXXX, O=XXXX, Inc., OU=XX, CN=XXXXXXXXX CA, E=XXXXXXXXXXXXXXXXXXX" from '/etc/ipsec.d/cacerts/cacert.pem'
Jul  8 13:34:56 ipfire charon: 06[CFG] rereading aa certificates from '/etc/ipsec.d/aacerts'
Jul  8 13:34:56 ipfire charon: 06[CFG] rereading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Jul  8 13:34:56 ipfire charon: 06[CFG] rereading attribute certificates from '/etc/ipsec.d/acerts'
Jul  8 13:34:56 ipfire charon: 06[CFG] rereading crls from '/etc/ipsec.d/crls'
Jul  8 13:34:56 ipfire charon: 06[CFG]   loaded crl from '/etc/ipsec.d/crls/cacrl.pem'
Jul  8 13:34:56 ipfire charon: 06[LIB]   crl from Feb 09 15:29:01 2021 is not newer - existing crl from Feb 09 15:29:01 2021 retained
Jul  8 13:34:56 ipfire charon: 05[CFG] received stroke: delete connection 'FSP3DPACERT'
Jul  8 13:34:56 ipfire charon: 05[CFG] deleted connection 'FSP3DPACERT'
Jul  8 13:34:56 ipfire charon: 09[CFG] received stroke: add connection 'FSP3DPACERT'
Jul  8 13:34:56 ipfire charon: 09[CFG]   loaded certificate "C=US, ST=XX, O=XXXXXX, OU=XX, CN=XXXXXXXXXXXXXX" from '/var/ipfire/certs/hostcert.pem'
Jul  8 13:34:56 ipfire charon: 09[CFG]   id 'FSPCERT' not confirmed by certificate, defaulting to 'C=US, ST=XX, O=XXXXXXXXXXXX, OU=IS, CN=XXXXXXXXXXXXXX'
Jul  8 13:34:56 ipfire charon: 09[CFG]   loaded certificate "C=US, ST=XX, O=XXXX, OU=XX, CN=XXXXXX" from '/var/ipfire/certs/FSP3DPACERTcert.pem'
Jul  8 13:34:56 ipfire charon: 09[CFG]   id '3DPACERT' not confirmed by certificate, defaulting to 'C=US, ST=XX, O=XXXx, OU=XX, CN=XXXX'
Jul  8 13:34:56 ipfire charon: 09[CFG] added configuration 'FSP3DPACERT'
Jul  8 13:34:56 ipfire charon: 08[CFG] received stroke: initiate 'FSP3DPACERT'
Jul  8 13:34:56 ipfire charon: 08[IKE] initiating IKE_SA FSP3DPACERT[4] to 69.XXXXXX
Jul  8 13:34:56 ipfire charon: 08[IKE] initiating IKE_SA FSP3DPACERT[4] to 69.XXXXXX
Jul  8 13:34:56 ipfire charon: 08[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Jul  8 13:34:56 ipfire charon: 08[NET] sending packet: from 104XXXXXX[500] to 69XXXXXX[500] (5076 bytes)
Jul  8 13:34:56 ipfire charon: 11[CFG] received stroke: initiate 'FSP3DPACERT'
Jul  8 13:35:00 ipfire charon: 01[IKE] retransmit 1 of request with message ID 0
Jul  8 13:35:00 ipfire charon: 01[NET] sending packet: from 104XXXXXX[500] to 69XXXXXX[500] (5076 bytes)
Jul  8 13:35:07 ipfire charon: 01[IKE] retransmit 2 of request with message ID 0
Jul  8 13:35:07 ipfire charon: 01[NET] sending packet: from 104XXXXXX[500] to 69XXXXXX[500] (5076 bytes)
Jul  8 13:35:20 ipfire charon: 06[IKE] retransmit 3 of request with message ID 0
Jul  8 13:35:20 ipfire charon: 06[NET] sending packet: from 104XXXXXX[500] to 69XXXXXX[500] (5076 bytes)
Jul  8 13:35:43 ipfire charon: 08[IKE] retransmit 4 of request with message ID 0
Jul  8 13:35:43 ipfire charon: 08[NET] sending packet: from 104XXXXXX[500] to 69XXXXXX[500] (5076 bytes)
^C

Remote:

 tail -f messages | grep charon
Jul  8 13:40:38 ipfire charon: 14[CFG]   id '3DPACERT' not confirmed by certificate, defaulting to 'C=US, ST=XXXXXX, O=XXXXXX, OU=XXXXXX, CN=XXXXXX'
Jul  8 13:40:38 ipfire charon: 14[CFG]   loaded certificate "C=US, ST=XXXXXX, O=XXXXXX, OU=IS, CN=XXXXXX" from '/var/ipfire/certs/FSP3DPACERTcert.pem'
Jul  8 13:40:38 ipfire charon: 14[CFG]   id 'FSPCERT' not confirmed by certificate, defaulting to 'C=US, ST=XXXXXX, O=XXXXXX, Inc., OU=XXXXXX, CN=XXXXXX'
Jul  8 13:40:38 ipfire charon: 14[CFG] added configuration 'FSP3DPACERT'
Jul  8 13:40:38 ipfire charon: 15[CFG] received stroke: initiate 'FSP3DPACERT'
Jul  8 13:40:38 ipfire charon: 15[IKE] initiating IKE_SA FSP3DPACERT[3] to 104XXXXXX
Jul  8 13:40:38 ipfire charon: 15[IKE] initiating IKE_SA FSP3DPACERT[3] to 104XXXXXX
Jul  8 13:40:38 ipfire charon: 15[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Jul  8 13:40:38 ipfire charon: 15[NET] sending packet: from 69XXXXXX[500] to 104XXXXXX[500] (5076 bytes)
Jul  8 13:40:38 ipfire charon: 04[CFG] received stroke: initiate 'FSP3DPACERT'
Jul  8 13:40:42 ipfire charon: 07[IKE] retransmit 1 of request with message ID 0
Jul  8 13:40:42 ipfire charon: 07[NET] sending packet: from 69XXXXXX[500] to XXXXXX[500] (5076 bytes)
Jul  8 13:40:42 ipfire charon: 11[NET] received packet: from 104XXXXXX[500] to 69XXXXXX[500] (5076 bytes)
Jul  8 13:40:42 ipfire charon: 11[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Jul  8 13:40:42 ipfire charon: 11[IKE] 104XXXXXX is initiating an IKE_SA
Jul  8 13:40:42 ipfire charon: 11[IKE] 104XXXXXX is initiating an IKE_SA
Jul  8 13:40:42 ipfire charon: 11[CFG] selected proposal: IKE:CHACHA20_POLY1305/PRF_HMAC_SHA2_512/CURVE_25519
Jul  8 13:40:42 ipfire charon: 11[IKE] sending cert request for "C=US, ST=XXXXXX, L=XXXXXX, O=XXXXXX, OU=XXXXXX, CN=XXXXXX CA, E=XXXXXX"
Jul  8 13:40:42 ipfire charon: 11[IKE] sending cert request for "C=US, ST=XXXXXX, L=XXXXXX, O=XXXXXX, OU=XXXXXX, CN=XXXXXX CA, E=XXXXXX"
Jul  8 13:40:42 ipfire charon: 11[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(FRAG_SUP) N(HASH_ALG) N(CHDLESS_SUP) N(MULT_AUTH) ]
Jul  8 13:40:42 ipfire charon: 11[NET] sending packet: from 69.XXXXXX[500] to 104.XXXXXX[500] (281 bytes)
Jul  8 13:40:49 ipfire charon: 15[IKE] retransmit 2 of request with message ID 0
Jul  8 13:40:49 ipfire charon: 15[NET] sending packet: from 69.XXXXXX[500] to 104XXXXXX[500] (5076 bytes)
Jul  8 13:41:02 ipfire charon: 06[IKE] retransmit 3 of request with message ID 0
Jul  8 13:41:02 ipfire charon: 06[NET] sending packet: from 69.XXXXXX[500] to 104.XXXXXX[500] (5076 bytes)

pmueller · 10 July 2021 20:01

Hi,

sorry for my late reply.

First, it seems as the system time on both IPFire machines differs by about 5 minutes. Is this the case (if so, please check NTP working correctly - just for good measure ) or do the log snippets cover different time frames?

Second, lets skim through the logs in detail:

First, the local IPFire machine is generating an IKE_SA_INIT message and sends it to the remote machine:

cwensink:

Jul  8 13:34:56 ipfire charon: 08[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Jul  8 13:34:56 ipfire charon: 08[NET] sending packet: from 104XXXXXX[500] to 69XXXXXX[500] (5076 bytes)

The remote machine successfully receives that packet, and parses it:

cwensink:

Jul  8 13:40:42 ipfire charon: 11[NET] received packet: from 104XXXXXX[500] to 69XXXXXX[500] (5076 bytes)
Jul  8 13:40:42 ipfire charon: 11[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]

It then assembles a response and tries to send it back to your “local” IPFire machine:

cwensink:

Jul  8 13:40:42 ipfire charon: 11[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(FRAG_SUP) N(HASH_ALG) N(CHDLESS_SUP) N(MULT_AUTH) ]
Jul  8 13:40:42 ipfire charon: 11[NET] sending packet: from 69.XXXXXX[500] to 104.XXXXXX[500] (281 bytes)

But that packet does not seem to reach the system. This is why your IPsec connection will not be established. Two reasons are common for this:

The router before your local IPFire machine drops incoming UDP packets to port 500 in particular, or drops any incoming packets in general - as you already suspected initially. To avoid any interference from it, can you turn it into a bridge mode so it will only translate from DSL or cable to Ethernet, not doing anything else?
This could also indicate a one-way fragmenting issue. However, since the big UDP packet (> 5.000 bytes) made it through, and the reply is smaller by orders of magnitude (281 bytes), I do not really suspect the case - unless you already have heard of MTU issues or fragmentation problems somewhere in or around your networks.

To cut it short: Please check the router before the “local” IPFire machine.

Thanks, and best regards,
Peter Müller

cwensink · 12 July 2021 16:11

I found the issue. As you suspected, there was a block that started happening on the DSL Modem on the main site side. The device lost it’s settings then went back into standard security mode, which turned on a firewall, and the 802.11 broadcast, etc. After turning that stuff off and having the modem be in bridging mode then the tunnel came back up without issue.

Thanks for your help.

pmueller · 12 July 2021 17:05

Hi,

I see, glad to have this confirmed and to be helpful.

Thanks, and best regards,
Peter Müller

cwensink · 12 July 2021 19:10

I spoke too soon. After coming back from Lunch the sites were down. I used connection scheduler to reconnect on my side, nothing helped.

I used connection scheduler to reconnect through teamveiwer on the remote site, then after that side reconnected the VPN came up instantly.

So my question now is, is there a way to conditionally reset the connection, for exaple if the VPN is down for more than 5 minutes then reset the connection?

Chris

pmueller · 13 July 2021 19:56

Hi,

well, I am sorry. What did the IPsec logs say this time?

This should not be necessary, unless you turned off DPD (dead peer detection) or the IPsec connection is only established by one IPFire system, not by both. Would you mind posting a screenshot of your IPsec connection configuration here? Feel free to redact any sensitive information (FQDNs, public IP addresses, etc.); the “advanced” section is particularly interesting to me.

Thanks, and best regards,
Peter Müller

cwensink · 2 August 2021 17:30

Sorry for the late reply, the core issue was settings on the local Modem reverted back to factory defaults and turned off bridge mode and did not allow other packets to go through for VPN connections, once It was set back up everything came back up just fine.

pmueller · 5 August 2021 12:59

Hi,

no worries. Glad to hear this is solved.

Thanks, and best regards,
Peter Müller