[Openswan dev] [Openswan Users] Strange outage on some tunnels (fwd)
Paul Wouters
paul at xelerance.com
Wed May 30 19:05:47 EDT 2007
---------- Forwarded message ----------
Date: Wed, 30 May 2007 14:38:48 +0200
From: Pompon2 <pompon2 at gmail.com>
To: <users at openswan.org>
Subject: [Openswan Users] Strange outage on some tunnels
Hello all,
We've got a little problem on 2 tunnels this night causing them to be down
for some hours unit a manual intervention. They have been down in a strange
state where an ISAKMP SA was up but our side was expecting QI2 and received
Quick_R1, with a Bad Address error message in the logs.
In fact, there has been a problem (probably a network outage) at 00:30:53 as
I have a lot of other tunnels that falls down to trap state at this time,
but all of them reach to renegociate a few seconds later. However this one
keep staying in this strange state until we delete/add/up the connection
some hours later.
The difference between the logs for other tunnels and this one is that the
ip adress of the remote gateway is specified instead of 0.0.0.0 in the Bad
Address error message.
Do you have any idea that could help me investigate further?
BTW, we use openswan 2.4.7 with Klips on linux kernel 2.6.8
Thanks.
***************************************************
The log of the strange tunnel :
May 30 00:30:43 vpn-server1 pluto[23345]: "partner1_SP_AUTH" #7928:
initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+UP to replace #7696 {using
isakmp#7674}
May 30 00:30:52 vpn-server1 pluto[23345]: "partner1_SP_AUTH" #7928: ignoring
informational payload, type IPSEC_RESPONDER_LIFETIME
May 30 00:30:52 vpn-server1 pluto[23345]: "partner1_SP_AUTH" #7928: Dead
Peer Detection (RFC 3706): enabled
May 30 00:30:53 vpn-server1 pluto[23345]: "partner1_SP_AUTH" #7928:
transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
May 30 00:30:53 vpn-server1 pluto[23345]: "partner1_SP_AUTH" #7928:
STATE_QUICK_I2: sent QI2, IPsec SA established {ESP=>0x7f9cc315 <0x4e537db0
x
frm=3DES_0-HMAC_MD5 NATD=none DPD=enabled}
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_ICMP" #7674: DPD: Info:
No response from peer - declaring peer dead
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_ICMP" #7674: DPD: Info:
Putting connection into %trap
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_SP_AUTH" #7928: deleting
state (STATE_QUICK_I2)
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7855: deleting
state (STATE_QUICK_I2)
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_SP_ACCT" #7756: deleting
state (STATE_QUICK_I2)
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #7719: deleting
state (STATE_QUICK_I2)
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_ICMP" #7717: deleting
state (STATE_QUICK_I2)
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_SP_AUTH" #7696: deleting
state (STATE_QUICK_I2)
May 30 00:31:01 vpn-server1 pluto[23345]: "partner1_ICMP" #7674: deleting
state (STATE_MAIN_I4)
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951:
responding to Main Mode
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951:
transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951:
STATE_MAIN_R1: sent MR1, expecting MI2
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: received
Vendor ID payload [XAUTH]
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: received
Vendor ID payload [Dead Peer Detection]
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: received
Vendor ID payload [Cisco-Unity]
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: ignoring
unknown Vendor ID payload [8e4c769809eb7a8630f0511b630c5353]
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951:
transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951:
STATE_MAIN_R2: sent MR2, expecting MI3
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: Main
mode peer ID is ID_IPV4_ADDR: '211.14.225.67'
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: I did
not send a certificate because I do not have one.
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951:
transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951:
STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY
cip
her=oakley_3des_cbc_192 prf=oakley_sha group=modp1024}
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: Dead
Peer Detection (RFC 3706): enabled
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: ignoring
informational payload, type IPSEC_INITIAL_CONTACT
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #7951: received
and ignored informational message
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: responding
to Quick Mode {msgid:cfd21611}
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: transition
from state STATE_QUICK_R0 to state STATE_QUICK_R1
May 30 00:32:05 vpn-server1 pluto[23345]: "partner1_ICMP" #7952:
STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
May 30 00:32:05 vpn-server1 pluto[23345]: ERROR: "partner1_ICMP" #7952:
pfkey write() of SADB_X_ADDFLOW message 18840 for flow
tun.1e78 at 211.14.225.67 failed. Errno 14: Bad address
May 30 00:32:15 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:32:35 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:33:15 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:33:55 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:34:35 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:35:15 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:35:55 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:36:35 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:37:15 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:37:55 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:38:35 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:39:15 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:39:55 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:40:35 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:41:15 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:41:55 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:42:35 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:43:15 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:43:55 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:43:59 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
responding to Quick Mode {msgid:bdfc5c5e}
May 30 00:43:59 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
May 30 00:43:59 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
May 30 00:43:59 vpn-server1 pluto[23345]: ERROR: "partner1_NO_AUTH" #8006:
pfkey write() of SADB_X_ADDFLOW message 18942 for flow
tun.1e8c at 211.14.225.67 failed. Errno 14: Bad address
May 30 00:44:09 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:44:29 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:44:35 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: discarding
duplicate packet; already STATE_QUICK_R1
May 30 00:45:09 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:45:15 vpn-server1 pluto[23345]: "partner1_ICMP" #7952: max number
of retransmissions (20) reached STATE_QUICK_R1
May 30 00:45:49 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:46:29 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:47:09 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:47:49 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:48:29 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:49:09 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:49:49 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:50:29 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:51:09 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:51:49 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:52:29 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:52:34 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
responding to Quick Mode {msgid:c3393429}
May 30 00:52:34 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
May 30 00:52:34 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
May 30 00:52:34 vpn-server1 pluto[23345]: ERROR: "partner1_NO_ACCT" #8049:
pfkey write() of SADB_X_ADDFLOW message 19032 for flow
tun.1e9e at 217.14.225.67 failed. Errno 14: Bad address
May 30 00:52:44 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:53:04 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:53:09 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:53:44 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:54:24 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:55:04 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:55:44 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:56:24 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:57:04 vpn-server1 pluto[23345]: "partner1_NO_ACCT" #8049:
discarding duplicate packet; already STATE_QUICK_R1
May 30 00:57:09 vpn-server1 pluto[23345]: "partner1_NO_AUTH" #8006: max
number of retransmissions (20) reached STATE_QUICK_R1
[...]
***************************************************
Short log for a working tunnel :
May 30 00:31:00 vpn-server1 pluto[23345]: "partner2" #6807: DPD: Info: No
response from peer - declaring peer dead
May 30 00:31:00 vpn-server1 pluto[23345]: "partner2" #6807: DPD: Info:
Putting connection into %trap
May 30 00:31:00 vpn-server1 pluto[23345]: "partner2" #6808: deleting state
(STATE_QUICK_I2)
May 30 00:31:01 vpn-server1 pluto[23345]: "partner2" #6807: deleting state
(STATE_MAIN_I4)
May 30 00:31:02 vpn-server1 pluto[23345]: "partner2": deleting connection
May 30 00:31:04 vpn-server1 pluto[23345]: ERROR: "partner2": pfkey write()
of SADB_X_DELFLOW message 18745 for flow int.0 at 0.0.0.0 failed. Errno 14: Bad
address
May 30 00:31:04 vpn-server1 pluto[23345]: | 02 0f 00 0b 0e 00 00 00 39
49 00 00 31 5b 00 00
May 30 00:31:04 vpn-server1 pluto[23345]: | 03 00 15 00 00 00 00 00 02
00 00 00 59 ea 21 76
May 30 00:31:04 vpn-server1 pluto[23345]: | 40 ff 14 40 31 00 00 00 03
00 16 00 00 00 00 00
May 30 00:31:04 vpn-server1 pluto[23345]: | 02 00 00 00 83 a6 51 12 40
ff 14 40 31 00 00 00
May 30 00:31:04 vpn-server1 pluto[23345]: | 03 00 17 00 00 00 00 00 02
00 00 00 00 ff ff ff
May 30 00:31:04 vpn-server1 pluto[23345]: | 01 00 00 00 10 00 00 00 03
00 18 00 00 00 00 00
May 30 00:31:04 vpn-server1 pluto[23345]: | 02 00 00 00 ff ff ff ff 08
e6 ff bf 7e 66 0b 08
May 30 00:31:06 vpn-server1 pluto[23345]: added connection description
"partner2"
May 30 00:31:10 vpn-server1 pluto[23345]: "partner2" #7939: initiating Main
Mode
May 30 00:31:10 vpn-server1 pluto[23345]: "partner2" #7939: transition from
state STATE_MAIN_I1 to state STATE_MAIN_I2
May 30 00:31:10 vpn-server1 pluto[23345]: "partner2" #7939: STATE_MAIN_I2:
sent MI2, expecting MR2
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: received Vendor
ID payload [Cisco-Unity]
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: received Vendor
ID payload [Dead Peer Detection]
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: ignoring unknown
Vendor ID payload [5a77c384634c9b025b2154312a771c0d]
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: received Vendor
ID payload [XAUTH]
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: I did not send a
certificate because I do not have one.
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: transition from
state STATE_MAIN_I2 to state STATE_MAIN_I3
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: STATE_MAIN_I3:
sent MI3, expecting MR3
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: Main mode peer
ID is ID_IPV4_ADDR: '131.166.52.20'
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: transition from
state STATE_MAIN_I3 to state STATE_MAIN_I4
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: STATE_MAIN_I4:
ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192
prf=oakley_sha group=modp1024}
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7939: Dead Peer
Detection (RFC 3706): enabled
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7940: initiating Quick
Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS+UP {using isakmp#7939}
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7940: ignoring
informational payload, type IPSEC_RESPONDER_LIFETIME
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7940: Dead Peer
Detection (RFC 3706): enabled
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7940: transition from
state STATE_QUICK_I1 to state STATE_QUICK_I2
May 30 00:31:11 vpn-server1 pluto[23345]: "partner2" #7940: STATE_QUICK_I2:
sent QI2, IPsec SA established {ESP=>0x937a7eb1 <0x4e537db6
xfrm=3DES_0-HMAC_SHA1 NATD=none DPD=enabled}
-------------- next part --------------
_______________________________________________
Users at openswan.org
http://lists.openswan.org/mailman/listinfo/users
Building and Integrating Virtual Private Networks with Openswan:
http://www.amazon.com/gp/product/1904811256/104-3099591-2946327?n=283155
More information about the Dev
mailing list