VPN IPsec Remote gateway using DDNS doesn't update

cyboc

Hi Ermal,

I noticed you've made some recent commits involving replacing dnswatch with filterdns, which I assume is in response to this thread. Thank you for that. :-)

I wasn't sure if you were still working on these changes but I thought I would try today's build anyway (2.0-BETA5 (i386) built on Fri Jan 28 05:30:15 EST 2011).

In the system log, I can see an attempt to startup filterdns but it fails with the following errors:

Jan 28 16:04:54 	filterdns: unable to open configuration file
Jan 28 16:04:54 	php: : The command '/usr/local/sbin/filterdns -p /var/run/filterdns-ipsec.pid -i 60 -c /var/etc/filterdns_ipsec.hosts -d 1' returned exit code '71', the output was 'filterdns: open file'

I think the problem is that filterdns is trying to open the config file /var/etc/filterdns_ipsec.hosts but that file doesn't exist. The closest file name that exists in that directory is filternds-ipsec.hosts:

# ls /var/etc/ | grep filter
filternds-ipsec.hosts

Notice the two differences between the expected file name and the actual file name:

"nds" instead of "dns"
"-" instead of "_"

I hope that helps. I'm glad to help test this some more if you make some more commits.

eri--

Thank you for noticing that.
The fix is simple https://rcs.pfsense.org/projects/pfsense/repos/mainline/commits/44ab93a4188b7530425ec74b5f832b5ab33fd1c4 if you do not want to wait for a snapshot.

cyboc

Hi Ermal,

Thank you for your quick response to my previous message.

I tried 2.0-BETA5 (i386) built on Mon Jan 31 07:16:37 EST 2011 but I still see this filterdns error in the system logs:

Jan 31 09:25:31 	filterdns: unable to open configuration file
Jan 31 09:25:31 	php: : The command '/usr/local/sbin/filterdns -p /var/run/filterdns-ipsec.pid -i 60 -c /var/etc/filterdns-ipsec.hosts -d 1' returned exit code '71', the output was 'filterdns: open file'

It appears that you have fixed the "_" vs "-" error but the "nds" vs "dns" error is still there. The command in the log message above expects to find the file filterdns-ipsec.hosts but the actual file in /var/etc is spelled like this: filternds-ipsec.hosts. Note the transposition of the letters "n" and "d".

# ls /var/etc/ | grep filter
filternds-ipsec.hosts

I will continue to test this in new builds and I will report back here.

jimp

Should be fixed in new snaps.

cyboc

Thanks Jimp,

I also just noticed another error message in the build 2.0-BETA5 (i386) built on Mon Jan 31 07:16:37 EST 2011. I don't know if it is already fixed in the next snaps but I thought I should report it anyway.

When I uncheck "Enable IPSec", hit Save, then check "Enable IPSec" and hit Save again, I see the following error message at the top of the page:

Warning: Invalid argument supplied for foreach() in /etc/inc/vpn.inc on line 908

You can see it in the attached screenshot.

Here is the code in that spot, it it helps:


/* start filterdns, if necessary */
if (count($filterdns_list) > 0) {
  $interval = 60;
  if (!empty($ipseccfg['dns-interval']) && is_numeric($ipseccfg['dns-interval']))
    $interval = $ipseccfg['dns-interval'];

  $hostnames = "";
  array_unique($filterdns_list);
  foreach ($hostname as $filterdns_list) ###### <---line 908
    $hostnames .= "cmd {$hostname} '/etc/rc.newipsecdns'\n";
  file_put_contents("{$g['varetc_path']}/filternds-ipsec.hosts", $hostnames);

  killbypid("{$g['varrun_path']}/filterdns-ipsec.pid");
  mwexec("/usr/local/sbin/filterdns -p {$g['varrun_path']}/filterdns-ipsec.pid -i {$interval} -c {$g['varetc_path']}/filterdns-ipsec.hosts -d 1");
}

InvalidArgument-vpninc.PNG_thumb

jimp

Fixed now.

That should have been:

foreach ($filterdns_list as $hostname)

cyboc

Hi Jimp,

Thanks for your very quick response. I applied your changes locally, in advance of the next snapshots. The error messages are now gone from the system log and from the IPSec config page. However, when the IP address on the dynamic side of the tunnel changes, the tunnel does not come back up. The change is detected by filterdns (because the system log shows "php: : IPSEC: One or more IPSEC tunnel endpoints has changed IP. Refreshing.") but the tunnel just does not come back up.

Attached are a series of obfuscated screenshots from both the static side and the dynamic before and after the dyndns IP address change. The address of the dynamic side was changed from x.x.x.198 to x.x.x.195. The address of the static side is 216.x.x.x. The are a lot of screenshots so please pay close attention to the words "staticSide", "dynamicSide", "Before" and "After" in the file names to figure out which is which.

(the screenshots are spread out over the next couple of posts because of attachment limits in this forum)

It is interesting to note that after the address change, the racoon service on the static side stopped, as shown in the screenshot "staticSide-ServicesStatus-AfterDyndnsChange.PNG". To get the tunnel back up, I had to start the stopped racoon service on the static side and restart the running racoon service on the dynamic side.

staticSide-IPSecStatus-BeforeDyndnsChange.PNG_thumb

staticSide-IPSecSAD-BeforeDyndnsChange.PNG_thumb

staticSide-IPSecSPD-BeforeDyndnsChange.PNG_thumb

staticSide-IPSecLog-BeforeDyndnsChange.PNG_thumb

cyboc

more screeshots

dynamicSide-IPSecStatus-BeforeDyndnsChange.PNG_thumb

