[Swan] Problem in reestablishment of an ipsec connection
Philippe Vouters
philippe.vouters at laposte.net
Tue Jan 1 17:17:16 EET 2013
Dear Oguz,
For Libreswan (an Openswan fork based on Openswan 2.6.38), we modified
this line in bold in ./programs/pluto/kernel_netlink.c:
req.u.p.lft.soft_use_expires_seconds = use_lifetime;
req.u.p.lft.soft_byte_limit = XFRM_INF;
req.u.p.lft.soft_packet_limit = XFRM_INF;
req.u.p.lft.hard_byte_limit = XFRM_INF;
req.u.p.lft.hard_packet_limit = XFRM_INF;
*req.n.nlmsg_type = XFRM_MSG_NEWPOLICY;*
if (sadb_op == ERO_REPLACE)
{
req.n.nlmsg_type = XFRM_MSG_UPDPOLICY;
}
req.n.nlmsg_len = NLMSG_ALIGN(NLMSG_LENGTH(sizeof(req.u.p)));
}
if (policy == IPSEC_POLICY_IPSEC && sadb_op != ERO_DELETE)
{
In Openswan, this line in bold is set to:
req.n.nlmsg_type = *XFRM_MSG_UPDPOLICY
*which can explain the problem you encountered so far.
Libreswan is due to see birth today. Wouldn't it be worth you wait a
little for Libreswan to become official and test your Cisco connection
with Libreswan ? Meanwhile you can decrease your ikelifetime to 8 hours.
Please note that as soon as I am given the opportunity with a real Cisco
router end, I shall work onto strengthening the Libreswan operations
with a remote Cisco router. I solely depend upon the time which can
freed and dedicated onto by the owner of the Cisco equipment. As soon as
allowed access to a Cisco router, I promise to document an HOWTO on my
Web site at http://vouters.dyndns.org/ using Cisco/Shrew/Libreswan VPN
clients.
Yours truly,
Philippe Vouters (Fontainebleau/France)
URL: http://vouters.dyndns.org/
SIP: sip:Vouters at sip.linphone.org
Le 01/01/2013 14:24, Oguz Yilmaz a écrit :
> Unfortunately, now it is connected. I think it is because keylife or
> ikelifetime has been reached. It is exactşy 24 hours from last
> successful connection (yesterday 15:10), remote cisco removed
> established key and became available for new connections. However I
> am sure it will happen again.
>
> I have extracted log during the problem, below. openswan can not do
> anything it just waits for reply from remote side for isakmp.
>
>
> Jan 1 13:54:56 2013 pluto[8841]: \"merkezvpn/0x2\" #954: initiating
> Main Mode to replace #948
> Jan 1 13:56:56 2013 pluto[8841]: pending Quick Mode with RIGHTEXTIP
> \"merkezvpn/0x2\" took too long -- replacing phase 1
> Jan 1 13:56:56 2013 pluto[8841]: pending Quick Mode with RIGHTEXTIP
> \"merkezvpn/0x1\" took too long -- replacing phase 1
> Jan 1 13:56:56 2013 pluto[8841]: \"merkezvpn/0x2\" #961: initiating
> Main Mode to replace #954
> Jan 1 13:58:56 2013 pluto[8841]: pending Quick Mode with RIGHTEXTIP
> \"merkezvpn/0x2\" took too long -- replacing phase 1
> Jan 1 13:58:56 2013 pluto[8841]: pending Quick Mode with RIGHTEXTIP
> \"merkezvpn/0x1\" took too long -- replacing phase 1
> Jan 1 13:58:56 2013 pluto[8841]: \"merkezvpn/0x2\" #967: initiating
> Main Mode to replace #961
> Jan 1 14:00:56 2013 pluto[8841]: pending Quick Mode with RIGHTEXTIP
> \"merkezvpn/0x2\" took too long -- replacing phase 1
> Jan 1 14:00:56 2013 pluto[8841]: pending Quick Mode with RIGHTEXTIP
> \"merkezvpn/0x1\" took too long -- replacing phase 1
> Jan 1 14:00:56 2013 pluto[8841]: \"merkezvpn/0x2\" #975: initiating
> Main Mode to replace #967
> Jan 1 14:02:56 2013 pluto[8841]: pending Quick Mode with RIGHTEXTIP
> \"merkezvpn/0x2\" took too long -- replacing phase 1
> Jan 1 14:02:56 2013 pluto[8841]: pending Quick Mode with RIGHTEXTIP
> \"merkezvpn/0x1\" took too long -- replacing phase 1
> Jan 1 14:02:56 2013 pluto[8841]: \"merkezvpn/0x2\" #981: initiating
> Main Mode to replace #975
> .....
> CONTINUES LIKE THIS
>
>
>
> When DEBUG=ALL Log:
>
>
> Jan 1 08:41:06 2013 pluto[5254]: added connection description \"myvpn\"
> Jan 1 08:41:06 2013 pluto[5254]: |
> 10.14.0.0/16===LEFTEXTIP<LEFTEXTIP>[+S=C]---LEFTEXTIPGW...RIGHTEXTIP<RIGHTEXTIP>[10.6.202.3,+S=C]===10.0.0.0/8
> Jan 1 08:41:06 2013 pluto[5254]: | ike_life: 86400s; ipsec_life:
> 86400s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy:
> PSK+ENCRYPT+TUNNEL+DONTREKEY+IKEv2ALLOW+SAREFTRACK
> Jan 1 08:41:06 2013 pluto[5254]: | * processed 0 messages from
> cryptographic helpers
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: |
> Jan 1 08:41:06 2013 pluto[5254]: | *received whack message
> Jan 1 08:41:06 2013 pluto[5254]: | Added new connection passthru with
> policy PFS+IKEv2ALLOW+SAREFTRACK+PASS+NEVER_NEGOTIATE
> Jan 1 08:41:06 2013 pluto[5254]: | counting wild cards for 10.14.1.5 is 0
> Jan 1 08:41:06 2013 pluto[5254]: | counting wild cards for (none) is 15
> Jan 1 08:41:06 2013 pluto[5254]: added connection description \"passthru\"
> Jan 1 08:41:06 2013 pluto[5254]: |
> 10.14.0.0/19===10.14.1.5<10.14.1.5>[+S=C]...%any[+S=C]===10.14.0.0/19
> Jan 1 08:41:06 2013 pluto[5254]: | ike_life: 3600s; ipsec_life:
> 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy:
> PFS+IKEv2ALLOW+SAREFTRACK+PASS+NEVER_NEGOTIATE
> Jan 1 08:41:06 2013 pluto[5254]: | * processed 0 messages from
> cryptographic helpers
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: |
> Jan 1 08:41:06 2013 pluto[5254]: | *received whack message
> Jan 1 08:41:06 2013 pluto[5254]: listening for IKE messages
> Jan 1 08:41:06 2013 pluto[5254]: | found lo with address 127.0.0.1
> Jan 1 08:41:06 2013 pluto[5254]: | found eth0 with address 169.254.1.1
> Jan 1 08:41:06 2013 pluto[5254]: | found eth1 with address 10.14.1.5
> Jan 1 08:41:06 2013 pluto[5254]: | found eth9.102 with address LEFTEXTIP
> Jan 1 08:41:06 2013 pluto[5254]: | found eth9.102:0 with address RIGHTEXT.27
> Jan 1 08:41:06 2013 pluto[5254]: | found eth9.102:1 with address RIGHTEXT.28
> Jan 1 08:41:06 2013 pluto[5254]: | found eth9.102:2 with address RIGHTEXT.29
> Jan 1 08:41:06 2013 pluto[5254]: | found tap0 with address 10.14.41.1
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface tap0/tap0 10.14.41.1:500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface tap0/tap0 10.14.41.1:4500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface
> eth9.102:2/eth9.102:2 RIGHTEXT.29:500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface
> eth9.102:2/eth9.102:2 RIGHTEXT.29:4500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface
> eth9.102:1/eth9.102:1 RIGHTEXT.28:500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface
> eth9.102:1/eth9.102:1 RIGHTEXT.28:4500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface
> eth9.102:0/eth9.102:0 RIGHTEXT.27:500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface
> eth9.102:0/eth9.102:0 RIGHTEXT.27:4500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface eth9.102/eth9.102
> LEFTEXTIP:500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> :
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface eth9.102/eth9.102
> LEFTEXTIP:4500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface eth1/eth1 10.14.1.5:500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface eth1/eth1 10.14.1.5:4500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface eth0/eth0 169.254.1.1:500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface eth0/eth0 169.254.1.1:4500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(1) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface lo/lo 127.0.0.1:500
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying new style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> failed for new style NAT-T family IPv4 (errno=95)
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: Trying old style NAT-T
> Jan 1 08:41:06 2013 pluto[5254]: | NAT-Traversal: ESPINUDP(2) setup
> succeeded for new style NAT-T family IPv4
> Jan 1 08:41:06 2013 pluto[5254]: adding interface lo/lo 127.0.0.1:4500
> Jan 1 08:41:06 2013 pluto[5254]: | found lo with address
> 0000:0000:0000:0000:0000:0000:0000:0001
> Jan 1 08:41:06 2013 pluto[5254]: adding interface lo/lo ::1:500
> Jan 1 08:41:06 2013 pluto[5254]: | connect_to_host_pair:
> 10.14.1.5:500 0.0.0.0:500 -> hp:none
> Jan 1 08:41:06 2013 pluto[5254]: | find_host_pair: comparing to
> 10.14.1.5:500 0.0.0.0:500
> Jan 1 08:41:06 2013 pluto[5254]: | connect_to_host_pair:
> LEFTEXTIP:500 RIGHTEXTIP:500 -> hp:none
> Jan 1 08:41:06 2013 pluto[5254]: loading secrets from \"/etc/ipsec.secrets\"
> Jan 1 08:41:06 2013 pluto[5254]: | id type added to
> secret(0xb6100af8) PPK_PSK: LEFTEXTIP
> Jan 1 08:41:06 2013 pluto[5254]: | id type added to
> secret(0xb6100af8) PPK_PSK: RIGHTEXTIP
> Jan 1 08:41:06 2013 pluto[5254]: | Processing PSK at line 2: passed
> Jan 1 08:41:06 2013 pluto[5254]: no secrets filename matched
> \"/etc/ipsec.*.secrets\"
> Jan 1 08:41:06 2013 pluto[5254]: | * processed 0 messages from
> cryptographic helpers
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: |
> Jan 1 08:41:06 2013 pluto[5254]: | *received whack message
> Jan 1 08:41:06 2013 pluto[5254]: | processing connection myvpn
> Jan 1 08:41:06 2013 pluto[5254]: | route owner of \"myvpn\" unrouted:
> NULL; eroute owner: NULL
> Jan 1 08:41:06 2013 pluto[5254]: | could_route called for myvpn
> (kind=CK_PERMANENT)
> Jan 1 08:41:06 2013 pluto[5254]: | route owner of \"myvpn\" unrouted:
> NULL; eroute owner: NULL
> Jan 1 08:41:06 2013 pluto[5254]: | route_and_eroute with c: myvpn
> (next: none) ero:null esr:{(nil)} ro:null rosr:{(nil)} and state: 0
> Jan 1 08:41:06 2013 pluto[5254]: | request to add a prospective
> erouted policy with netkey kernel --- experimental
> Jan 1 08:41:06 2013 pluto[5254]: | route_and_eroute: firewall_notified: true
> Jan 1 08:41:06 2013 pluto[5254]: | command executing prepare-client
> Jan 1 08:41:06 2013 pluto[5254]: | executing prepare-client: 2>&1
> PLUTO_VERB=\'prepare-client\' PLUTO_VERSION=\'2.0\'
> PLUTO_CONNECTION=\'myvpn\' PLUTO_INTERFACE=\'eth9.102\'
> PLUTO_NEXT_HOP=\'LEFTEXTIPGW\' PLUTO_ME=\'LEFTEXTIP\'
> PLUTO_MY_ID=\'LEFTEXTIP\' PLUTO_MY_CLIENT=\'10.14.0.0/16\'
> PLUTO_MY_CLIENT_NET=\'10.14.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\' PLUTO_PEER=\'RIGHTEXTIP\'
> PLUTO_PEER_ID=\'10.6.202.3\' PLUTO_PEER_CLIENT=\'10.0.0.0/8\'
> PLUTO_PEER_CLIENT_NET=\'10.0.0.0\'
> PLUTO_PEER_CLIENT_MASK=\'255.0.0.0\' PLUTO_PEER_PORT=\'0\'
> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+DONTREKEY+IKEv2ALLOW+SAREFTRACK\'
> PLUTO_MY_SOURCEIP=\'10.14.1.5\' PLUTO_CISCO_DNS_INFO=\'\'
> PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER_BANNER=\'\'
> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
> Jan 1 08:41:06 2013 pluto[5254]: | popen(): cmd is 771 chars long
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 0):2>&1
> PLUTO_VERB=\'prepare-client\' PLUTO_VERSION=\'2.0\'
> PLUTO_CONNECTION=\'myvpn:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 80):\'
> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'LEFTEXTIPGW\'
> PLUTO_ME=\'LEFTEXTIP\':
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 160):
> PLUTO_MY_ID=\'LEFTEXTIP\' PLUTO_MY_CLIENT=\'10.14.0.0/16\'
> PLUTO_MY_CLIENT_NET=\'1:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 240):0.14.0.0\'
> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
> PLUTO_MY_PROTOCOL:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 320):=\'0\'
> PLUTO_PEER=\'RIGHTEXTIP\' PLUTO_PEER_ID=\'10.6.202.3\'
> PLUTO_PEER_CLIENT=\'10.:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 400):0.0.0/8\'
> PLUTO_PEER_CLIENT_NET=\'10.0.0.0\'
> PLUTO_PEER_CLIENT_MASK=\'255.0.0.0\' PLU:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 480):TO_PEER_PORT=\'0\'
> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\' :
> Jan 1 08:41:06 2013 pluto[5254]: | cmd(
> 560):PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+DONTREKEY+IKEv2ALLOW+SAREFTRACK\'
> PLUTO_MY:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 640):_SOURCEIP=\'10.14.1.5\'
> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_P:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 720):EER_BANNER=\'\'
> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
> Jan 1 08:41:06 2013 pluto[5254]: | command executing route-client
> Jan 1 08:41:06 2013 pluto[5254]: | executing route-client: 2>&1
> PLUTO_VERB=\'route-client\' PLUTO_VERSION=\'2.0\'
> PLUTO_CONNECTION=\'myvpn\' PLUTO_INTERFACE=\'eth9.102\'
> PLUTO_NEXT_HOP=\'LEFTEXTIPGW\' PLUTO_ME=\'LEFTEXTIP\'
> PLUTO_MY_ID=\'LEFTEXTIP\' PLUTO_MY_CLIENT=\'10.14.0.0/16\'
> PLUTO_MY_CLIENT_NET=\'10.14.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\' PLUTO_PEER=\'RIGHTEXTIP\'
> PLUTO_PEER_ID=\'10.6.202.3\' PLUTO_PEER_CLIENT=\'10.0.0.0/8\'
> PLUTO_PEER_CLIENT_NET=\'10.0.0.0\'
> PLUTO_PEER_CLIENT_MASK=\'255.0.0.0\' PLUTO_PEER_PORT=\'0\'
> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+DONTREKEY+IKEv2ALLOW+SAREFTRACK\'
> PLUTO_MY_SOURCEIP=\'10.14.1.5\' PLUTO_CISCO_DNS_INFO=\'\'
> PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER_BANNER=\'\'
> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
> Jan 1 08:41:06 2013 pluto[5254]: | popen(): cmd is 769 chars long
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 0):2>&1
> PLUTO_VERB=\'route-client\' PLUTO_VERSION=\'2.0\'
> PLUTO_CONNECTION=\'myvpn\' :
> Jan 1 08:41:06 2013 pluto[5254]: | cmd(
> 80):PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'LEFTEXTIPGW\'
> PLUTO_ME=\'LEFTEXTIP\' P:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 160):LUTO_MY_ID=\'LEFTEXTIP\'
> PLUTO_MY_CLIENT=\'10.14.0.0/16\' PLUTO_MY_CLIENT_NET=\'10.:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 240):14.0.0\'
> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
> PLUTO_MY_PROTOCOL=\':
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 320):0\'
> PLUTO_PEER=\'RIGHTEXTIP\' PLUTO_PEER_ID=\'10.6.202.3\'
> PLUTO_PEER_CLIENT=\'10.0.:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 400):0.0/8\'
> PLUTO_PEER_CLIENT_NET=\'10.0.0.0\'
> PLUTO_PEER_CLIENT_MASK=\'255.0.0.0\' PLUTO:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 480):_PEER_PORT=\'0\'
> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
> PL:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd(
> 560):UTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+DONTREKEY+IKEv2ALLOW+SAREFTRACK\'
> PLUTO_MY_S:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 640):OURCEIP=\'10.14.1.5\'
> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEE:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 720):R_BANNER=\'\'
> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
> Jan 1 08:41:06 2013 pluto[5254]: | * processed 0 messages from
> cryptographic helpers
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: |
> Jan 1 08:41:06 2013 pluto[5254]: | *received whack message
> Jan 1 08:41:06 2013 pluto[5254]: | processing connection passthru
> Jan 1 08:41:06 2013 pluto[5254]: | route owner of \"passthru\"
> unrouted: NULL; eroute owner: NULL
> Jan 1 08:41:06 2013 pluto[5254]: | could_route called for passthru
> (kind=CK_PERMANENT)
> Jan 1 08:41:06 2013 pluto[5254]: | route owner of \"passthru\"
> unrouted: NULL; eroute owner: NULL
> Jan 1 08:41:06 2013 pluto[5254]: | route_and_eroute with c: passthru
> (next: none) ero:null esr:{(nil)} ro:null rosr:{(nil)} and state: 0
> Jan 1 08:41:06 2013 pluto[5254]: | request to add a prospective
> erouted policy with netkey kernel --- experimental
> Jan 1 08:41:06 2013 pluto[5254]: | route_and_eroute: firewall_notified: true
> Jan 1 08:41:06 2013 pluto[5254]: | command executing prepare-client
> Jan 1 08:41:06 2013 pluto[5254]: | executing prepare-client: 2>&1
> PLUTO_VERB=\'prepare-client\' PLUTO_VERSION=\'2.0\'
> PLUTO_CONNECTION=\'passthru\' PLUTO_INTERFACE=\'eth1\'
> PLUTO_ME=\'10.14.1.5\' PLUTO_MY_ID=\'10.14.1.5\'
> PLUTO_MY_CLIENT=\'10.14.0.0/19\' PLUTO_MY_CLIENT_NET=\'10.14.0.0\'
> PLUTO_MY_CLIENT_MASK=\'255.255.224.0\' PLUTO_MY_PORT=\'0\'
> PLUTO_MY_PROTOCOL=\'0\' PLUTO_PEER=\'0.0.0.0\'
> PLUTO_PEER_ID=\'(none)\' PLUTO_PEER_CLIENT=\'10.14.0.0/19\'
> PLUTO_PEER_CLIENT_NET=\'10.14.0.0\'
> PLUTO_PEER_CLIENT_MASK=\'255.255.224.0\' PLUTO_PEER_PORT=\'0\'
> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
> PLUTO_CONN_POLICY=\'PFS+IKEv2ALLOW+SAREFTRACK+PASS+NEVER_NEGOTIATE\'
> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
> Jan 1 08:41:06 2013 pluto[5254]: | popen(): cmd is 700 chars long
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 0):2>&1
> PLUTO_VERB=\'prepare-client\' PLUTO_VERSION=\'2.0\'
> PLUTO_CONNECTION=\'passthru\':
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 80):
> PLUTO_INTERFACE=\'eth1\' PLUTO_ME=\'10.14.1.5\'
> PLUTO_MY_ID=\'10.14.1.5\' PLUTO_MY_CL:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 160):IENT=\'10.14.0.0/19\'
> PLUTO_MY_CLIENT_NET=\'10.14.0.0\' PLUTO_MY_CLIENT_MASK=\'255.25:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 240):5.224.0\'
> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\' PLUTO_PEER=\'0.0.0.0\'
> PLUTO_PEER:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 320):_ID=\'(none)\'
> PLUTO_PEER_CLIENT=\'10.14.0.0/19\' PLUTO_PEER_CLIENT_NET=\'10.14.0.0\'
> :
> Jan 1 08:41:06 2013 pluto[5254]: | cmd(
> 400):PLUTO_PEER_CLIENT_MASK=\'255.255.224.0\' PLUTO_PEER_PORT=\'0\'
> PLUTO_PEER_PROTOCOL=\':
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 480):0\' PLUTO_PEER_CA=\'\'
> PLUTO_STACK=\'netkey\' PLUTO_CONN_POLICY=\'PFS+IKEv2ALLOW+SARE:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd(
> 560):FTRACK+PASS+NEVER_NEGOTIATE\' PLUTO_CISCO_DNS_INFO=\'\'
> PLUTO_CISCO_DOMAIN_INFO=\':
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 640):\'
> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
> Jan 1 08:41:06 2013 pluto[5254]: | command executing route-client
> Jan 1 08:41:06 2013 pluto[5254]: | executing route-client: 2>&1
> PLUTO_VERB=\'route-client\' PLUTO_VERSION=\'2.0\'
> PLUTO_CONNECTION=\'passthru\' PLUTO_INTERFACE=\'eth1\'
> PLUTO_ME=\'10.14.1.5\' PLUTO_MY_ID=\'10.14.1.5\'
> PLUTO_MY_CLIENT=\'10.14.0.0/19\' PLUTO_MY_CLIENT_NET=\'10.14.0.0\'
> PLUTO_MY_CLIENT_MASK=\'255.255.224.0\' PLUTO_MY_PORT=\'0\'
> PLUTO_MY_PROTOCOL=\'0\' PLUTO_PEER=\'0.0.0.0\'
> PLUTO_PEER_ID=\'(none)\' PLUTO_PEER_CLIENT=\'10.14.0.0/19\'
> PLUTO_PEER_CLIENT_NET=\'10.14.0.0\'
> PLUTO_PEER_CLIENT_MASK=\'255.255.224.0\' PLUTO_PEER_PORT=\'0\'
> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
> PLUTO_CONN_POLICY=\'PFS+IKEv2ALLOW+SAREFTRACK+PASS+NEVER_NEGOTIATE\'
> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
> Jan 1 08:41:06 2013 pluto[5254]: | popen(): cmd is 698 chars long
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 0):2>&1
> PLUTO_VERB=\'route-client\' PLUTO_VERSION=\'2.0\'
> PLUTO_CONNECTION=\'passthru\' P:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 80):LUTO_INTERFACE=\'eth1\'
> PLUTO_ME=\'10.14.1.5\' PLUTO_MY_ID=\'10.14.1.5\' PLUTO_MY_CLIE:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 160):NT=\'10.14.0.0/19\'
> PLUTO_MY_CLIENT_NET=\'10.14.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 240):224.0\'
> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\' PLUTO_PEER=\'0.0.0.0\'
> PLUTO_PEER_I:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 320):D=\'(none)\'
> PLUTO_PEER_CLIENT=\'10.14.0.0/19\' PLUTO_PEER_CLIENT_NET=\'10.14.0.0\'
> PL:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd(
> 400):UTO_PEER_CLIENT_MASK=\'255.255.224.0\' PLUTO_PEER_PORT=\'0\'
> PLUTO_PEER_PROTOCOL=\'0\':
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 480): PLUTO_PEER_CA=\'\'
> PLUTO_STACK=\'netkey\' PLUTO_CONN_POLICY=\'PFS+IKEv2ALLOW+SAREFT:
> Jan 1 08:41:06 2013 pluto[5254]: | cmd(
> 560):RACK+PASS+NEVER_NEGOTIATE\' PLUTO_CISCO_DNS_INFO=\'\'
> PLUTO_CISCO_DOMAIN_INFO=\'\' :
> Jan 1 08:41:06 2013 pluto[5254]: | cmd( 640):PLUTO_PEER_BANNER=\'\'
> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
> Jan 1 08:41:06 2013 pluto[5254]: | * processed 0 messages from
> cryptographic helpers
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_PENDING_DDNS in 60 seconds
> Jan 1 08:41:06 2013 pluto[5254]: |
> Jan 1 08:41:06 2013 pluto[5254]: | *received whack message
> Jan 1 08:41:06 2013 pluto[5254]: | processing connection myvpn
> Jan 1 08:41:06 2013 pluto[5254]: | kernel_alg_db_new() initial trans_cnt=128
> Jan 1 08:41:06 2013 pluto[5254]: | kernel_alg_db_new() will return
> p_new->protoid=3, p_new->trans_cnt=1
> Jan 1 08:41:06 2013 pluto[5254]: | kernel_alg_db_new() trans[0]:
> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
> Jan 1 08:41:06 2013 pluto[5254]: | returning new proposal from esp_info
> Jan 1 08:41:06 2013 pluto[5254]: | creating state object #1 at 0xb6107d70
> Jan 1 08:41:06 2013 pluto[5254]: | processing connection myvpn
> Jan 1 08:41:06 2013 pluto[5254]: | ICOOKIE: 25 c7 56 b1 20 8b 77 9d
> Jan 1 08:41:06 2013 pluto[5254]: | RCOOKIE: 00 00 00 00 00 00 00 00
> Jan 1 08:41:06 2013 pluto[5254]: | state hash entry 14
> Jan 1 08:41:06 2013 pluto[5254]: | inserting state object #1 on chain 14
> Jan 1 08:41:06 2013 pluto[5254]: | inserting event EVENT_SO_DISCARD,
> timeout in 0 seconds for #1
> Jan 1 08:41:06 2013 pluto[5254]: | event added at head of queue
> Jan 1 08:41:06 2013 pluto[5254]: | processing connection myvpn
> Jan 1 08:41:06 2013 pluto[5254]: | Queuing pending Quick Mode with
> RIGHTEXTIP \"myvpn\"
> Jan 1 08:41:06 2013 pluto[5254]: \"myvpn\" #1: initiating Main Mode
> Jan 1 08:41:06 2013 pluto[5254]: | **emit ISAKMP Message:
> Jan 1 08:41:06 2013 pluto[5254]: | initiator cookie:
> Jan 1 08:41:06 2013 pluto[5254]: | 25 c7 56 b1 20 8b 77 9d
> Jan 1 08:41:06 2013 pluto[5254]: | responder cookie:
> Jan 1 08:41:06 2013 pluto[5254]: | 00 00 00 00 00 00 00 00
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_SA
> Jan 1 08:41:06 2013 pluto[5254]: | ISAKMP version: ISAKMP Version
> 1.0 (rfc2407)
> Jan 1 08:41:06 2013 pluto[5254]: | exchange type: ISAKMP_XCHG_IDPROT
> Jan 1 08:41:06 2013 pluto[5254]: | flags: none
> Jan 1 08:41:06 2013 pluto[5254]: | message ID: 00 00 00 00
> Jan 1 08:41:06 2013 pluto[5254]: | ***emit ISAKMP Security Association Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_VID
> Jan 1 08:41:06 2013 pluto[5254]: | DOI: ISAKMP_DOI_IPSEC
> Jan 1 08:41:06 2013 pluto[5254]: | ****emit IPsec DOI SIT:
> Jan 1 08:41:06 2013 pluto[5254]: | IPsec DOI SIT: SIT_IDENTITY_ONLY
> Jan 1 08:41:06 2013 pluto[5254]: | out_sa pcn: 0 has 1 valid proposals
> Jan 1 08:41:06 2013 pluto[5254]: | out_sa pcn: 0 pn: 0<1 valid_count:
> 1 trans_cnt: 1
> Jan 1 08:41:06 2013 pluto[5254]: | ****emit ISAKMP Proposal Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_NONE
> Jan 1 08:41:06 2013 pluto[5254]: | proposal number: 0
> Jan 1 08:41:06 2013 pluto[5254]: | protocol ID: PROTO_ISAKMP
> Jan 1 08:41:06 2013 pluto[5254]: | SPI size: 0
> Jan 1 08:41:06 2013 pluto[5254]: | number of transforms: 1
> Jan 1 08:41:06 2013 pluto[5254]: | *****emit ISAKMP Transform Payload (ISAKMP):
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_NONE
> Jan 1 08:41:06 2013 pluto[5254]: | transform number: 0
> Jan 1 08:41:06 2013 pluto[5254]: | transform ID: KEY_IKE
> Jan 1 08:41:06 2013 pluto[5254]: | ******emit ISAKMP Oakley attribute:
> Jan 1 08:41:06 2013 pluto[5254]: | af+type: OAKLEY_LIFE_TYPE
> Jan 1 08:41:06 2013 pluto[5254]: | length/value: 1
> Jan 1 08:41:06 2013 pluto[5254]: | [1 is OAKLEY_LIFE_SECONDS]
> Jan 1 08:41:06 2013 pluto[5254]: | ******emit ISAKMP Oakley attribute:
> Jan 1 08:41:06 2013 pluto[5254]: | af+type: OAKLEY_LIFE_DURATION
> (variable length)
> Jan 1 08:41:06 2013 pluto[5254]: | emitting 4 raw bytes of long
> attribute value into ISAKMP Oakley attribute
> Jan 1 08:41:06 2013 pluto[5254]: | long attribute value
> Jan 1 08:41:06 2013 pluto[5254]: | 00 01 51 80
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Oakley
> attribute: 4
> Jan 1 08:41:06 2013 pluto[5254]: | ******emit ISAKMP Oakley attribute:
> Jan 1 08:41:06 2013 pluto[5254]: | af+type: OAKLEY_ENCRYPTION_ALGORITHM
> Jan 1 08:41:06 2013 pluto[5254]: | length/value: 5
> Jan 1 08:41:06 2013 pluto[5254]: | [5 is OAKLEY_3DES_CBC]
> Jan 1 08:41:06 2013 pluto[5254]: | ******emit ISAKMP Oakley attribute:
> Jan 1 08:41:06 2013 pluto[5254]: | af+type: OAKLEY_HASH_ALGORITHM
> Jan 1 08:41:06 2013 pluto[5254]: | length/value: 1
> Jan 1 08:41:06 2013 pluto[5254]: | [1 is OAKLEY_MD5]
> Jan 1 08:41:06 2013 pluto[5254]: | ******emit ISAKMP Oakley attribute:
> Jan 1 08:41:06 2013 pluto[5254]: | af+type: OAKLEY_AUTHENTICATION_METHOD
> Jan 1 08:41:06 2013 pluto[5254]: | length/value: 1
> Jan 1 08:41:06 2013 pluto[5254]: | [1 is OAKLEY_PRESHARED_KEY]
> Jan 1 08:41:06 2013 pluto[5254]: | ******emit ISAKMP Oakley attribute:
> Jan 1 08:41:06 2013 pluto[5254]: | af+type: OAKLEY_GROUP_DESCRIPTION
> Jan 1 08:41:06 2013 pluto[5254]: | length/value: 2
> Jan 1 08:41:06 2013 pluto[5254]: | [2 is OAKLEY_GROUP_MODP1024]
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP
> Transform Payload (ISAKMP): 36
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Proposal
> Payload: 44
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Security
> Association Payload: 56
> Jan 1 08:41:06 2013 pluto[5254]: | ***emit ISAKMP Vendor ID Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_VID
> Jan 1 08:41:06 2013 pluto[5254]: | emitting 12 raw bytes of Vendor ID
> into ISAKMP Vendor ID Payload
> Jan 1 08:41:06 2013 pluto[5254]: | Vendor ID 4f 45 67 68 49 5f 77
> 5c 41 4c 46 79
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Vendor
> ID Payload: 16
> Jan 1 08:41:06 2013 pluto[5254]: | out_vendorid(): sending [Dead Peer
> Detection]
> Jan 1 08:41:06 2013 pluto[5254]: | ***emit ISAKMP Vendor ID Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_VID
> Jan 1 08:41:06 2013 pluto[5254]: | emitting 16 raw bytes of V_ID into
> ISAKMP Vendor ID Payload
> Jan 1 08:41:06 2013 pluto[5254]: | V_ID af ca d7 13 68 a1 f1 c9 6b
> 86 96 fc 77 57 01 00
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Vendor
> ID Payload: 20
> Jan 1 08:41:06 2013 pluto[5254]: | nat traversal enabled: 1
> Jan 1 08:41:06 2013 pluto[5254]: | nat add vid. port: 1 nonike: 1
> Jan 1 08:41:06 2013 pluto[5254]: | out_vendorid(): sending [RFC 3947]
> Jan 1 08:41:06 2013 pluto[5254]: | ***emit ISAKMP Vendor ID Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_VID
> Jan 1 08:41:06 2013 pluto[5254]: | emitting 16 raw bytes of V_ID into
> ISAKMP Vendor ID Payload
> Jan 1 08:41:06 2013 pluto[5254]: | V_ID 4a 13 1c 81 07 03 58 45 5c
> 57 28 f2 0e 95 45 2f
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Vendor
> ID Payload: 20
> Jan 1 08:41:06 2013 pluto[5254]: | out_vendorid(): sending
> [draft-ietf-ipsec-nat-t-ike-03]
> Jan 1 08:41:06 2013 pluto[5254]: | ***emit ISAKMP Vendor ID Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_VID
> Jan 1 08:41:06 2013 pluto[5254]: | emitting 16 raw bytes of V_ID into
> ISAKMP Vendor ID Payload
> Jan 1 08:41:06 2013 pluto[5254]: | V_ID 7d 94 19 a6 53 10 ca 6f 2c
> 17 9d 92 15 52 9d 56
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Vendor
> ID Payload: 20
> Jan 1 08:41:06 2013 pluto[5254]: | out_vendorid(): sending
> [draft-ietf-ipsec-nat-t-ike-02_n]
> Jan 1 08:41:06 2013 pluto[5254]: | ***emit ISAKMP Vendor ID Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_VID
> Jan 1 08:41:06 2013 pluto[5254]: | emitting 16 raw bytes of V_ID into
> ISAKMP Vendor ID Payload
> Jan 1 08:41:06 2013 pluto[5254]: | V_ID 90 cb 80 91 3e bb 69 6e 08
> 63 81 b5 ec 42 7b 1f
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Vendor
> ID Payload: 20
> Jan 1 08:41:06 2013 pluto[5254]: | out_vendorid(): sending
> [draft-ietf-ipsec-nat-t-ike-02]
> Jan 1 08:41:06 2013 pluto[5254]: | ***emit ISAKMP Vendor ID Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_VID
> Jan 1 08:41:06 2013 pluto[5254]: | emitting 16 raw bytes of V_ID into
> ISAKMP Vendor ID Payload
> Jan 1 08:41:06 2013 pluto[5254]: | V_ID cd 60 46 43 35 df 21 f8 7c
> fd b2 fc 68 b6 a4 48
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Vendor
> ID Payload: 20
> Jan 1 08:41:06 2013 pluto[5254]: | out_vendorid(): sending
> [draft-ietf-ipsec-nat-t-ike-00]
> Jan 1 08:41:06 2013 pluto[5254]: | ***emit ISAKMP Vendor ID Payload:
> Jan 1 08:41:06 2013 pluto[5254]: | next payload type: ISAKMP_NEXT_NONE
> Jan 1 08:41:06 2013 pluto[5254]: | emitting 16 raw bytes of V_ID into
> ISAKMP Vendor ID Payload
> Jan 1 08:41:06 2013 pluto[5254]: | V_ID 44 85 15 2d 18 b6 bb cd 0b
> e8 a8 46 95 79 dd cc
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Vendor
> ID Payload: 20
> Jan 1 08:41:06 2013 pluto[5254]: | emitting length of ISAKMP Message: 220
> Jan 1 08:41:06 2013 pluto[5254]: | sending 220 bytes for main_outI1
> through eth9.102:500 to RIGHTEXTIP:500 (using #1)
> Jan 1 08:41:06 2013 pluto[5254]: | 25 c7 56 b1 20 8b 77 9d 00 00
> 00 00 00 00 00 00
> Jan 1 08:41:06 2013 pluto[5254]: | 01 10 02 00 00 00 00 00 00 00
> 00 dc 0d 00 00 38
> Jan 1 08:41:06 2013 pluto[5254]: | 00 00 00 01 00 00 00 01 00 00
> 00 2c 00 01 00 01
> Jan 1 08:41:06 2013 pluto[5254]: | 00 00 00 24 00 01 00 00 80 0b
> 00 01 00 0c 00 04
> Jan 1 08:41:06 2013 pluto[5254]: | 00 01 51 80 80 01 00 05 80 02
> 00 01 80 03 00 01
> Jan 1 08:41:06 2013 pluto[5254]: | 80 04 00 02 0d 00 00 10 4f 45
> 67 68 49 5f 77 5c
> Jan 1 08:41:06 2013 pluto[5254]: | 41 4c 46 79 0d 00 00 14 af ca
> d7 13 68 a1 f1 c9
> Jan 1 08:41:06 2013 pluto[5254]: | 6b 86 96 fc 77 57 01 00 0d 00
> 00 14 4a 13 1c 81
> Jan 1 08:41:06 2013 pluto[5254]: | 07 03 58 45 5c 57 28 f2 0e 95
> 45 2f 0d 00 00 14
> Jan 1 08:41:06 2013 pluto[5254]: | 7d 94 19 a6 53 10 ca 6f 2c 17
> 9d 92 15 52 9d 56
> Jan 1 08:41:06 2013 pluto[5254]: | 0d 00 00 14 90 cb 80 91 3e bb
> 69 6e 08 63 81 b5
> Jan 1 08:41:06 2013 pluto[5254]: | ec 42 7b 1f 0d 00 00 14 cd 60
> 46 43 35 df 21 f8
> Jan 1 08:41:06 2013 pluto[5254]: | 7c fd b2 fc 68 b6 a4 48 00 00
> 00 14 44 85 15 2d
> Jan 1 08:41:06 2013 pluto[5254]: | 18 b6 bb cd 0b e8 a8 46 95 79 dd cc
> Jan 1 08:41:06 2013 pluto[5254]: | deleting event for #1
> Jan 1 08:41:06 2013 pluto[5254]: | inserting event EVENT_RETRANSMIT,
> timeout in 10 seconds for #1
> Jan 1 08:41:06 2013 pluto[5254]: | event added at head of queue
> Jan 1 08:41:06 2013 pluto[5254]: | * processed 0 messages from
> cryptographic helpers
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_RETRANSMIT in 10
> seconds for #1
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_RETRANSMIT in 10
> seconds for #1
> Jan 1 08:41:06 2013 pluto[5254]: |
> Jan 1 08:41:06 2013 pluto[5254]: | *received kernel message
> Jan 1 08:41:06 2013 pluto[5254]: | netlink_get: XFRM_MSG_ACQUIRE message
> Jan 1 08:41:06 2013 pluto[5254]: | add bare shunt 0xb6108d40
> 10.14.25.4/32:54933 --6--> 10.6.25.22/32:135 => %hold 0
> %acquire-netlink
> Jan 1 08:41:06 2013 pluto[5254]: initiate on demand from
> 10.14.25.4:54933 to 10.6.25.22:135 proto=6 state: fos_start because:
> acquire
> Jan 1 08:41:06 2013 pluto[5254]: | find_connection: looking for
> policy for connection: 10.14.25.4:6/54933 -> 10.6.25.22:6/135
> Jan 1 08:41:06 2013 pluto[5254]: | find_connection: conn \"myvpn\"
> has compatible peers: 10.14.0.0/16 -> 10.0.0.0/8 [pri: 8405000]
> Jan 1 08:41:06 2013 pluto[5254]: | find_connection: comparing best
> \"myvpn\" [pri:8405000]{0xb6101178} (child none) to \"myvpn\"
> [pri:8405000]{0xb6101178} (child none)
> Jan 1 08:41:06 2013 pluto[5254]: | find_connection: concluding with
> \"myvpn\" [pri:8405000]{0xb6101178} kind=CK_PERMANENT
> Jan 1 08:41:06 2013 pluto[5254]: | assign hold, routing was
> prospective erouted, needs to be erouted HOLD
> Jan 1 08:41:06 2013 pluto[5254]: | eroute_connection replace %trap
> with broad %hold eroute 10.14.0.0/16:0 --0-> 10.0.0.0/8:0 => %hold
> (raw_eroute)
> Jan 1 08:41:06 2013 pluto[5254]: | raw_eroute result=1
> Jan 1 08:41:06 2013 pluto[5254]: | adding specific host-to-host bare shunt
> Jan 1 08:41:06 2013 pluto[5254]: | delete narrow %hold eroute
> 10.14.25.4/32:54933 --6-> 10.6.25.22/32:135 => %hold (raw_eroute)
> Jan 1 08:41:06 2013 pluto[5254]: | raw_eroute result=1
> Jan 1 08:41:06 2013 pluto[5254]: | delete bare shunt 0xb6108d40
> 10.14.25.4/32:54933 --6--> 10.6.25.22/32:135 => %hold 0
> %acquire-netlink
> Jan 1 08:41:06 2013 pluto[5254]: | Ignored already queued up pending
> Quick Mode with RIGHTEXTIP \"myvpn\"
> Jan 1 08:41:06 2013 pluto[5254]: | * processed 0 messages from
> cryptographic helpers
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_RETRANSMIT in 10
> seconds for #1
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_RETRANSMIT in 10
> seconds for #1
> Jan 1 08:41:06 2013 pluto[5254]: |
> Jan 1 08:41:06 2013 pluto[5254]: | *received kernel message
> Jan 1 08:41:06 2013 pluto[5254]: | netlink_get: XFRM_MSG_ACQUIRE message
> Jan 1 08:41:06 2013 pluto[5254]: | add bare shunt 0xb6108d40
> 10.14.2.34/32:1034 --17--> 10.6.25.22/32:53 => %hold 0
> %acquire-netlink
> Jan 1 08:41:06 2013 pluto[5254]: initiate on demand from
> 10.14.2.34:1034 to 10.6.25.22:53 proto=17 state: fos_start because:
> acquire
> Jan 1 08:41:06 2013 pluto[5254]: | find_connection: looking for
> policy for connection: 10.14.2.34:17/1034 -> 10.6.25.22:17/53
> Jan 1 08:41:06 2013 pluto[5254]: | find_connection: conn \"myvpn\"
> has compatible peers: 10.14.0.0/16 -> 10.0.0.0/8 [pri: 8405000]
> Jan 1 08:41:06 2013 pluto[5254]: | find_connection: comparing best
> \"myvpn\" [pri:8405000]{0xb6101178} (child none) to \"myvpn\"
> [pri:8405000]{0xb6101178} (child none)
> Jan 1 08:41:06 2013 pluto[5254]: | find_connection: concluding with
> \"myvpn\" [pri:8405000]{0xb6101178} kind=CK_PERMANENT
> Jan 1 08:41:06 2013 pluto[5254]: | assign hold, routing was erouted
> HOLD, needs to be erouted HOLD
> Jan 1 08:41:06 2013 pluto[5254]: | adding specific host-to-host bare shunt
> Jan 1 08:41:06 2013 pluto[5254]: | delete narrow %hold eroute
> 10.14.2.34/32:1034 --17-> 10.6.25.22/32:53 => %hold (raw_eroute)
> Jan 1 08:41:06 2013 pluto[5254]: | raw_eroute result=1
> Jan 1 08:41:06 2013 pluto[5254]: | delete bare shunt 0xb6108d40
> 10.14.2.34/32:1034 --17--> 10.6.25.22/32:53 => %hold 0
> %acquire-netlink
> Jan 1 08:41:06 2013 pluto[5254]: | Ignored already queued up pending
> Quick Mode with RIGHTEXTIP \"myvpn\"
> Jan 1 08:41:06 2013 pluto[5254]: | * processed 0 messages from
> cryptographic helpers
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_RETRANSMIT in 10
> seconds for #1
> Jan 1 08:41:06 2013 pluto[5254]: | next event EVENT_RETRANSMIT in 10
> seconds for #1
> Jan 1 08:41:08 2013 pluto[5254]: |
> Jan 1 08:41:08 2013 pluto[5254]: | *received kernel message
> Jan 1 08:41:08 2013 pluto[5254]: | netlink_get: XFRM_MSG_ACQUIRE message
>
>
>
> --
> Oguz YILMAZ
>
>
> On Tue, Jan 1, 2013 at 2:48 PM, Philippe Vouters
> <philippe.vouters at laposte.net> wrote:
>> Can you share more of the ipsec log file ? tcpdump traces do not help the
>> Openswan maintainers in this case to actually figure what can be going
>> wrong.
>>
>>
>> Philippe Vouters (Fontainebleau/France)
>> URL: http://vouters.dyndns.org/
>> SIP: sip:Vouters at sip.linphone.org
>>
>> Le 01/01/2013 13:38, Oguz Yilmaz a écrit :
>>
>>> Nothing changes. I have even rebooted the machine yesterday.
>>>
>>> --
>>> Oguz YILMAZ
>>>
>>>
>>> On Tue, Jan 1, 2013 at 2:07 PM, Philippe Vouters
>>> <philippe.vouters at laposte.net> wrote:
>>>> Dear Oguz,
>>>>
>>>> Happy New Year. What does happen if you:
>>>> 1/ /etc/init.d/network restart
>>>> 2/ ipsec setup restart
>>>> ????
>>>>
>>>> Philippe Vouters (Fontainebleau/France)
>>>> URL: http://vouters.dyndns.org/
>>>> SIP: sip:Vouters at sip.linphone.org
>>>>
>>>> Le 01/01/2013 07:58, Oguz Yilmaz a écrit :
>>>>> I have changed to singular definition and nothing changed.
>>>>>
>>>>> # ipsec setup restart
>>>>> ipsec_setup: Stopping Openswan IPsec...
>>>>> ipsec_setup: ERROR: Module xfrm6_mode_tunnel is in use
>>>>> ipsec_setup: ERROR: Module xfrm4_mode_tunnel is in use
>>>>> ipsec_setup: ERROR: Module esp4 is in use
>>>>> ipsec_setup: Starting Openswan IPsec U2.6.33/K3.5.3...
>>>>> ipsec_setup: multiple ip addresses, using LEFTEXTIP on eth9
>>>>> ipsec_setup: /usr/libexec/ipsec/addconn Not able to open
>>>>> /proc/sys/crypto/fips_enabled, returning non-fips mode
>>>>>
>>>>>
>>>>> Note: esp4 module is in use even when I stop ipsec. rmmod does not work
>>>>> either.
>>>>>
>>>>> Actually, I track thru tcpdump. Remote site never send reply for
>>>>> isakmp process. Insteadi it continues to send esp packets related with
>>>>> a previously opened ping command thru previous established spi.
>>>>>
>>>>> 08:51:10.519152 IP LEFTEXTIP.500 > RIGHTEXTIP.500: isakmp: phase 1 I
>>>>> ident
>>>>> 08:51:10.519158 IP LEFTEXTIP.500 > RIGHTEXTIP.500: isakmp: phase 1 I
>>>>> ident
>>>>> 08:51:13.531732 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf2), length 116
>>>>> 08:51:13.531732 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf2), length 116
>>>>> 08:51:14.531251 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf3), length 116
>>>>> 08:51:14.531251 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf3), length 116
>>>>> 08:51:15.531327 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf4), length 116
>>>>> 08:51:15.531327 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf4), length 116
>>>>> 08:51:16.531339 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf5), length 116
>>>>> 08:51:16.531339 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf5), length 116
>>>>> 08:51:17.531125 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf6), length 116
>>>>> 08:51:17.531125 IP RIGHTEXTIP > LEFTEXTIP:
>>>>> ESP(spi=0x23d4417b,seq=0x10cf6), length 116
>>>>> 08:51:20.955840 IP LEFTEXTIP.500 > RIGHTEXTIP.500: isakmp: phase 1 I
>>>>> ident
>>>>> 08:51:20.955844 IP LEFTEXTIP.500 > RIGHTEXTIP.500: isakmp: phase 1 I
>>>>> ident
>>>>> 08:51:40.998708 IP LEFTEXTIP.500 > RIGHTEXTIP.500: isakmp: phase 1 I
>>>>> ident
>>>>> 08:51:40.998713 IP LEFTEXTIP.500 > RIGHTEXTIP.500: isakmp: phase 1 I
>>>>> ident
>>>>>
>>>>> Jan 1 08:47:58 2013 pluto[5960]: pending Quick Mode with RIGHTEXTIP
>>>>> \"myvpn\" took too long -- replacing phase 1
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Oguz YILMAZ
>>>>>
>>>>>
>>>>> On Tue, Jan 1, 2013 at 4:02 AM, Paul Wouters <paul at nohats.ca> wrote:
>>>>>> On Tue, 1 Jan 2013, Oguz Yilmaz wrote:
>>>>>>
>>>>>>> Dec 31 15:10:13 2012 pluto[21253]: \"myvpn/0x1\" #24: STATE_QUICK_R2:
>>>>>>> IPsec SA established tunnel mode {ESP=>0x4888824c <0x23d4417b
>>>>>>> xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=enabled}
>>>>>>
>>>>>>> rightsubnets={10.0.0.0/8}
>>>>>>
>>>>>> This syntax truggers the alias code, which might not be expecting only
>>>>>> one entry. Can you change this to:
>>>>>>
>>>>>> rightsubnet=10.0.0.0/8
>>>>>>
>>>>>> Note the singular subnet, not the plural subnetS
>>>>>>
>>>>>> Then do a full restart, eg ipsec setup restart. If that fails, you
>>>>>> might need to share a little bit more log information.
>>>>>>
>>>>>> Paul
>>>>> _______________________________________________
>>>>> Swan mailing list
>>>>> Swan at lists.libreswan.org
>>>>> https://lists.libreswan.org/mailman/listinfo/swan
>>>>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20130101/3bc56d2b/attachment-0001.html>
More information about the Swan
mailing list