IPsec Point-to-Point Fails Hard
-
My organization has been running an IPsec tunnel for about a year with both ends running the latest version of pfSense (2.1.4 as of this writing, previously 2.1.3).
We've had problems on and off, but about 99% of the time its been stable (not good enough for our standards, mind you.)
in the past six months, we've ironed out almost all of our major bugs, but it's still faulted out a couple of times, and I haven't been able to find anything to help me understand what's being logged when the failure happens.
This is a sanitized copy of the logs covering our most recent outage:
Aug 19 19:54:10 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=228093799(0xd986f67) Aug 19 19:54:10 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=159771144(0x985ea08) Aug 19 19:54:10 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:43 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=121898106(0x744047a) Aug 19 19:50:43 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=119648669(0x721b19d) Aug 19 19:50:43 racoon: [VPN->RemoteSite]: INFO: initiate new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:30 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=235549440(0xe0a3300) Aug 19 19:50:30 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=267095629(0xfeb8e4d) Aug 19 19:50:30 racoon: [VPN->RemoteSite]: INFO: initiate new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:26 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=29527171(0x1c28c83) Aug 19 19:50:26 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=15104821(0xe67b35) Aug 19 19:50:25 racoon: [VPN->RemoteSite]: INFO: initiate new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:25 racoon: [VPN->RemoteSite]: INFO: ISAKMP-SA established {ISP 1 Public IP 1}[500]-{RemoteIP}[500] spi:dad589bca3717502:5a5f569abd313e55 Aug 19 19:50:25 racoon: INFO: received Vendor ID: DPD Aug 19 19:50:25 racoon: INFO: received broken Microsoft ID: FRAGMENTATION Aug 19 19:50:25 racoon: INFO: begin Identity Protection mode. Aug 19 19:50:25 racoon: [VPN->RemoteSite]: INFO: respond new phase 1 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:25 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=178848155(0xaa9019b) Aug 19 19:50:25 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=27143013(0x19e2b65) Aug 19 19:50:24 racoon: [VPN->RemoteSite]: INFO: initiate new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:22 racoon: INFO: purged IPsec-SA proto_id=ESP spi=263322175. Aug 19 19:50:22 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=106480519(0x658c387) Aug 19 19:50:22 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=263322175(0xfb1fa3f) Aug 19 19:50:22 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=180607411(0xac3d9b3) Aug 19 19:50:22 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=202609879(0xc1394d7) Aug 19 19:50:22 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=49876078(0x2f90c6e) Aug 19 19:50:21 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=106480519(0x658c387) Aug 19 19:50:21 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=174603812(0xa683e24) Aug 19 19:50:21 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:21 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:21 racoon: [VPN->RemoteSite]: INFO: initiate new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:20 racoon: [VPN->RemoteSite]: INFO: ISAKMP-SA established {ISP 1 Public IP 1}[500]-{RemoteIP}[500] spi:b939b05f89ee26a8:e254e4374b0959f7 Aug 19 19:50:20 racoon: INFO: received broken Microsoft ID: FRAGMENTATION Aug 19 19:50:20 racoon: INFO: received Vendor ID: DPD Aug 19 19:50:20 racoon: INFO: begin Identity Protection mode. Aug 19 19:50:20 racoon: [VPN->RemoteSite]: INFO: initiate new phase 1 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:50:20 racoon: [VPN->RemoteSite]: INFO: IPsec-SA request for {RemoteIP} queued due to no phase1 found. Aug 19 19:50:19 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:19 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:19 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:19 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:19 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:19 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:19 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:15 racoon: [VPN->RemoteSite]: [{RemoteIP}] ERROR: exchange Identity Protection not allowed in any applicable rmconf. Aug 19 19:50:11 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:11 racoon: [VPN->RemoteSite]: INFO: ISAKMP-SA deleted {ISP 1 Public IP 1}[500]-{RemoteIP}[500] spi:2ececdaa4598b6a2:5c6e69759bcc753a Aug 19 19:50:11 racoon: [Self]: INFO: 192.168.99.1[4500] used as isakmp port (fd=43) Aug 19 19:50:11 racoon: [Self]: INFO: 192.168.99.1[4500] used for NAT-T Aug 19 19:50:11 racoon: [Self]: INFO: 192.168.99.1[500] used as isakmp port (fd=42) Aug 19 19:50:11 racoon: [Self]: INFO: 192.168.99.1[500] used for NAT-T Aug 19 19:50:11 racoon: INFO: fe80:9::4e02:89ff:fe09:4ae[4500] used as isakmp port (fd=41) Aug 19 19:50:11 racoon: INFO: fe80:9::4e02:89ff:fe09:4ae[500] used as isakmp port (fd=40) Aug 19 19:50:11 racoon: [Self]: INFO: fe80:5::1[4500] used as isakmp port (fd=39) Aug 19 19:50:11 racoon: [Self]: INFO: fe80:5::1[500] used as isakmp port (fd=38) Aug 19 19:50:11 racoon: [Self]: INFO: ::1[4500] used as isakmp port (fd=37) Aug 19 19:50:11 racoon: [Self]: INFO: ::1[500] used as isakmp port (fd=36) Aug 19 19:50:11 racoon: [Self]: INFO: 127.0.0.1[4500] used as isakmp port (fd=35) Aug 19 19:50:11 racoon: [Self]: INFO: 127.0.0.1[4500] used for NAT-T Aug 19 19:50:11 racoon: [Self]: INFO: 127.0.0.1[500] used as isakmp port (fd=34) Aug 19 19:50:11 racoon: [Self]: INFO: 127.0.0.1[500] used for NAT-T Aug 19 19:50:11 racoon: INFO: fe80:4::4e02:89ff:fe09:4b1[4500] used as isakmp port (fd=33) Aug 19 19:50:11 racoon: INFO: fe80:4::4e02:89ff:fe09:4b1[500] used as isakmp port (fd=32) Aug 19 19:50:11 racoon: [Self]: INFO: 10.1.20.1[4500] used as isakmp port (fd=31) Aug 19 19:50:11 racoon: [Self]: INFO: 10.1.20.1[4500] used for NAT-T Aug 19 19:50:11 racoon: [Self]: INFO: 10.1.20.1[500] used as isakmp port (fd=30) Aug 19 19:50:11 racoon: [Self]: INFO: 10.1.20.1[500] used for NAT-T Aug 19 19:50:11 racoon: INFO: fe80:3::4e02:89ff:fe09:4b0[4500] used as isakmp port (fd=29) Aug 19 19:50:11 racoon: INFO: fe80:3::4e02:89ff:fe09:4b0[500] used as isakmp port (fd=28) Aug 19 19:50:11 racoon: [Self]: INFO: {ISP 2 Public IP 1}[4500] used as isakmp port (fd=27) Aug 19 19:50:11 racoon: [Self]: INFO: {ISP 2 Public IP 1}[4500] used for NAT-T Aug 19 19:50:11 racoon: [Self]: INFO: {ISP 2 Public IP 1}[500] used as isakmp port (fd=26) Aug 19 19:50:11 racoon: [Self]: INFO: {ISP 2 Public IP 1}[500] used for NAT-T Aug 19 19:50:11 racoon: [Self]: INFO: {ISP 1 Public IP 2}[4500] used as isakmp port (fd=25) Aug 19 19:50:11 racoon: [Self]: INFO: {ISP 1 Public IP 2}[4500] used for NAT-T Aug 19 19:50:11 racoon: [Self]: INFO: {ISP 1 Public IP 2}[500] used as isakmp port (fd=24) Aug 19 19:50:11 racoon: [Self]: INFO: {ISP 1 Public IP 2}[500] used for NAT-T Aug 19 19:50:11 racoon: INFO: fe80:2::4e02:89ff:fe09:4af[4500] used as isakmp port (fd=23) Aug 19 19:50:11 racoon: INFO: fe80:2::4e02:89ff:fe09:4af[500] used as isakmp port (fd=22) Aug 19 19:50:11 racoon: INFO: fe80:1::4e02:89ff:fe09:4ae[4500] used as isakmp port (fd=19) Aug 19 19:50:11 racoon: INFO: fe80:1::4e02:89ff:fe09:4ae[500] used as isakmp port (fd=18) Aug 19 19:50:11 racoon: [Self]: INFO: 192.168.1.1[4500] used as isakmp port (fd=17) Aug 19 19:50:11 racoon: [Self]: INFO: 192.168.1.1[4500] used for NAT-T Aug 19 19:50:11 racoon: [Self]: INFO: 192.168.1.1[500] used as isakmp port (fd=16) Aug 19 19:50:11 racoon: [Self]: INFO: 192.168.1.1[500] used for NAT-T Aug 19 19:50:11 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:11 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:11 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:11 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:11 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=152426221(0x915d6ed) Aug 19 19:50:11 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=62483466(0x3b96c0a) Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=8617416(0x837dc8) Aug 19 19:50:11 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=130219438(0x7c2fdae) Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=216079264(0xce11ba0) Aug 19 19:50:11 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=230695843(0xdc023a3) Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=20938334(0x13f7e5e) Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=102825367(0x620fd97) Aug 19 19:50:11 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=144683486(0x89fb1de) Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=119558535(0x7205187) Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=156127355(0x94e507b) Aug 19 19:50:11 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=36462564(0x22c5fe4) Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=185997930(0xb161a6a) Aug 19 19:50:11 racoon: ERROR: no iph2 found: ESP {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=192406940(0xb77e59c) Aug 19 19:50:11 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=80335979(0x4c9d46b) Aug 19 19:50:11 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=32256311(0x1ec3137) Aug 19 19:50:11 racoon: INFO: unsupported PF_KEY message REGISTER Aug 19 19:20:04 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=96848159(0x5c5c91f) Aug 19 19:20:03 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=36462564(0x22c5fe4) Aug 19 19:20:03 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=156127355(0x94e507b) Aug 19 19:20:03 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:18:06 racoon: ERROR: pfkey DELETE received: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=27231381(0x19f8495) Aug 19 19:14:33 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=144683486(0x89fb1de) Aug 19 19:14:33 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=102825367(0x620fd97) Aug 19 19:14:33 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:13:12 racoon: ERROR: {RemoteIP} give up to get IPsec-SA due to time up to wait. Aug 19 19:13:08 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=32256311(0x1ec3137) Aug 19 19:13:08 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=192406940(0xb77e59c) Aug 19 19:13:07 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:12:42 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:10:55 racoon: ERROR: {RemoteIP} give up to get IPsec-SA due to time up to wait. Aug 19 19:10:55 racoon: ERROR: {RemoteIP} give up to get IPsec-SA due to time up to wait. Aug 19 19:10:49 racoon: [VPN->RemoteSite]: INFO: ISAKMP-SA deleted {ISP 1 Public IP 1}[500]-{RemoteIP}[500] spi:608011b495ce8d0b:e32c2fafe8d1e90d Aug 19 19:10:49 racoon: INFO: purged ISAKMP-SA spi=608011b495ce8d0b:e32c2fafe8d1e90d. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=152426221 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=62483466 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=8617416 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=130219438 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=216079264 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=230695843 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=20938334 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=27231381 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=119558535 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=96848159 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=185997930 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: keeping IPsec-SA spi=80335979 - found valid ISAKMP-SA spi=2ececdaa4598b6a2:5c6e69759bcc753a. Aug 19 19:10:49 racoon: INFO: purging ISAKMP-SA spi=608011b495ce8d0b:e32c2fafe8d1e90d. Aug 19 19:10:49 racoon: [VPN->RemoteSite]: [{RemoteIP}] INFO: DPD: remote (ISAKMP-SA spi=608011b495ce8d0b:e32c2fafe8d1e90d) seems to be dead. Aug 19 19:10:25 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:10:25 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 19:10:24 racoon: NOTIFY: the packet is retransmitted by {RemoteIP}[500] (1). Aug 19 19:10:24 racoon: WARNING: the packet retransmitted in a short time from {RemoteIP}[500] Aug 19 19:10:24 racoon: [VPN->RemoteSite]: INFO: ISAKMP-SA established {ISP 1 Public IP 1}[500]-{RemoteIP}[500] spi:2ececdaa4598b6a2:5c6e69759bcc753a Aug 19 19:10:24 racoon: NOTIFY: the packet is retransmitted by {RemoteIP}[500] (1). Aug 19 19:10:24 racoon: WARNING: the packet retransmitted in a short time from {RemoteIP}[500] Aug 19 19:10:14 racoon: INFO: received Vendor ID: DPD Aug 19 19:10:14 racoon: INFO: received broken Microsoft ID: FRAGMENTATION Aug 19 19:10:14 racoon: INFO: begin Identity Protection mode. Aug 19 19:10:14 racoon: [VPN->RemoteSite]: INFO: respond new phase 1 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 17:04:00 racoon: [VPN->RemoteSite]: INFO: ISAKMP-SA deleted {ISP 1 Public IP 1}[500]-{RemoteIP}[500] spi:3ec2fb2ec559eba7:e92a52e05e6bd965 Aug 19 17:04:00 racoon: [VPN->RemoteSite]: INFO: ISAKMP-SA expired {ISP 1 Public IP 1}[500]-{RemoteIP}[500] spi:3ec2fb2ec559eba7:e92a52e05e6bd965 Aug 19 14:42:39 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=96848159(0x5c5c91f) Aug 19 14:42:39 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=119558535(0x7205187) Aug 19 14:42:39 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 14:42:39 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP/Tunnel {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=75900866(0x48627c2) Aug 19 14:42:39 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=6229344(0x5f0d60) Aug 19 14:42:10 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=130219438(0x7c2fdae) Aug 19 14:42:10 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=8617416(0x837dc8) Aug 19 14:42:10 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP/Tunnel {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=33217454(0x1fadbae) Aug 19 14:42:10 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=200043994(0xbec6dda) Aug 19 14:42:10 racoon: [VPN->RemoteSite]: INFO: respond new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 14:40:57 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=27231381(0x19f8495) Aug 19 14:40:57 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=20938334(0x13f7e5e) Aug 19 14:40:57 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP/Tunnel {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=48479228(0x2e3bbfc) Aug 19 14:40:57 racoon: [VPN->RemoteSite]: INFO: initiate new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 14:40:57 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=188290008(0xb3913d8) Aug 19 14:40:54 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=80335979(0x4c9d46b) Aug 19 14:40:54 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=185997930(0xb161a6a) Aug 19 14:40:54 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP/Tunnel {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=72744627(0x455feb3) Aug 19 14:40:54 racoon: [VPN->RemoteSite]: INFO: initiate new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 14:40:54 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=89756263(0x5599267) Aug 19 14:40:40 racoon: INFO: purged IPsec-SA proto_id=ESP spi=9235643. Aug 19 14:40:40 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=62483466(0x3b96c0a) Aug 19 14:40:40 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=152426221(0x915d6ed) Aug 19 14:40:40 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP/Tunnel {RemoteIP}[500]->{ISP 1 Public IP 1}[500] spi=58916423(0x382fe47) Aug 19 14:40:40 racoon: [VPN->RemoteSite]: INFO: initiate new phase 2 negotiation: {ISP 1 Public IP 1}[500]<=>{RemoteIP}[500] Aug 19 14:40:40 racoon: [VPN->RemoteSite]: INFO: IPsec-SA expired: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=9235643(0x8cecbb) Aug 19 14:40:39 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=230695843(0xdc023a3) Aug 19 14:40:39 racoon: [VPN->RemoteSite]: INFO: IPsec-SA established: ESP {ISP 1 Public IP 1}[500]->{RemoteIP}[500] spi=216079264(0xce11ba0)The entries around 19:10 reflect activity during the period of trouble.
Entries starting at 19:50:11 and running to the top show re-establishment after manual intervention.
My best guess is that DPD is responsible for the failure to re-establish, but racoon's logging is so cryptic and documentation thereof is so sparse that I don't feel like I can confidently say anything about this.
If anyone can point me to some quality reference for racoon's error messages (I couldn't find anything here, on the main page, on KAME's site, or on IPsecTools's site,) I would be immensely appreciative.
Likewise, if anyone can point out exactly why this isn't reconnecting from the logs, it'd be a big help.
Thanks!
-
..some of the stories you tell made me switch to openVPN tunnels with good results. Maybe you should give it a try, with a pre-shared secret a site-to-site tunnel is not that a big issue with 2.1.4…
-
I saw others suggest the same in other threads. It's certainly worth consideration, I just have to do some research to make sure it'd do what we need it to without compromising security :)
-
Have you tried disabling DPD ?
i have had some problems on a long latancy ipsec tunnel where DPD was taking the tunnel down and not re-establishing it. Disabling it resolved the issue for me.Cheers - Thor
-
Thanks, Thor!
The tunnels have remained pretty stable for the past few days since I relaxed DPD's tolerances, so I'm keeping my fingers crossed. However, if they start to flake out on me again, that is my next step :)