[Openswan Users] Dead Peer Detection restart causes tunnel to be established, but afterwards cannot ping from either side

Geekman the1geekman at gmail.com
Thu Oct 6 00:50:49 EDT 2011


Hi,

Just adding a bit more info. This time I left the tunnel to timeout
for a while longer. About two hours. Just to see what would happen if
I waited a little longer.

It seems to me that, fairly consistently, whenever Neo is the one
trying to initiate a connection, it doesn't work on either end, but if
the remote end gets to initiate, its fine.

In any case, here's the log entries:


Here I have restarted IPSec, the tunnel comes up and pings time out, as usual:

…

Oct  6 13:39:29 neo pluto[22096]: "CustomerTunnel" #4: Dead Peer
Detection (RFC 3706): enabled
Oct  6 13:39:29 neo pluto[22096]: "CustomerTunnel" #4: transition from
state STATE_QUICK_I1 to state STATE_QUICK_I2
Oct  6 13:39:29 neo pluto[22096]: "CustomerTunnel" #4: STATE_QUICK_I2:
sent QI2, IPsec SA established tunnel mode {ESP=>0x3bdb8c7d
<0xd7142aab xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
Oct  6 13:39:29 neo pluto[22096]: "CustomerTunnel" #1: ignoring Delete
SA payload: PROTO_IPSEC_ESP SA(0x3bdb8c7c) not found (maybe expired)
Oct  6 13:39:29 neo pluto[22096]: "CustomerTunnel" #1: received and
ignored informational message



The below occurs, but it seems that the pings are still timing out. No effect.


Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: initiating Main
Mode to replace #1
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: received Vendor
ID payload [Dead Peer Detection]
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: transition from
state STATE_MAIN_I1 to state STATE_MAIN_I2
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: STATE_MAIN_I2:
sent MI2, expecting MR2
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: transition from
state STATE_MAIN_I2 to state STATE_MAIN_I3
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: STATE_MAIN_I3:
sent MI3, expecting MR3
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: Main mode peer
ID is ID_IPV4_ADDR: 'REMOTE_IP'
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: transition from
state STATE_MAIN_I3 to state STATE_MAIN_I4
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: STATE_MAIN_I4:
ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
prf=oakley_sha group=modp1536}
Oct  6 14:24:47 neo pluto[22096]: "CustomerTunnel" #6: Dead Peer
Detection (RFC 3706): enabled
Oct  6 14:24:55 neo pluto[22096]: "CustomerTunnel" #6: DPD: unexpected
R_U_THERE_ACK packet with sequence number 1028



When this occurs, one hour later, the pings start to work.


Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #6: the peer
proposed: 172.16.0.0/24:0/0 -> 192.168.1.0/24:0/0
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9: responding to
Quick Mode proposal {msgid:3edf4fd3}
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9:     us:
172.16.0.0/24===NEO_IP<NEO_IP>[+S=C]---NEO_NEXTHOP
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9:   them:
REMOTE_NEXTHOP---REMOTE_IP<REMOTE_IP>[+S=C]===192.168.1.0/24
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9: keeping
refhim=4294901761 during rekey
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9: transition from
state STATE_QUICK_R0 to state STATE_QUICK_R1
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9: STATE_QUICK_R1:
sent QR1, inbound IPsec SA installed, expecting QI2
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9: Dead Peer
Detection (RFC 3706): enabled
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9: transition from
state STATE_QUICK_R1 to state STATE_QUICK_R2
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #9: STATE_QUICK_R2:
IPsec SA established tunnel mode {ESP=>0x3bdb8c7e <0xfa5a4ebc
xfrm=AES_256-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #6: received Delete
SA(0x3bdb8c7d) payload: deleting IPSEC State #4
Oct  6 14:38:59 neo pluto[22096]: "CustomerTunnel" #6: received and
ignored informational message


Leaving it for a bit more, Neo tries to replace main mode again, and
subsequently, the tunnel stops working



Oct  6 15:13:21 neo pluto[22096]: "CustomerTunnel" #10: initiating
Main Mode to replace #6
Oct  6 15:13:21 neo pluto[22096]: "CustomerTunnel" #10: received
Vendor ID payload [Dead Peer Detection]
Oct  6 15:13:21 neo pluto[22096]: "CustomerTunnel" #10: transition
from state STATE_MAIN_I1 to state STATE_MAIN_I2
Oct  6 15:13:21 neo pluto[22096]: "CustomerTunnel" #10: STATE_MAIN_I2:
sent MI2, expecting MR2
Oct  6 15:13:22 neo pluto[22096]: "CustomerTunnel" #10: transition
from state STATE_MAIN_I2 to state STATE_MAIN_I3
Oct  6 15:13:22 neo pluto[22096]: "CustomerTunnel" #10: STATE_MAIN_I3:
sent MI3, expecting MR3
Oct  6 15:13:22 neo pluto[22096]: "CustomerTunnel" #10: Main mode peer
ID is ID_IPV4_ADDR: 'REMOTE_IP'
Oct  6 15:13:22 neo pluto[22096]: "CustomerTunnel" #10: transition
from state STATE_MAIN_I3 to state STATE_MAIN_I4
Oct  6 15:13:22 neo pluto[22096]: "CustomerTunnel" #10: STATE_MAIN_I4:
ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
prf=oakley_sha group=modp1536}
Oct  6 15:13:22 neo pluto[22096]: "CustomerTunnel" #10: Dead Peer
Detection (RFC 3706): enabled


