[Swan] Problem in reestablishment of an ipsec connection
Oguz Yilmaz
oguzyilmazlist at gmail.com
Tue Jan 1 18:12:06 EET 2013
I have recompiled openswan-2.6.38 with changing the line you remarked.
Did not helped.
The last succesfull connection was at 15:14 with spi 5b0028c7.
Jan 1 15:14:32 2013 pluto[13887]: \"myvpn/0x1\" #24: STATE_QUICK_R2:
IPsec SA established tunnel mode {ESP=>0x3af61480 <0x5b0028c7
xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=enabled}
Openswan sends isakmp requests:
18:05:30.509884 IP LEFTIP.500 > RIGHTIP.500: isakmp: phase 1 I ident
18:05:30.509887 IP LEFTIP.500 > RIGHTIP.500: isakmp: phase 1 I ident
Does not get any reply.
During this occurs, remote cisco continues to send esp packets with spi 5b0028c7
18:05:42.467983 IP RIGHTIP > LEFTIP: ESP(spi=0x5b0028c7,seq=0x11c6), length 84
18:05:42.467983 IP RIGHTIP > LEFTIP: ESP(spi=0x5b0028c7,seq=0x11c6), length 84
18:05:44.649190 IP RIGHTIP > LEFTIP: ESP(spi=0x5b0028c7,seq=0x11c7), length 84
18:05:44.649190 IP RIGHTIP > LEFTIP: ESP(spi=0x5b0028c7,seq=0x11c7), length 84
18:05:46.834829 IP RIGHTIP > LEFTIP: ESP(spi=0x5b0028c7,seq=0x11c8), length 84
--
Oguz YILMAZ
On Tue, Jan 1, 2013 at 5:40 PM, Oguz Yilmaz <oguzyilmazlist at gmail.com> wrote:
> --
> Oguz YILMAZ
>
>
> On Tue, Jan 1, 2013 at 5:17 PM, Philippe Vouters
> <philippe.vouters at laposte.net> wrote:
>> 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:
>
> Actually I have updated today to 2.6.38. It did not helped. Maybe your
> patch will help. Do you want me to prepare a small patch as below and
> try it?
> Do you think the point is this? That is, When kernel receive an esp
> packet with a previous spi, it will take it into account? Can this
> patch will make previous connection invalid on Cisco side and force
> Cisco to create a new connection? I just want to be sure about the
> problem is well understood.
>
> Thank you for your help
>
>>
>> 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
>>
>>
More information about the Swan
mailing list