site to site VPN keeps going down

Matt James <[email protected]> Wed, 1 Jul 2015 23:03:16 -0600
Newsgroups	gmane.comp.security.ipcop.user
Message-ID	<CAAiWk=VOef=2FXDyDhtL9cEmu3KF2M_yUjiRdS8TPEKvrndXqA@mail.gmail.com>
Folks,
   I have an ongoing issue.  I have a client who has an office IPcop and a
home IPcop.  The idea is to keep the two connected via IPSEC VPN.  Office
has a static IP, home has a dynamic IP and uses dyndns.org to update the
DNS record.

The VPN might stay up for several days / weeks / months and then go down
over and over then back to up for days / weeks / months.

My first reaction was that the dynamic DNS wasn't updating fast enough and
that it was just taking some time to flush the DNS through the tubes and
have everything come back up.

Well, after some investigation tonight and looking at logs, processes,
etc.  It appears that I had not had an IP change in over a month but the
connection had been bouncing up and down for the last week or more.
Further investigation revealed several dozen pluto processes on the home
end like this:

28600 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

28601 root       9   0   548  544  480 S  0.0  0.1   0:00.00
logger

28602 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

28605 root       8   0  1156 1152  984 S  0.0  0.1   0:00.01
_plutoload

28606 root       9   0  1420 1412 1236 S  0.0  0.1   0:00.97
pluto

28609 root       9   0   372  368  308 S  0.0  0.0   0:00.00
_pluto_adns

22480 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

22481 root       9   0   548  544  480 S  0.0  0.1   0:00.00
logger

22482 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

22485 root       8   0  1144 1140  972 S  0.0  0.1   0:00.00
_plutoload

22486 root       9   0  1436 1428 1252 S  0.0  0.1   0:00.91
pluto

22489 root       9   0   372  368  308 S  0.0  0.0   0:00.00
_pluto_adns

12006 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

12007 root       9   0   548  544  480 S  0.0  0.1   0:00.00
logger

12008 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

12011 root       8   0  1156 1152  984 S  0.0  0.1   0:00.00
_plutoload

12012 root       9   0  1232 1224 1072 S  0.0  0.1   0:00.75
pluto

12020 root       9   0   372  368  308 S  0.0  0.0   0:00.00
_pluto_adns

14959 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

14960 root       9   0   548  544  480 S  0.0  0.1   0:00.00
logger

14961 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

14964 root       8   0  1144 1140  972 S  0.0  0.1   0:00.01
_plutoload

14965 root       9   0  1436 1428 1252 S  0.0  0.1   0:00.93
pluto

14968 root       9   0   372  368  308 S  0.0  0.0   0:00.00
_pluto_adns

29721 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00
_plutorun

29722 root       9   0   548  544  480 S  0.0  0.1   0:00.00
logger

29723 root       9   0  1160 1156 1076 S  0.0  0.1   0:00.00 _plutorun


I also saw maybe 4 or 5 on the office end that looked similar to the above.

Here is the ps output:

root     15115  0.0  0.2   2440  1156 ?        S    Jun17   0:00 /bin/sh
/usr/lib/ipsec/_plutorun --debug none --uniqueids yes --nocrsend
--strictcrlpolicy  --crlcheckinterval "" --nat_traversal yes --keep_alive
--force_keepalive  --disable_port_floating  --virtual_private %v4:
10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16,%v4:!10.0.8.0/255.255.255.0,%v4:!10.10.10.0/255.255.255.0,%v4:!10.0.2.0/255.255.255.0
--dump  --load %search --start %search --wait  --pre  --post  --log
daemon.error --pid /var/run/pluto.pid
root     15116  0.0  0.1   1540   544 ?        S    Jun17   0:00 logger -p
daemon.error -t ipsec__plutorun
root     15117  0.0  0.2   2440  1156 ?        S    Jun17   0:00 /bin/sh
/usr/lib/ipsec/_plutorun --debug none --uniqueids yes --nocrsend
--strictcrlpolicy  --crlcheckinterval "" --nat_traversal yes --keep_alive
--force_keepalive  --disable_port_floating  --virtual_private %v4:
10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16,%v4:!10.0.8.0/255.255.255.0,%v4:!10.10.10.0/255.255.255.0,%v4:!10.0.2.0/255.255.255.0
--dump  --load %search --start %search --wait  --pre  --post  --log
daemon.error --pid /var/run/pluto.pid
root     15118  0.0  0.2   2424  1140 ?        S    Jun17   0:00 /bin/sh
/usr/lib/ipsec/_plutoload --load %search --start %search --wait  --post
root     15121  0.0  0.2   2944  1440 ?        S    Jun17   0:00
/usr/lib/ipsec/pluto --nofork --debug-none --uniqueids --nat_traversal
--virtual_private %v4:
10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16,%v4:!10.0.8.0/255.255.255.0,%v4:!10.10.10.0/255.255.255.0,%v4:!10.0.2.0/255.255.255.0
root     15124  0.0  0.0   1608   368 ?        S    Jun17   0:00
_pluto_adns 7 10