Oct  6 15:34:29 neo pluto[22096]: "CustomerTunnel" #13: initiating
Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK to replace
#9 {using isakmp#10 msgid:e16ae394 proposal=defaults
pfsgroup=OAKLEY_GROUP_MODP1536}
Oct  6 15:34:30 neo pluto[22096]: "CustomerTunnel" #13: Dead Peer
Detection (RFC 3706): enabled
Oct  6 15:34:30 neo pluto[22096]: "CustomerTunnel" #13: transition
from state STATE_QUICK_I1 to state STATE_QUICK_I2
Oct  6 15:34:30 neo pluto[22096]: "CustomerTunnel" #13:
STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode
{ESP=>0x3bdb8c7f <0xd3253c2c xfrm=AES_128-HMAC_SHA1 NATOA=none
NATD=none DPD=enabled}
Oct  6 15:34:30 neo pluto[22096]: "CustomerTunnel" #10: received
Delete SA(0x3bdb8c7e) payload: deleting IPSEC State #9
Oct  6 15:34:30 neo pluto[22096]: "CustomerTunnel" #10: received and
ignored informational message




- And here's the VPN log entries on the remote RV042 device. The times
are off by a few hours, but you can match up each section easily:

Restarting

Oct 5 18:40:16 2011	    VPN Log	   received Delete SA payload:
deleting IPSEC State #167
Oct 5 18:40:16 2011	    VPN Log	   received Delete SA payload:
deleting ISAKMP State #165
Oct 5 18:40:16 2011	    VPN Log	   received Delete SA payload:
deleting ISAKMP State #168
Oct 5 18:40:18 2011	    VPN Log	   Ignoring Vendor ID payload
[4f45716c74725d4b...]
Oct 5 18:40:18 2011	    VPN Log	   Received Vendor ID payload Type =
[Dead Peer Detection]
Oct 5 18:40:18 2011	    VPN Log	   Ignoring Vendor ID payload
[4a131c8107035845...]
Oct 5 18:40:18 2011	    VPN Log	   Received Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-03]
Oct 5 18:40:18 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-02_n]
Oct 5 18:40:18 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-02]
Oct 5 18:40:18 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-00]
Oct 5 18:40:18 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 1st packet
Oct 5 18:40:18 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder Send Main Mode 2nd packet
Oct 5 18:40:18 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 3rd packet
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder send Main Mode 4th packet
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 5th packet
Oct 5 18:40:19 2011	    VPN Log	   Main mode peer ID is ID_IPV4_ADDR: 'NEO_IP'
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder Send Main Mode 6th packet
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] Main Mode
Phase 1 SA Established
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] Initiator
Cookies = 8e9d f518 49f 7c9
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] Responder
Cookies = 253e 26e8 b817 cbc
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Quick Mode 1st packet
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] Inbound
SPI value = 3bdb8c7d
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] Outbound
SPI value = d7142aab
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder send Quick Mode 2nd packet
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Quick Mode 3rd packet
Oct 5 18:40:19 2011	    VPN Log	   [Tunnel Negotiation Info] Quick
Mode Phase 2 SA Established, IPSec Tunnel Connected
Oct 5 18:40:19 2011	    VPN Log	   Dead Peer Detection Start, DPD
delay timer=10 sec timeout=10 sec
Oct 5 18:40:19 2011	    VPN Log	   Dead Peer Detection Start, DPD
delay timer=10 sec timeout=10 sec



Oct 5 19:25:42 2011	    VPN Log	   Ignoring Vendor ID payload
[4f45716c74725d4b...]
Oct 5 19:25:42 2011	    VPN Log	   Received Vendor ID payload Type =
[Dead Peer Detection]
Oct 5 19:25:42 2011	    VPN Log	   Ignoring Vendor ID payload
[4a131c8107035845...]
Oct 5 19:25:42 2011	    VPN Log	   Received Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-03]
Oct 5 19:25:42 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-02_n]
Oct 5 19:25:42 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-02]
Oct 5 19:25:42 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-00]
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 1st packet
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder Send Main Mode 2nd packet
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 3rd packet
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder send Main Mode 4th packet
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 5th packet
Oct 5 19:25:42 2011	    VPN Log	   Main mode peer ID is ID_IPV4_ADDR: 'NEO_IP'
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder Send Main Mode 6th packet
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] Main Mode
Phase 1 SA Established
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] Initiator
Cookies = c9f9 d520 c945 6f90
Oct 5 19:25:42 2011	    VPN Log	   [Tunnel Negotiation Info] Responder
Cookies = 3cd3 8765 3b28 2e0