dynamicSide-IPSecSAD-BeforeDyndnsChange.PNG_thumb

dynamicSide-IPSecSPD-BeforeDyndnsChange.PNG_thumb

dynamicSide-IPSecLog-BeforeDyndnsChange.PNG_thumb

cyboc

even more screenshots

staticSide-IPSecStatus-AfterDyndnsChange.PNG_thumb

staticSide-IPSecSAD-AfterDyndnsChange.PNG_thumb

staticSide-IPSecSPD-AfterDyndnsChange.PNG_thumb

staticSide-IPSecLog-AfterDyndnsChange.PNG_thumb

staticSide-ServicesStatus-AfterDyndnsChange.PNG_thumb

staticSide-SystemLog-AfterDyndnsChange.PNG_thumb

cyboc

Last set of screenshots. Phew!

dynamicSide-IPSecStatus-AfterDyndnsChange.PNG_thumb

dynamicSide-IPSecSAD-AfterDyndnsChange.PNG_thumb

dynamicSide-IPSecSPD-AfterDyndnsChange.PNG_thumb

dynamicSide-IPSecLog-AfterDyndnsChange.PNG_thumb

dynamicSide-ServicesStatus-AfterDyndnsChange.PNG_thumb

cegner

I'm encountering the same problem. Did you find a solution for it?

Christof

cyboc

@cegner:

I'm encountering the same problem. Did you find a solution for it?

Christof

Did you try the latest firmware version?

cegner

Yes, but the problem still exists.

2.0-RC1 (i386)
built on Fri Mar 4 23:09:48 EST 2011

eri--

Please post again te system logs and ipsec logs

cegner

Here you go.

At 04:00 the PPPoE connection was terminated. After the reconnect the IPSEC tunnel does not come up again (for hours) without a reload as the remote peer IP address has changed. It does not seem to lookup the hostname again.

Mar 7 03:20:37 fw racoon: INFO: initiate new phase 2 negotiation: X.X.219.99[500]<=>X.X.197.44[500]
Mar 7 03:20:37 fw racoon: INFO: IPsec-SA expired: ESP/Tunnel X.X.197.44[500]->X.X0.219.99[500] spi=143188784(0x888e330)
Mar 7 03:20:37 fw racoon: INFO: IPsec-SA established: ESP X.X.219.99[500]->X.X.197.44[500] spi=201427959(0xc018bf7)
Mar 7 03:20:37 fw racoon: INFO: IPsec-SA established: ESP X.X.219.99[500]->X.X.197.44[500] spi=13656620(0xd0622c)
Mar 7 04:00:13 fw racoon: INFO: caught signal 15
Mar 7 04:00:13 fw racoon: INFO: racoon process 30653 shutdown
Mar 7 04:00:20 fw racoon: INFO: @(#)ipsec-tools 0.8.0.RC (http://ipsec-tools.sourceforge.net)
Mar 7 04:00:20 fw racoon: INFO: @(#)This product linked OpenSSL 0.9.8n 24 Mar 2010 (http://www.openssl.org/)
Mar 7 04:00:20 fw racoon: INFO: Reading configuration from "/var/etc/racoon.conf"
Mar 7 04:00:20 fw racoon: INFO: X.X.200.246[4500] used for NAT-T
Mar 7 04:00:20 fw racoon: INFO: X.X.200.246[4500] used as isakmp port (fd=19)
Mar 7 04:00:20 fw racoon: INFO: X.X.200.246[500] used for NAT-T
Mar 7 04:00:20 fw racoon: INFO: X.X.200.246[500] used as isakmp port (fd=20)
Mar 7 04:00:20 fw racoon: INFO: unsupported PF_KEY message REGISTER
Mar 7 04:00:20 fw racoon: ERROR: such policy already exists. anyway replace it: 192.168.1.254/32[0] 192.168.1.0/24[0] proto=any dir=out
Mar 7 04:00:20 fw racoon: ERROR: such policy already exists. anyway replace it: 192.168.1.0/24[0] 192.168.1.254/32[0] proto=any dir=in
Mar 7 04:00:20 fw racoon: ERROR: such policy already exists. anyway replace it: 192.168.1.0/24[0] 192.168.10.0/24[0] proto=any dir=out
Mar 7 04:00:20 fw racoon: ERROR: such policy already exists. anyway replace it: 192.168.10.0/24[0] 192.168.1.0/24[0] proto=any dir=in
Mar 7 04:00:29 fw racoon: INFO: IPsec-SA request for X.X.197.44 queued due to no phase1 found.
Mar 7 04:00:29 fw racoon: INFO: initiate new phase 1 negotiation: X.X.200.246[500]<=>X.X.197.44[500]
Mar 7 04:00:29 fw racoon: INFO: begin Aggressive mode.
Mar 7 04:01:01 fw racoon: [X.X.197.44] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP X.X.197.44[0]->X.X.200.246[0]
Mar 7 04:01:01 fw racoon: INFO: delete phase 2 handler.
Mar 7 04:01:19 fw racoon: ERROR: phase1 negotiation failed due to time up. 1f856cf72bf9c322:0000000000000000
Mar 7 04:04:55 fw racoon: INFO: IPsec-SA request for X.X.197.44 queued due to no phase1 found.
Mar 7 04:04:55 fw racoon: INFO: initiate new phase 1 negotiation: X.X.200.246[500]<=>X.X.197.44[500]
Mar 7 04:04:55 fw racoon: INFO: begin Aggressive mode.
Mar 7 04:05:26 fw racoon: [X.X.197.44] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP X.X.197.44[0]->X.X.200.246[0]