Another odd observation:  When I would disable the vpn connections on
either end of the tunnel, I'd still get lots of ipsec messages in the logs
like this (IPs removed for fun):

Jul  2 04:16:23 ipcop pluto[14965]: ERROR: "SAT" #53583: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:16:23 ipcop pluto[28606]: ERROR: "SAT" #62703: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:16:23 ipcop pluto[29727]: ERROR: "SAT" #53370: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:16:23 ipcop pluto[22486]: ERROR: "SAT" #54018: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:16:23 ipcop pluto[2232]: packet from X.X.X.X:500: Phase 1 message
is part of an unknown exchange
Jul  2 04:16:23 ipcop pluto[2232]: packet from X.X.X.X:500: Phase 1 message
is part of an unknown exchange
Jul  2 04:16:33 ipcop pluto[2928]: ERROR: "SAT" #45678: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:16:33 ipcop pluto[2232]: packet from X.X.X.X:500: Phase 1 message
is part of an unknown exchange
Jul  2 04:16:33 ipcop pluto[2232]: packet from X.X.X.X500: Phase 1 message
is part of an unknown exchange
Jul  2 04:16:53 ipcop pluto[2232]: packet from X.X.X.X:500: Phase 1 message
is part of an unknown exchange
Jul  2 04:17:03 ipcop pluto[14965]: ERROR: "SAT" #53583: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:03 ipcop pluto[28606]: ERROR: "SAT" #62703: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:03 ipcop pluto[29727]: ERROR: "SAT" #53370: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:03 ipcop pluto[22486]: ERROR: "SAT" #54018: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:03 ipcop pluto[2232]: packet from X.X.X.X:500: Phase 1 message
is part of an unknown exchange
Jul  2 04:17:13 ipcop pluto[2928]: ERROR: "SAT" #45678: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:13 ipcop pluto[2232]: packet from X.X.X.X:500: Phase 1 message
is part of an unknown exchange
Jul  2 04:17:23 ipcop pluto[19540]: "SAT" #1712: max number of
retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our
first Quick Mode message: perhaps peer likes no proposal
Jul  2 04:17:23 ipcop pluto[19540]: "SAT" #1712: starting keying attempt 70
of an unlimited number
Jul  2 04:17:23 ipcop pluto[19540]: "SAT" #1713: initiating Quick Mode
PSK+ENCRYPT+TUNNEL to replace #1712
Jul  2 04:17:33 ipcop pluto[2232]: packet from X.X.X.X:500: Phase 1 message
is part of an unknown exchange
Jul  2 04:17:43 ipcop pluto[14965]: ERROR: "SAT" #53583: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:43 ipcop pluto[28606]: ERROR: "SAT" #62703: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:43 ipcop pluto[29727]: ERROR: "SAT" #53370: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:43 ipcop pluto[22486]: ERROR: "SAT" #54018: sendto on ppp0 to
X.X.X.X:500 failed in EVENT_RETRANSMIT. Errno 22: Invalid argument
Jul  2 04:17:43 ipcop pluto[2232]: packet from X.X.X.X:500: Phase 1 message
is part of an unknown exchange

What this tells me is that I had lots of processes all trying to establish
VPN tunnels all at once.  So, I turned off the VPN service on either end
and did a "killall pluto" on either end.  I then turned on the VPN on
either end and the tunnel immediately  came right up - no errors.

So - (drum roll please....)  Why the extra pluto processes over time?  How
do I get the thing to go down clean and come back up clean?  I still think
this is related to the dynamic IP but I guess I don't know what else to
look at.

Help?

Thanks in advance,

Matt James
------------------------------------------------------------------------------
Don't Limit Your Business. Reach for the Cloud.
GigeNET's Cloud Solutions provide you with the tools and support that
you need to offload your IT needs and focus on growing your business.
Configured For All Businesses. Start Your Cloud Today.
https://www.gigenetcloud.com/
_______________________________________________
IPCop-user mailing list
[email protected]
Manage your subscription or unsubscribe
https://lists.sourceforge.net/lists/listinfo/ipcop-user