Re-key, working


Oct 5 19:39:49 2011	    VPN Log	   initiating Quick Mode
PSK+ENCRYPT+TUNNEL+PFS to replace #170
Oct 5 19:39:49 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Initiator send Quick Mode 1st packet
Oct 5 19:39:49 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Initiator Received Quick Mode 2nd packet
Oct 5 19:39:50 2011	    VPN Log	   [Tunnel Negotiation Info] Inbound
SPI value = 3bdb8c7e
Oct 5 19:39:50 2011	    VPN Log	   [Tunnel Negotiation Info] Outbound
SPI value = fa5a4ebc
Oct 5 19:39:50 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Initiator Send Quick Mode 3rd packet
Oct 5 19:39:50 2011	    VPN Log	   [Tunnel Negotiation Info] Quick
Mode Phase 2 SA Established, IPSec Tunnel Connected
Oct 5 19:39:50 2011	    VPN Log	   Dead Peer Detection Start, DPD
delay timer=10 sec timeout=10 sec
Oct 5 19:39:50 2011	    VPN Log	   ignoring Delete SA payload: IPSEC
SA not found (maybe expired)
Oct 5 19:40:18 2011	    VPN Log	   Informational Exchange is for an
unknown (expired?) SA
Oct 5 19:40:18 2011	    VPN Log	   Informational Exchange is for an
unknown (expired?) SA


Stopped working after this:


Oct 5 20:14:02 2011	    VPN Log	   Ignoring Vendor ID payload
[4f45716c74725d4b...]
Oct 5 20:14:02 2011	    VPN Log	   Ignoring Vendor ID payload
[4f45716c74725d4b...]
Oct 5 20:14:02 2011	    VPN Log	   Received Vendor ID payload Type =
[Dead Peer Detection]
Oct 5 20:14:02 2011	    VPN Log	   Ignoring Vendor ID payload
[4a131c8107035845...]
Oct 5 20:14:02 2011	    VPN Log	   Received Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-03]
Oct 5 20:14:02 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-02_n]
Oct 5 20:14:02 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-02]
Oct 5 20:14:02 2011	    VPN Log	   Ignoring Vendor ID payload Type =
[draft-ietf-ipsec-nat-t-ike-00]
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 1st packet
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder Send Main Mode 2nd packet
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 3rd packet
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder send Main Mode 4th packet
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Main Mode 5th packet
Oct 5 20:14:02 2011	    VPN Log	   Main mode peer ID is ID_IPV4_ADDR: 'NEO_IP'
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder Send Main Mode 6th packet
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] Main Mode
Phase 1 SA Established
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] Initiator
Cookies = b37e 277c bc5a 90c6
Oct 5 20:14:02 2011	    VPN Log	   [Tunnel Negotiation Info] Responder
Cookies = a730 75a9 1d2 226a


Oct 5 20:25:42 2011	    VPN Log	   Informational Exchange is for an
unknown (expired?) SA
Oct 5 20:25:42 2011	    VPN Log	   Informational Exchange is for an
unknown (expired?) SA

Oct 5 20:35:22 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Quick Mode 1st packet
Oct 5 20:35:22 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Quick Mode 1st packet
Oct 5 20:35:23 2011	    VPN Log	   [Tunnel Negotiation Info] Inbound
SPI value = 3bdb8c7f
Oct 5 20:35:23 2011	    VPN Log	   [Tunnel Negotiation Info] Outbound
SPI value = d3253c2c
Oct 5 20:35:23 2011	    VPN Log	   [Tunnel Negotiation Info] >>>
Responder send Quick Mode 2nd packet
Oct 5 20:35:23 2011	    VPN Log	   [Tunnel Negotiation Info] <<<
Responder Received Quick Mode 3rd packet
Oct 5 20:35:23 2011	    VPN Log	   [Tunnel Negotiation Info] Quick
Mode Phase 2 SA Established, IPSec Tunnel Connected
Oct 5 20:35:23 2011	    VPN Log	   Dead Peer Detection Start, DPD
delay timer=10 sec timeout=10 sec
Oct 5 20:35:23 2011	    VPN Log	   ignoring Delete SA payload: IPSEC
SA not found (maybe expired)
Oct 5 20:35:23 2011	    VPN Log	   ignoring Delete SA payload: IPSEC
SA not found (maybe expired)

Thanks.


On Thu, Oct 6, 2011 at 12:42 PM, Geekman <the1geekman at gmail.com> wrote:
> Hi All,
>
> So, I upgraded to 2.6.36 -- and ipsec verify is showing the new
> version -- this morning, but unfortunately for me my testing shows the
> issues are still there. I kept my original configs, of course.


More information about the Users mailing list