[Swan] Problem in reestablishment of an ipsec connection
Oguz Yilmaz
oguzyilmazlist at gmail.com
Tue Jan 1 15:24:17 EET 2013
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