[Openswan Users] Tunnel hangs

Mon Nov 14 14:14:57 EST 2011

Here is a log extract from the left side from around the time of last
Friday's hang.  I obfuscated the public IP Addresses.  Looks like the
problem started right around 15:11.  My phone rang shortly after 16:00
when I was driving in the car and I talked her through rebooting the
whole box around 16:18.  You can see where she messed up the root
password trying to login.  The tunnel was still no good after the box
came back up.  But by the time I was able to sit down in front of a
computer and get to this system, the tunnel was back up and running,
sometime shortly after 16:30.  You'll see a login from 16:35 - that was
me.  

I'll go find and post the right side (central site) secure log from
around this same time.  

Nov 11 14:14:51 Superior-fw pluto[1501]: "Superior-Everywhere" #211:
STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG
cipher=aes_128 prf=oakley_sha group=modp2048}
Nov 11 14:29:57 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
Informational Exchange is for an unknown (expired?) SA with
MSGID:0xccc7256f
Nov 11 14:57:23 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
ignoring unknown Vendor ID payload [4f456b71484c42504f664d44]
Nov 11 14:57:23 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [Dead Peer Detection]
Nov 11 14:57:23 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [RFC 3947] method set to=109 
Nov 11 14:57:23 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but
already using method 109
Nov 11 14:57:23 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106,
but already using method 109
Nov 11 14:57:23 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but
already using method 109
Nov 11 14:57:23 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
responding to Main Mode
Nov 11 14:57:23 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Nov 11 14:57:23 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
STATE_MAIN_R1: sent MR1, expecting MI2
Nov 11 14:57:24 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
NAT-Traversal: Result using RFC 3947 (NAT-Traversal): no NAT detected
Nov 11 14:57:24 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Nov 11 14:57:24 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
STATE_MAIN_R2: sent MR2, expecting MI3
Nov 11 14:57:24 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
Main mode peer ID is ID_FQDN: '@hq.local'
Nov 11 14:57:24 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Nov 11 14:57:24 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG
cipher=aes_128 prf=oakley_sha group=modp2048}
Nov 11 15:05:19 Superior-fw pluto[1501]: "Superior-Everywhere" #213:
initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK
to replace #202 {using isakmp#212 msgid:101c4994 proposal=defaults
pfsgroup=OAKLEY_GROUP_MODP2048}
Nov 11 15:06:29 Superior-fw pluto[1501]: "Superior-Everywhere" #213: max
number of retransmissions (2) reached STATE_QUICK_I1
Nov 11 15:06:29 Superior-fw pluto[1501]: "Superior-Everywhere" #213:
starting keying attempt 2 of an unlimited number
Nov 11 15:06:29 Superior-fw pluto[1501]: "Superior-Everywhere" #214:
initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK
to replace #213 {using isakmp#212 msgid:c81f7814 proposal=defaults
pfsgroup=OAKLEY_GROUP_MODP2048}
Nov 11 15:07:39 Superior-fw pluto[1501]: "Superior-Everywhere" #214: max
number of retransmissions (2) reached STATE_QUICK_I1
Nov 11 15:07:39 Superior-fw pluto[1501]: "Superior-Everywhere" #214:
starting keying attempt 3 of an unlimited number
Nov 11 15:07:39 Superior-fw pluto[1501]: "Superior-Everywhere" #215:
initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK
to replace #214 {using isakmp#212 msgid:05bf76de proposal=defaults
pfsgroup=OAKLEY_GROUP_MODP2048}
Nov 11 15:08:49 Superior-fw pluto[1501]: "Superior-Everywhere" #215: max
number of retransmissions (2) reached STATE_QUICK_I1
Nov 11 15:08:49 Superior-fw pluto[1501]: "Superior-Everywhere" #215:
starting keying attempt 4 of an unlimited number
Nov 11 15:08:49 Superior-fw pluto[1501]: "Superior-Everywhere" #216:
initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK
to replace #215 {using isakmp#212 msgid:fab66ff5 proposal=defaults
pfsgroup=OAKLEY_GROUP_MODP2048}
Nov 11 15:09:59 Superior-fw pluto[1501]: "Superior-Everywhere" #216: max
number of retransmissions (2) reached STATE_QUICK_I1
Nov 11 15:09:59 Superior-fw pluto[1501]: "Superior-Everywhere" #216:
starting keying attempt 5 of an unlimited number
Nov 11 15:09:59 Superior-fw pluto[1501]: "Superior-Everywhere" #217:
initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK
to replace #216 {using isakmp#212 msgid:17be09a6 proposal=defaults
pfsgroup=OAKLEY_GROUP_MODP2048}
Nov 11 15:11:09 Superior-fw pluto[1501]: "Superior-Everywhere" #217: max
number of retransmissions (2) reached STATE_QUICK_I1
Nov 11 15:11:09 Superior-fw pluto[1501]: "Superior-Everywhere" #217:
starting keying attempt 6 of an unlimited number
Nov 11 15:11:09 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK
to replace #217 {using isakmp#212 msgid:b36f75e6 proposal=defaults
pfsgroup=OAKLEY_GROUP_MODP2048}
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #212: the
peer proposed: 172.21.5.0/24:0/0 -> 192.168.0.0/16:0/0
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
responding to Quick Mode proposal {msgid:22f466dd}
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
us:
172.21.5.0/24===3.4.22.228<3.4.22.228>[@superior.local,+S=C]---216.70.22
.1
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
them:
12.24.248.49---1.2.248.50<1.2.248.50>[@hq.local,+S=C]===192.168.0.0/16
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
keeping refhim=4294901761 during rekey
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Nov 11 15:11:32 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0x0085d044
<0xebbf8322 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=none}
Nov 11 15:11:39 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:11:49 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:12:09 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:12:49 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:13:29 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:14:09 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:14:49 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:14:51 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
Informational Exchange is for an unknown (expired?) SA with
MSGID:0xdf15a6a3
Nov 11 15:15:29 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:16:02 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
ignoring Delete SA payload: PROTO_IPSEC_ESP SA(0x71188d88) not found
(maybe expired)
Nov 11 15:16:02 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
received and ignored informational message
Nov 11 15:16:09 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:16:49 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:17:29 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:18:09 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:18:49 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:19:29 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:20:09 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:20:49 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:21:29 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:22:09 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:22:49 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:23:29 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:24:09 Superior-fw pluto[1501]: "Superior-Everywhere" #218:
ERROR: netlink response for Add SA esp.bd47d7f5 at 3.4.22.228 included
errno 3: No such process
Nov 11 15:40:03 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
ignoring unknown Vendor ID payload [4f456b71484c42504f664d44]
Nov 11 15:40:03 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [Dead Peer Detection]
Nov 11 15:40:03 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [RFC 3947] method set to=109 
Nov 11 15:40:03 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but
already using method 109
Nov 11 15:40:03 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106,
but already using method 109
Nov 11 15:40:03 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but
already using method 109
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
responding to Main Mode
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
STATE_MAIN_R1: sent MR1, expecting MI2
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
NAT-Traversal: Result using RFC 3947 (NAT-Traversal): no NAT detected
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
STATE_MAIN_R2: sent MR2, expecting MI3
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
Main mode peer ID is ID_FQDN: '@hq.local'
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Nov 11 15:40:03 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG
cipher=aes_128 prf=oakley_sha group=modp2048}
Nov 11 15:57:24 Superior-fw pluto[1501]: "Superior-Everywhere" #212:
received Delete SA payload: deleting ISAKMP State #212
Nov 11 15:57:24 Superior-fw pluto[1501]: packet from 1.2.248.50:500:
received and ignored informational message
Nov 11 16:14:33 Superior-fw login: pam_unix(login:auth): check pass;
user unknown
Nov 11 16:14:33 Superior-fw login: pam_unix(login:auth): authentication
failure; logname=LOGIN uid=0 euid=0 tty=tty1 ruser= rhost= 
Nov 11 16:14:34 Superior-fw login: FAILED LOGIN 1 FROM (null) FOR  root,
User not known to the underlying authentication module
Nov 11 16:15:33 Superior-fw login: pam_unix(login:session): session
opened for user root by LOGIN(uid=0)
Nov 11 16:15:33 Superior-fw login: ROOT LOGIN ON tty1
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down
Nov 11 16:18:50 Superior-fw pluto[1501]: forgetting secrets
Nov 11 16:18:50 Superior-fw pluto[1501]: "Superior-Everywhere": deleting
connection
Nov 11 16:18:50 Superior-fw pluto[1501]: "Superior-Everywhere" #219:
deleting state (STATE_QUICK_R2)
Nov 11 16:18:50 Superior-fw pluto[1501]: "Superior-Everywhere" #220:
deleting state (STATE_MAIN_R3)
Nov 11 16:18:50 Superior-fw pluto[1501]: "Superior-Everywhere":
unroute-client output: /usr/local/lib/ipsec/_updown.netkey: doroute `ip
route del 192.168.0.0/16 via 216.70.22.1 dev em1 ' failed (RTNETLINK
answers: No such process)
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface lo/lo
::1:500
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface lo/lo
127.0.0.1:4500
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface lo/lo
127.0.0.1:500
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface em1/em1
3.4.22.228:4500
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface em1/em1
3.4.22.228:500
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface
p2p1/p2p1 10.10.10.88:4500
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface
p2p1/p2p1 10.10.10.88:500
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface
p1p1/p1p1 172.21.5.100:4500
Nov 11 16:18:50 Superior-fw pluto[1501]: shutting down interface
p1p1/p1p1 172.21.5.100:500
Nov 11 16:18:50 Superior-fw pluto[1504]: pluto_crypto_helper: helper (0)
is  normal exiting 
Nov 11 16:18:52 Superior-fw ipsec__plutorun: Starting Pluto subsystem...
Nov 11 16:18:52 Superior-fw pluto[11548]: Starting Pluto (Openswan
Version 2.6.36; Vendor ID OEqltr]KZl]_) pid:11548
Nov 11 16:18:52 Superior-fw pluto[11548]: LEAK_DETECTIVE support
[disabled]
Nov 11 16:18:52 Superior-fw pluto[11548]: OCF support for IKE [disabled]
Nov 11 16:18:52 Superior-fw pluto[11548]: SAref support [disabled]:
Protocol not available
Nov 11 16:18:52 Superior-fw pluto[11548]: SAbind support [disabled]:
Protocol not available
Nov 11 16:18:52 Superior-fw pluto[11548]: NSS support [disabled]
Nov 11 16:18:52 Superior-fw pluto[11548]: HAVE_STATSD notification
support not compiled in
Nov 11 16:18:52 Superior-fw pluto[11548]: Setting NAT-Traversal
port-4500 floating to on
Nov 11 16:18:52 Superior-fw pluto[11548]:    port floating activation
criteria nat_t=1/port_float=1
Nov 11 16:18:52 Superior-fw pluto[11548]:    NAT-Traversal support
[enabled]
Nov 11 16:18:52 Superior-fw pluto[11548]: 1 bad entries in
virtual_private - none loaded
Nov 11 16:18:52 Superior-fw pluto[11548]: using /dev/urandom as source
of random entropy
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_register_enc():
Activating OAKLEY_AES_CBC: Ok (ret=0)
Nov 11 16:18:52 Superior-fw pluto[11548]: starting up 1 cryptographic
helpers
Nov 11 16:18:52 Superior-fw pluto[11548]: started helper pid=11550
(fd:6)
Nov 11 16:18:52 Superior-fw pluto[11548]: Using Linux 2.6 IPsec
interface code on 2.6.40.6-0.fc15.x86_64 (experimental code)
Nov 11 16:18:52 Superior-fw pluto[11550]: using /dev/urandom as source
of random entropy
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_register_enc():
Activating aes_ccm_8: Ok (ret=0)
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_add(): ERROR:
Algorithm already exists
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_register_enc():
Activating aes_ccm_12: FAILED (ret=-17)
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_add(): ERROR:
Algorithm already exists
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_register_enc():
Activating aes_ccm_16: FAILED (ret=-17)
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_add(): ERROR:
Algorithm already exists
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_register_enc():
Activating aes_gcm_8: FAILED (ret=-17)
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_add(): ERROR:
Algorithm already exists
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_register_enc():
Activating aes_gcm_12: FAILED (ret=-17)
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_add(): ERROR:
Algorithm already exists
Nov 11 16:18:52 Superior-fw pluto[11548]: ike_alg_register_enc():
Activating aes_gcm_16: FAILED (ret=-17)
Nov 11 16:18:52 Superior-fw pluto[11548]: Changed path to directory
'/etc/ipsec.d/cacerts'
Nov 11 16:18:52 Superior-fw pluto[11548]: Changed path to directory
'/etc/ipsec.d/aacerts'
Nov 11 16:18:52 Superior-fw pluto[11548]: Changed path to directory
'/etc/ipsec.d/ocspcerts'
Nov 11 16:18:52 Superior-fw pluto[11548]: Changing to directory
'/etc/ipsec.d/crls'
Nov 11 16:18:52 Superior-fw pluto[11548]:   Warning: empty directory
Nov 11 16:18:52 Superior-fw pluto[11548]: added connection description
"Superior-Everywhere"
Nov 11 16:18:52 Superior-fw pluto[11548]: listening for IKE messages
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface p1p1/p1p1
172.21.5.100:500
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface p1p1/p1p1
172.21.5.100:4500
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface p2p1/p2p1
10.10.10.88:500
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface p2p1/p2p1
10.10.10.88:4500
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface em1/em1
3.4.22.228:500
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface em1/em1
3.4.22.228:4500
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface lo/lo
127.0.0.1:500
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface lo/lo
127.0.0.1:4500
Nov 11 16:18:52 Superior-fw pluto[11548]: adding interface lo/lo ::1:500
Nov 11 16:18:52 Superior-fw pluto[11548]: loading secrets from
"/etc/ipsec.secrets"
Nov 11 16:18:52 Superior-fw pluto[11548]: loading secrets from
"/etc/ipsec.d/hostkey.secrets"
Nov 11 16:18:52 Superior-fw pluto[11548]: loaded private key for keyid:
PPK_RSA:AQNl6eslo
Nov 11 16:18:52 Superior-fw pluto[11548]: "Superior-Everywhere" #1:
initiating Main Mode
Nov 11 16:18:54 Superior-fw pluto[11548]: initiate on demand from
172.21.5.20:51582 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:19:31 Superior-fw pluto[11548]: initiate on demand from
172.21.5.20:61898 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:19:42 Superior-fw pluto[11548]: initiate on demand from
172.21.5.100:54604 to 192.168.3.5:1025 proto=17 state: fos_start
because: acquire
Nov 11 16:20:20 Superior-fw pluto[11548]: initiate on demand from
172.21.5.20:59955 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:21:13 Superior-fw runuser: pam_unix(runuser:session): session
opened for user root by (uid=0)
Nov 11 16:21:13 Superior-fw sshd[1295]: Server listening on 0.0.0.0 port
22.
Nov 11 16:21:13 Superior-fw sshd[1295]: Server listening on :: port 22.
Nov 11 16:21:13 Superior-fw runuser: pam_unix(runuser:session): session
closed for user root
Nov 11 16:21:14 Superior-fw ipsec__plutorun: Starting Pluto subsystem...
Nov 11 16:21:14 Superior-fw pluto[1479]: Starting Pluto (Openswan
Version 2.6.36; Vendor ID OEqltr]KZl]_) pid:1479
Nov 11 16:21:14 Superior-fw pluto[1479]: LEAK_DETECTIVE support
[disabled]
Nov 11 16:21:14 Superior-fw pluto[1479]: OCF support for IKE [disabled]
Nov 11 16:21:14 Superior-fw pluto[1479]: SAref support [disabled]:
Protocol not available
Nov 11 16:21:14 Superior-fw pluto[1479]: SAbind support [disabled]:
Protocol not available
Nov 11 16:21:14 Superior-fw pluto[1479]: NSS support [disabled]
Nov 11 16:21:14 Superior-fw pluto[1479]: HAVE_STATSD notification
support not compiled in
Nov 11 16:21:14 Superior-fw pluto[1479]: Setting NAT-Traversal port-4500
floating to on
Nov 11 16:21:14 Superior-fw pluto[1479]:    port floating activation
criteria nat_t=1/port_float=1
Nov 11 16:21:14 Superior-fw pluto[1479]:    NAT-Traversal support
[enabled]
Nov 11 16:21:14 Superior-fw pluto[1479]: 1 bad entries in
virtual_private - none loaded
Nov 11 16:21:14 Superior-fw pluto[1479]: using /dev/urandom as source of
random entropy
Nov 11 16:21:14 Superior-fw pluto[1479]: ike_alg_register_enc():
Activating OAKLEY_AES_CBC: Ok (ret=0)
Nov 11 16:21:14 Superior-fw pluto[1479]: starting up 1 cryptographic
helpers
Nov 11 16:21:14 Superior-fw pluto[1479]: started helper pid=1482 (fd:6)
Nov 11 16:21:14 Superior-fw pluto[1479]: Using Linux 2.6 IPsec interface
code on 2.6.40.6-0.fc15.x86_64 (experimental code)
Nov 11 16:21:14 Superior-fw pluto[1482]: using /dev/urandom as source of
random entropy
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_register_enc():
Activating aes_ccm_8: Ok (ret=0)
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_add(): ERROR: Algorithm
already exists
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_register_enc():
Activating aes_ccm_12: FAILED (ret=-17)
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_add(): ERROR: Algorithm
already exists
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_register_enc():
Activating aes_ccm_16: FAILED (ret=-17)
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_add(): ERROR: Algorithm
already exists
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_register_enc():
Activating aes_gcm_8: FAILED (ret=-17)
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_add(): ERROR: Algorithm
already exists
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_register_enc():
Activating aes_gcm_12: FAILED (ret=-17)
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_add(): ERROR: Algorithm
already exists
Nov 11 16:21:15 Superior-fw pluto[1479]: ike_alg_register_enc():
Activating aes_gcm_16: FAILED (ret=-17)
Nov 11 16:21:15 Superior-fw pluto[1479]: Changed path to directory
'/etc/ipsec.d/cacerts'
Nov 11 16:21:15 Superior-fw pluto[1479]: Changed path to directory
'/etc/ipsec.d/aacerts'
Nov 11 16:21:15 Superior-fw pluto[1479]: Changed path to directory
'/etc/ipsec.d/ocspcerts'
Nov 11 16:21:15 Superior-fw pluto[1479]: Changing to directory
'/etc/ipsec.d/crls'
Nov 11 16:21:15 Superior-fw pluto[1479]:   Warning: empty directory
Nov 11 16:21:15 Superior-fw pluto[1479]: added connection description
"Superior-Everywhere"
Nov 11 16:21:15 Superior-fw pluto[1479]: listening for IKE messages
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface p1p1/p1p1
172.21.5.100:500
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface p1p1/p1p1
172.21.5.100:4500
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface p2p1/p2p1
10.10.10.88:500
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface p2p1/p2p1
10.10.10.88:4500
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface em1/em1
3.4.22.228:500
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface em1/em1
3.4.22.228:4500
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface lo/lo
127.0.0.1:500
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface lo/lo
127.0.0.1:4500
Nov 11 16:21:15 Superior-fw pluto[1479]: adding interface lo/lo ::1:500
Nov 11 16:21:15 Superior-fw pluto[1479]: loading secrets from
"/etc/ipsec.secrets"
Nov 11 16:21:15 Superior-fw pluto[1479]: loading secrets from
"/etc/ipsec.d/hostkey.secrets"
Nov 11 16:21:15 Superior-fw pluto[1479]: loaded private key for keyid:
PPK_RSA:AQNl6eslo
Nov 11 16:21:15 Superior-fw pluto[1479]: "Superior-Everywhere":
prepare-client output: RTNETLINK answers: No such file or directory
Nov 11 16:21:15 Superior-fw pluto[1479]: "Superior-Everywhere":
prepare-client command exited with status 2
Nov 11 16:21:15 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
initiating Main Mode
Nov 11 16:22:01 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:59047 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:22:13 Superior-fw pluto[1479]: initiate on demand from
172.21.5.1:1040 to 192.168.3.4:3389 proto=6 state: fos_start because:
acquire
Nov 11 16:22:49 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:60280 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:23:42 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:54774 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:24:34 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:50070 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:25:19 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:49839 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:26:10 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:62670 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:27:04 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:62147 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:27:55 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:49215 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:28:42 Superior-fw pluto[1479]: initiate on demand from
172.21.5.20:61640 to 192.168.3.4:53 proto=17 state: fos_start because:
acquire
Nov 11 16:28:50 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
ignoring unknown Vendor ID payload [4f456b71484c42504f664d44]
Nov 11 16:28:50 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [Dead Peer Detection]
Nov 11 16:28:50 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [RFC 3947] method set to=109 
Nov 11 16:28:50 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but
already using method 109
Nov 11 16:28:50 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106,
but already using method 109
Nov 11 16:28:50 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but
already using method 109
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
responding to Main Mode
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
STATE_MAIN_R1: sent MR1, expecting MI2
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
NAT-Traversal: Result using RFC 3947 (NAT-Traversal): no NAT detected
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
STATE_MAIN_R2: sent MR2, expecting MI3
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2: Main
mode peer ID is ID_FQDN: '@hq.local'
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Nov 11 16:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG
cipher=aes_128 prf=oakley_sha group=modp2048}
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
ignoring unknown Vendor ID payload [4f456b71484c42504f664d44]
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
received Vendor ID payload [Dead Peer Detection]
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
received Vendor ID payload [RFC 3947] method set to=109 
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
enabling possible NAT-traversal with method 4
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
STATE_MAIN_I2: sent MI2, expecting MR2
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
NAT-Traversal: Result using RFC 3947 (NAT-Traversal): no NAT detected
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
STATE_MAIN_I3: sent MI3, expecting MR3
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
received Vendor ID payload [CAN-IKEv2]
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1: Main
mode peer ID is ID_FQDN: '@hq.local'
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #1:
STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=aes_128
prf=oakley_sha group=modp2048}
Nov 11 16:29:05 Superior-fw pluto[1479]: "Superior-Everywhere" #3:
initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK
{using isakmp#1 msgid:e1ca1f15 proposal=defaults
pfsgroup=OAKLEY_GROUP_MODP2048}
Nov 11 16:29:06 Superior-fw pluto[1479]: "Superior-Everywhere" #3:
transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
Nov 11 16:29:06 Superior-fw pluto[1479]: "Superior-Everywhere" #3:
STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode
{ESP=>0x0d37397f <0xdb635564 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none
DPD=none}
Nov 11 16:35:33 Superior-fw sshd[1862]: Accepted password for root from
216.160.2.129 port 52861 ssh2
Nov 11 22:35:33 Superior-fw sshd[1863]: fatal: mm_request_receive: read:
Connection reset by peer
Nov 11 16:35:33 Superior-fw sshd[1862]: pam_unix(sshd:session): session
opened for user root by (uid=0)
Nov 11 16:40:03 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
Informational Exchange is for an unknown (expired?) SA with
MSGID:0xe839e7a9
Nov 11 17:15:09 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
initiating Main Mode to replace #1
Nov 11 17:24:35 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
ignoring unknown Vendor ID payload [4f456b71484c42504f664d44]
Nov 11 17:24:35 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [Dead Peer Detection]
Nov 11 17:24:35 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [RFC 3947] method set to=109 
Nov 11 17:24:35 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but
already using method 109
Nov 11 17:24:35 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106,
but already using method 109
Nov 11 17:24:35 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but
already using method 109
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5:
responding to Main Mode
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5:
transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5:
STATE_MAIN_R1: sent MR1, expecting MI2
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5:
NAT-Traversal: Result using RFC 3947 (NAT-Traversal): no NAT detected
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5:
transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5:
STATE_MAIN_R2: sent MR2, expecting MI3
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5: Main
mode peer ID is ID_FQDN: '@hq.local'
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5:
transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Nov 11 17:24:35 Superior-fw pluto[1479]: "Superior-Everywhere" #5:
STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG
cipher=aes_128 prf=oakley_sha group=modp2048}
Nov 11 17:24:59 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
ignoring unknown Vendor ID payload [4f456b71484c42504f664d44]
Nov 11 17:24:59 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
received Vendor ID payload [Dead Peer Detection]
Nov 11 17:24:59 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
received Vendor ID payload [RFC 3947] method set to=109 
Nov 11 17:24:59 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
enabling possible NAT-traversal with method 4
Nov 11 17:24:59 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
Nov 11 17:24:59 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
STATE_MAIN_I2: sent MI2, expecting MR2
Nov 11 17:25:00 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
NAT-Traversal: Result using RFC 3947 (NAT-Traversal): no NAT detected
Nov 11 17:25:00 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
Nov 11 17:25:00 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
STATE_MAIN_I3: sent MI3, expecting MR3
Nov 11 17:25:00 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
received Vendor ID payload [CAN-IKEv2]
Nov 11 17:25:00 Superior-fw pluto[1479]: "Superior-Everywhere" #4: Main
mode peer ID is ID_FQDN: '@hq.local'
Nov 11 17:25:00 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
Nov 11 17:25:00 Superior-fw pluto[1479]: "Superior-Everywhere" #4:
STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=aes_128
prf=oakley_sha group=modp2048}
Nov 11 17:28:50 Superior-fw pluto[1479]: "Superior-Everywhere" #2:
received Delete SA payload: deleting ISAKMP State #2
Nov 11 17:28:50 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received and ignored informational message
Nov 11 17:29:05 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
Informational Exchange is for an unknown (expired?) SA with
MSGID:0x580b7f2a
Nov 11 18:07:27 Superior-fw pluto[1479]: "Superior-Everywhere" #6:
initiating Main Mode to replace #4
Nov 11 18:20:30 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
ignoring unknown Vendor ID payload [4f456b71484c42504f664d44]
Nov 11 18:20:30 Superior-fw pluto[1479]: packet from 1.2.248.50:500:
received Vendor ID payload [Dead Peer Detection]

-----Original Message-----
From: Paul Wouters [mailto:paul at xelerance.com] 
Sent: Monday, November 14, 2011 12:33 PM
To: Greg Scott
Cc: users at openswan.org
Subject: RE: [Openswan Users] Tunnel hangs

On Mon, 14 Nov 2011, Greg Scott wrote:

> OK . . .  Now to work the original problem first posted on 11/2.  That
tunnel has gone offline at least twice that I know of since then.  Plus
I have other tunnels running various versions that continue to go
offline and the only cure seems to be stop and restart Openswan.

We probably need to see some more logging of such a failure with logs
from both ends.

>        rightupdown=/etc/ipsec.d/hq-updown.sh

> The updown script is just a little hack I use to shorten the MTU and
make my default source IP the LAN side.
>
> [root at Superior-fw ipsec.d]#  more superior-updown.sh
> #!/bin/sh
>
> LOCALNET=172.21.5.0/24
>
> /usr/local/lib/ipsec/_updown $*
> if [ "$PLUTO_VERB" = "route-host" -o "$PLUTO_VERB" = "route-client" ];
then
>    for dir in in out; do
>        ip xfrm policy update dir $dir src $LOCALNET dst $LOCALNET
>    done
> fi
>
> /sbin/ip route change 192.168.0.0/16 dev em1 src 172.21.5.100 mtu 1400

Note that we have an mtu= and leftsourceip= option for that. I recommend
using that as there is more logic
in the updown scripts you are bypassing now, as you did use the stock
updown script as a base for your
own version.

Also note that if your central node is the older openswan, it might not
matter what the leaves run for you
to experience old bugs. Please try and replicate this on two modern
openswan releases.

You might also want to consider enabling DPD, so there is a better
detection that a tunnel is down. Perhaps
that will bring to light why things are failing?

Paul