[Swan] repetitive reestablishment of ipsec
Philippe Vouters
philippe.vouters at laposte.net
Wed Jan 2 14:09:55 EET 2013
Dear Oguz,
Can you set plutodebug to only "control" ? I observed that the more you
attempt to log with Libreswan, the more you loose log entries.
I am interested in observing why the so frequent STATE_QUICK_I2.
By the way, is there any reason why you commented out:
# dpdaction=restart
# dpddelay=30
# dpdtimeout=120
???
Philippe Vouters (Fontainebleau/France)
URL: http://vouters.dyndns.org/
SIP: sip:Vouters at sip.linphone.org
Le 02/01/2013 11:36, Oguz Yilmaz a écrit :
> Log is below the email. O have seperated parts for easy perception.
>
> --
> Oguz YILMAZ
>
>
> On Wed, Jan 2, 2013 at 12:20 PM, Philippe Vouters
> <philippe.vouters at laposte.net> wrote:
>> Can you send us a relevant extract of your log file ?
>>
>> Philippe Vouters (Fontainebleau/France)
>> URL: http://vouters.dyndns.org/
>> SIP: sip:Vouters at sip.linphone.org
>>
>> Le 02/01/2013 11:09, Oguz Yilmaz a écrit :
>>> Hello,
>>>
>>> I have successfully established vpn connection. However there is
>>> continuous reestablishment of the connection. I have 2 questions:
>>>
>>>
>>>
>>> 11:49:23: restart of ipsec
>>>
>>> 11:51:09: Connection STATE_QUICK_I2
>>>
>>> 1- Why it takes about 2 minutes after restart of ipsec to establish
>>> connection?
>>>
>>> 11:51:28: Connection STATE_QUICK_I2
>>>
>>> 11:54:28: Connection STATE_QUICK_I2
>>>
>>> 2- Why it reestablish connection after about 3 minutes repetitively?
>>>
>>>
>>> Only interference I do after starting ipsec is; Each minute I run
>>> "ipsec auto --status" for specific logging purpose.
>>>
>>>
>>> version 2.0
>>>
>>> config setup
>>> interfaces=%defaultroute
>>> klipsdebug=none
>>> plutodebug="control lifecycle dpd"
>>> nat_traversal=no
>>>
>>> virtual_private=%v4:10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16,%v4:!172.19.32.0/24
>>> protostack=netkey
>>>
>>>
>>> conn %default
>>> auto=add
>>>
>>> conn myvpn
>>> authby=secret
>>> auth=esp
>>> esp=3des-md5-96
>>> leftsourceip=10.46.1.5
>>> left=LEFT_EXT_IP
>>> leftsubnet=10.46.0.0/16
>>> right=RIGHT_EXT_IP
>>> rightid=10.6.202.3
>>> rightsubnets={10.6.0.0/16,192.168.2.0/24}
>>> leftnexthop=LEFT_EXT_GW
>>> disablearrivalcheck=no
>>> auto=start
>>> keylife=86400s
>>> pfs=yes
>>> keyexchange=ike
>>> ikelifetime=86400s
>>> ike=3des-md5-modp1024
>>> # dpdaction=restart
>>> # dpddelay=30
>>> # dpdtimeout=120
>>>
>>>
>>> conn passthru
>>> type=passthrough
>>> leftsubnet=10.46.0.0/16
>>> rightsubnet=10.46.0.0/16
>>> left=10.46.1.5
>>> right=0.0.0.0
>>> authby=never
>>> auto=route
>>>
>>>
>>>
>>>
>>>
>>>
>>> 11:49:23: restart of ipsec
>>>
>>>
>>> Jan 2 11:49:22 2013 pluto[11287]: nss directory plutomain: /etc/ipsec.d
>>> Jan 2 11:49:22 2013 pluto[11287]: NSS Initialized
>>> Jan 2 11:49:22 2013 pluto[11287]: FIPS integrity support [disabled]
>>> Jan 2 11:49:22 2013 pluto[11287]: libcap-ng support [enabled]
>>> Jan 2 11:49:22 2013 pluto[11287]: Linux audit support [disabled]
>>> Jan 2 11:49:22 2013 pluto[11287]: Starting Pluto (Libreswan Version
>>> 3.0; Vendor ID OENiHcUfspQs) pid:11287
>>> Jan 2 11:49:22 2013 pluto[11287]: Not able to open
>>> /proc/sys/crypto/fips_enabled, returning non-fips mode
>>> Jan 2 11:49:22 2013 pluto[11287]: Pluto is NOT running in FIPS mode
>>> Jan 2 11:49:22 2013 pluto[11287]: core dump dir: /var/run/pluto
>>> Jan 2 11:49:22 2013 pluto[11287]: secrets file: /etc/ipsec.secrets
>>> Jan 2 11:49:22 2013 pluto[22204]: | alg_info_delref(0xb974a2a0)
>>> freeing alg_info
>>> Jan 2 11:49:22 2013 pluto[22204]: | processing connection myvpn/0x1
>>> Jan 2 11:49:22 2013 pluto[22204]: \"myvpn/0x1\": deleting connection
>>> Jan 2 11:49:22 2013 pluto[22204]: | processing connection myvpn/0x1
>>> Jan 2 11:49:22 2013 pluto[22204]: \"myvpn/0x1\" #20: deleting state
>>> (STATE_QUICK_I2)
>>> Jan 2 11:49:22 2013 pluto[22204]: | deleting state #20
>>> Jan 2 11:49:22 2013 pluto[22204]: | sending 68 bytes for delete
>>> notify through eth9.102:500 to RIGHT_EXT_IP:500 (using #19)
>>> Jan 2 11:49:22 2013 pluto[22204]: | ICOOKIE: da ea 61 2a cd 73 02 5a
>>> Jan 2 11:49:22 2013 pluto[22204]: | RCOOKIE: fc 82 4a fb 3e d0 b8 7f
>>> Jan 2 11:49:22 2013 pluto[22204]: | state hash entry 23
>>> Jan 2 11:49:22 2013 pluto[11287]: LEAK_DETECTIVE support [disabled]
>>> Jan 2 11:49:22 2013 pluto[11287]: OCF support for IKE [disabled]
>>> Jan 2 11:49:22 2013 pluto[11287]: SAref support [disabled]: Protocol
>>> not available
>>> Jan 2 11:49:22 2013 pluto[11287]: SAbind support [disabled]: Protocol
>>> not available
>>> Jan 2 11:49:22 2013 pluto[11287]: NSS crypto [enabled]
>>> Jan 2 11:49:22 2013 pluto[11287]: XAUTH PAM support [enabled]
>>> Jan 2 11:49:22 2013 pluto[11287]: HAVE_STATSD notification support
>>> [disabled]
>>> Jan 2 11:49:22 2013 pluto[11287]: Setting NAT-Traversal port-4500
>>> floating to off
>>> Jan 2 11:49:22 2013 pluto[11287]: port floating activation
>>> criteria nat_t=0/port_float=1
>>> Jan 2 11:49:22 2013 pluto[11287]: NAT-Traversal support [disabled]
>>> Jan 2 11:49:22 2013 pluto[22204]: | command executing down-client
>>> Jan 2 11:49:22 2013 pluto[11287]: | inserting event
>>> EVENT_REINIT_SECRET, timeout in 3600 seconds
>>> Jan 2 11:49:22 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_DDNS, timeout in 60 seconds
>>> Jan 2 11:49:22 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_PHASE2, timeout in 120 seconds
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_enc(): Activating
>>> OAKLEY_AES_CBC: Ok (ret=0)
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_hash(): Activating
>>> OAKLEY_SHA2_512: Ok (ret=0)
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_hash(): Activating
>>> OAKLEY_SHA2_384: Ok (ret=0)
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_hash(): Activating
>>> OAKLEY_SHA2_256: Ok (ret=0)
>>> Jan 2 11:49:22 2013 pluto[11287]: no helpers will be started, all
>>> cryptographic operations will be done inline
>>> Jan 2 11:49:22 2013 pluto[11287]: Using Linux XFRM/NETKEY IPsec
>>> interface code on 3.5.3
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_enc(): Activating
>>> aes_ccm_8: Ok (ret=0)
>>> Jan 2 11:49:22 2013 pluto[22204]: | executing down-client: 2>&1
>>> PLUTO_VERB=\'down-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0.0/16\' PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:49:22 2013 pluto[22204]: | popen(): cmd is 847 chars long
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'down-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 80):1\'
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\' :
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd(
>>> 160):PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 240):.46.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL=:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 320):\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 400):.0.0/16\'
>>> PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' P:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 480):LUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\':
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 560):
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CON:
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_add(): ERROR: algo_type
>>> \'0\', algo_id \'0\', Algorithm type already exists
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_enc(): Activating
>>> aes_ccm_12: FAILED (ret=-17)
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_add(): ERROR: algo_type
>>> \'0\', algo_id \'0\', Algorithm type already exists
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_enc(): Activating
>>> aes_ccm_16: FAILED (ret=-17)
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_add(): ERROR: algo_type
>>> \'0\', algo_id \'0\', Algorithm type already exists
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_enc(): Activating
>>> aes_gcm_8: FAILED (ret=-17)
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_add(): ERROR: algo_type
>>> \'0\', algo_id \'0\', Algorithm type already exists
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_enc(): Activating
>>> aes_gcm_12: FAILED (ret=-17)
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_add(): ERROR: algo_type
>>> \'0\', algo_id \'0\', Algorithm type already exists
>>> Jan 2 11:49:22 2013 pluto[11287]: ike_alg_register_enc(): Activating
>>> aes_gcm_16: FAILED (ret=-17)
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 640):N_ADDRFAMILY=\'ipv4\'
>>> PLUTO_XAUTH_USERNAME=\'\' PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 720):IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER_:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 800):BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:49:22 2013 pluto[22204]: | request to replace with shunt a
>>> prospective erouted policy with netkey kernel --- experimental
>>> Jan 2 11:49:22 2013 pluto[22204]: | delete inbound eroute
>>> 10.6.0.0/16:0 --0-> 10.46.0.0/16:0 => unk255.10000 at LEFT_EXT_IP
>>> (raw_eroute)
>>> Jan 2 11:49:22 2013 pluto[22204]: | raw_eroute result=1
>>> Jan 2 11:49:22 2013 pluto[22204]: | processing connection myvpn/0x1
>>> Jan 2 11:49:22 2013 pluto[22204]: \"myvpn/0x1\" #19: deleting state
>>> (STATE_MAIN_I4)
>>> Jan 2 11:49:22 2013 pluto[22204]: | deleting state #19
>>> Jan 2 11:49:22 2013 pluto[22204]: | sending 76 bytes for delete
>>> notify through eth9.102:500 to RIGHT_EXT_IP:500 (using #19)
>>> Jan 2 11:49:22 2013 pluto[11287]: | Changed path to directory
>>> \'/etc/ipsec.d/cacerts\'
>>> Jan 2 11:49:22 2013 pluto[11287]: loaded CA cert file
>>> \'cacert.pem\' (1143 bytes)
>>> Jan 2 11:49:22 2013 pluto[11287]: Could not change to directory
>>> \'/etc/ipsec.d/aacerts\': No such file or directory
>>> Jan 2 11:49:22 2013 pluto[11287]: Could not change to directory
>>> \'/etc/ipsec.d/crls\': 2 No such file or directory
>>> Jan 2 11:49:22 2013 pluto[11287]: | inserting event EVENT_LOG_DAILY,
>>> timeout in 43838 seconds
>>> Jan 2 11:49:22 2013 pluto[11287]: listening for IKE messages
>>> Jan 2 11:49:22 2013 pluto[11287]: adding interface eth9.102/eth9.102
>>> LEFT_EXT_IP:500
>>> Jan 2 11:49:22 2013 pluto[11287]: adding interface eth1/eth1
>>> 10.46.1.5:500
>>> Jan 2 11:49:22 2013 pluto[11287]: adding interface eth0/eth0
>>> 169.254.1.1:500
>>> Jan 2 11:49:22 2013 pluto[11287]: adding interface lo/lo 127.0.0.1:500
>>> Jan 2 11:49:22 2013 pluto[22204]: | ICOOKIE: da ea 61 2a cd 73 02 5a
>>> Jan 2 11:49:22 2013 pluto[22204]: | RCOOKIE: fc 82 4a fb 3e d0 b8 7f
>>> Jan 2 11:49:22 2013 pluto[22204]: | state hash entry 23
>>> Jan 2 11:49:22 2013 pluto[22204]: | request to delete a unrouted
>>> policy with netkey kernel --- experimental
>>> Jan 2 11:49:22 2013 pluto[22204]: | route owner of \"myvpn/0x1\"
>>> unrouted: NULL
>>> Jan 2 11:49:22 2013 pluto[22204]: | command executing unroute-client
>>> Jan 2 11:49:22 2013 pluto[22204]: | executing unroute-client: 2>&1
>>> PLUTO_VERB=\'unroute-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0.0/16\' PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_MY_SOURCEIP=\'10.46.1.5\'
>>> PLUTO_IS_PEER_CISCO=\'0\' PLUTO_CISCO_DNS_INFO=\'\'
>>> PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER_BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:49:22 2013 pluto[22204]: | popen(): cmd is 827 chars long
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'unroute-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 80):/0x1\'
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'RIGHT_EXT_IP:
>>> Jan 2 11:49:22 2013 pluto[11287]: | found lo with address
>>> 0000:0000:0000:0000:0000:0000:0000:0001
>>> Jan 2 11:49:22 2013 pluto[11287]: adding interface lo/lo ::1:500
>>> Jan 2 11:49:22 2013 pluto[11287]: loading secrets from
>>> \"/etc/ipsec.secrets\"
>>> Jan 2 11:49:22 2013 pluto[11287]: | id type added to
>>> secret(0xb7b6fd10) PPK_PSK: LEFT_EXT_IP
>>> Jan 2 11:49:22 2013 pluto[11287]: | id type added to
>>> secret(0xb7b6fd10) PPK_PSK: RIGHT_EXT_IP
>>> Jan 2 11:49:22 2013 pluto[11287]: | Processing PSK at line 2: passed
>>> Jan 2 11:49:22 2013 pluto[11287]: | id type added to
>>> secret(0xb7b6fe10) PPK_PSK: LEFT_EXT_IP
>>> Jan 2 11:49:22 2013 pluto[11287]: | id type added to
>>> secret(0xb7b6fe10) PPK_PSK: 10.6.202.3
>>> Jan 2 11:49:22 2013 pluto[11287]: | Processing PSK at line 4: passed
>>> Jan 2 11:49:22 2013 pluto[11287]: no secrets filename matched
>>> \"/etc/ipsec.*.secrets\"
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 160):8\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 240):\'10.46.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOC:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 320):OL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'1:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 400):0.6.0.0/16\'
>>> PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 480):\'
>>> PLUTO_PEER_PORT=\'0\' PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\'
>>> PLUTO_STACK=\'netk:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 560):ey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd(
>>> 640):CONN_ADDRFAMILY=\'ipv4\' PLUTO_MY_SOURCEIP=\'10.46.1.5\'
>>> PLUTO_IS_PEER_CISCO=\'0\' PL:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 720):UTO_CISCO_DNS_INFO=\'\'
>>> PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER_BANNER=\'\' PLUTO_NM_C:
>>> Jan 2 11:49:22 2013 pluto[22204]: | cmd( 800):ONFIGURED=\'0\' ipsec
>>> _updown:
>>> Jan 2 11:49:22 2013 pluto[22204]: \"myvpn/0x1\": unroute-client
>>> output: /usr/libexec/ipsec/_updown.netkey: doroute `ip route del
>>> 10.6.0.0/16 via 10.46.1.5 dev eth9.102 \' failed (RTNETLINK answers:
>>> No such process)
>>> Jan 2 11:49:22 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 60
>>> seconds
>>> Jan 2 11:49:22 2013 pluto[22204]: | alg_info_delref(0xb9749d88)
>>> alg_info->ref_cnt=1
>>> Jan 2 11:49:22 2013 pluto[22204]: | alg_info_delref(0xb9749d88)
>>> freeing alg_info
>>> Jan 2 11:49:22 2013 pluto[22204]: | alg_info_delref(0xb9745270)
>>> alg_info->ref_cnt=1
>>> Jan 2 11:49:22 2013 pluto[22204]: | alg_info_delref(0xb9745270)
>>> freeing alg_info
>>> Jan 2 11:49:22 2013 pluto[22204]: | processing connection passthru
>>> Jan 2 11:49:22 2013 pluto[22204]: \"passthru\": deleting connection
>>> Jan 2 11:49:22 2013 pluto[22204]: shutting down interface lo/lo ::1:500
>>> Jan 2 11:49:22 2013 pluto[22204]: shutting down interface lo/lo
>>> 127.0.0.1:500
>>> Jan 2 11:49:22 2013 pluto[22204]: shutting down interface eth0/eth0
>>> 169.254.1.1:500
>>> Jan 2 11:49:22 2013 pluto[22204]: shutting down interface eth1/eth1
>>> 10.46.1.5:500
>>> Jan 2 11:49:22 2013 pluto[22204]: shutting down interface
>>> eth9.102/eth9.102 LEFT_EXT_IP:500
>>> Jan 2 11:49:23 2013 pluto[11287]: |
>>> Jan 2 11:49:23 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:49:23 2013 pluto[11287]: | Added new connection passthru
>>> with policy PFS+IKEv2ALLOW+SAREFTRACK+PASS+NEVER_NEGOTIATE
>>> Jan 2 11:49:23 2013 pluto[11287]: | counting wild cards for 10.46.1.5 is
>>> 0
>>> Jan 2 11:49:23 2013 pluto[11287]: | counting wild cards for (none) is 15
>>> Jan 2 11:49:23 2013 pluto[11287]: added connection description
>>> \"passthru\"
>>> Jan 2 11:49:23 2013 pluto[11287]: |
>>> 10.46.0.0/16===10.46.1.5<10.46.1.5>...%any===10.46.0.0/16
>>> Jan 2 11:49:23 2013 pluto[11287]: | ike_life: 3600s; ipsec_life:
>>> 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy:
>>> PFS+IKEv2ALLOW+SAREFTRACK+PASS+NEVER_NEGOTIATE
>>> Jan 2 11:49:23 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:49:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 59
>>> seconds
>>> Jan 2 11:49:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 59
>>> seconds
>>> Jan 2 11:49:23 2013 pluto[11287]: |
>>> Jan 2 11:49:23 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:49:23 2013 pluto[11287]: | Added new connection myvpn/0x1
>>> with policy PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK
>>> Jan 2 11:49:23 2013 pluto[11287]: | from whack: got --esp=3des-md5-96
>>> Jan 2 11:49:23 2013 pluto[11287]: | esp string values:
>>> 3DES(3)_000-MD5(1)_096
>>> Jan 2 11:49:23 2013 pluto[11287]: | ike (phase1) algorihtm values:
>>> 3DES_CBC(5)_000-MD5(1)_000-MODP1024(2)
>>> Jan 2 11:49:23 2013 pluto[11287]: | counting wild cards for LEFT_EXT_IP
>>> is 0
>>> Jan 2 11:49:23 2013 pluto[11287]: | counting wild cards for 10.6.202.3 is
>>> 0
>>> Jan 2 11:49:23 2013 pluto[11287]: | alg_info_addref() alg_info->ref_cnt=1
>>> Jan 2 11:49:23 2013 pluto[11287]: | alg_info_addref() alg_info->ref_cnt=1
>>> Jan 2 11:49:23 2013 pluto[11287]: added connection description
>>> \"myvpn/0x1\"
>>> Jan 2 11:49:23 2013 pluto[11287]: |
>>>
>>> 10.46.0.0/16===LEFT_EXT_IP<LEFT_EXT_IP>---10.46.1.5...RIGHT_EXT_IP<RIGHT_EXT_IP>[10.6.202.3]===10.6.0.0/16
>>> Jan 2 11:49:23 2013 pluto[11287]: | ike_life: 86400s; ipsec_life:
>>> 86400s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy:
>>> PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK
>>> Jan 2 11:49:23 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:49:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 59
>>> seconds
>>> Jan 2 11:49:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 59
>>> seconds
>>> Jan 2 11:49:23 2013 pluto[11287]: |
>>> Jan 2 11:49:23 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:49:23 2013 pluto[11287]: | Added new connection myvpn/0x2
>>> with policy PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK
>>> Jan 2 11:49:23 2013 pluto[11287]: | from whack: got --esp=3des-md5-96
>>> Jan 2 11:49:23 2013 pluto[11287]: | esp string values:
>>> 3DES(3)_000-MD5(1)_096
>>> Jan 2 11:49:23 2013 pluto[11287]: | ike (phase1) algorihtm values:
>>> 3DES_CBC(5)_000-MD5(1)_000-MODP1024(2)
>>> Jan 2 11:49:23 2013 pluto[11287]: | counting wild cards for LEFT_EXT_IP
>>> is 0
>>> Jan 2 11:49:23 2013 pluto[11287]: | counting wild cards for 10.6.202.3 is
>>> 0
>>> Jan 2 11:49:23 2013 pluto[11287]: | alg_info_addref() alg_info->ref_cnt=1
>>> Jan 2 11:49:23 2013 pluto[11287]: | alg_info_addref() alg_info->ref_cnt=1
>>> Jan 2 11:49:23 2013 pluto[11287]: added connection description
>>> \"myvpn/0x2\"
>>> Jan 2 11:49:23 2013 pluto[11287]: |
>>>
>>> 10.46.0.0/16===LEFT_EXT_IP<LEFT_EXT_IP>---10.46.1.5...RIGHT_EXT_IP<RIGHT_EXT_IP>[10.6.202.3]===192.168.2.0/24
>>> Jan 2 11:49:23 2013 pluto[11287]: | ike_life: 86400s; ipsec_life:
>>> 86400s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy:
>>> PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK
>>> Jan 2 11:49:23 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:49:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 59
>>> seconds
>>> Jan 2 11:49:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 59
>>> seconds
>>> Jan 2 11:49:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 59
>>> seconds
>>>
>>>
>>>
>>>
>>> 11:51:09-28: Connection STATE_QUICK_I2
>>>
>>>
>>>
>>> Jan 2 11:50:06 2013 pluto[11287]: |
>>> Jan 2 11:50:06 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:50:06 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:50:06 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 16
>>> seconds
>>> Jan 2 11:50:06 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 16
>>> seconds
>>> Jan 2 11:50:10 2013 pluto[11287]: |
>>> Jan 2 11:50:10 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:50:10 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:50:10 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 12
>>> seconds
>>> Jan 2 11:50:10 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 12
>>> seconds
>>>
>>> Jan 2 11:50:22 2013 pluto[11287]: |
>>> Jan 2 11:50:22 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 0
>>> seconds
>>> Jan 2 11:50:22 2013 pluto[11287]: | *time to handle event
>>> Jan 2 11:50:22 2013 pluto[11287]: | handling event EVENT_PENDING_DDNS
>>> Jan 2 11:50:22 2013 pluto[11287]: | event after this is
>>> EVENT_PENDING_PHASE2 in 60 seconds
>>> Jan 2 11:50:22 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_DDNS, timeout in 60 seconds
>>> Jan 2 11:50:22 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 60
>>> seconds
>>>
>>>
>>>
>>> 11:51:09.802012 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x1), length 116
>>> 11:51:09.802016 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x1), length 116
>>> 11:51:09.829169 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x1), length 116
>>> 11:51:09.829169 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x1), length 116
>>> 11:51:10.803266 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x2), length 116
>>> 11:51:10.803270 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x2), length 116
>>> 11:51:10.821429 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x2), length 116
>>> 11:51:10.821429 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x2), length 116
>>> Jan 2 11:51:09 2013 pluto[11287]: |
>>> Jan 2 11:51:09 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | kernel_alg_db_new() will return
>>> p_new->protoid=3, p_new->trans_cnt=1
>>> Jan 2 11:51:09 2013 pluto[11287]: | kernel_alg_db_new() trans[0]:
>>> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
>>> Jan 2 11:51:09 2013 pluto[11287]: | returning new proposal from esp_info
>>> Jan 2 11:51:09 2013 pluto[11287]: | creating state object #1 at
>>> 0xb7b76028
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: 00 00 00 00 00 00 00 00
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 17
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting state object #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting event EVENT_SO_DISCARD,
>>> timeout in 0 seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | Queuing pending Quick Mode with
>>> RIGHT_EXT_IP \"myvpn/0x1\"
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: initiating Main Mode
>>> Jan 2 11:51:09 2013 pluto[11287]: | sending 120 bytes for main_outI1
>>> through eth9.102:500 to RIGHT_EXT_IP:500 (using #1)
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: |
>>> Jan 2 11:51:09 2013 pluto[11287]: | *received 84 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_IDPROT (2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 state object not found
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: 00 00 00 00 00 00 00 00
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 17
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 peer and cookies match on #1,
>>> provided msgid 00000000 vs 00000000
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 state object #1 found, in
>>> STATE_MAIN_I1
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | started looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:51:09 2013 pluto[11287]: | actually looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:51:09 2013 pluto[11287]: | 1: compared key 10.6.202.3 to
>>> LEFT_EXT_IP / 10.6.202.3 -> 4
>>> Jan 2 11:51:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 12
>>> Jan 2 11:51:09 2013 pluto[11287]: | line 2: match=12
>>> Jan 2 11:51:09 2013 pluto[11287]: | best_match 0>12 best=0xb7b6fe10
>>> (line=2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | 1: compared key RIGHT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 0
>>> Jan 2 11:51:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 8
>>> Jan 2 11:51:09 2013 pluto[11287]: | line 1: match=8
>>> Jan 2 11:51:09 2013 pluto[11287]: | concluding with best_match=12
>>> best=0xb7b6fe10 (lineno=2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | helper -1 doing build_kenonce op id:
>>> 0
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: 00 00 00 00 00 00 00 00
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 17
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting state object #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: transition from
>>> state STATE_MAIN_I1 to state STATE_MAIN_I2
>>> Jan 2 11:51:09 2013 pluto[11287]: | sending reply packet to
>>> RIGHT_EXT_IP:500 (from port 500)
>>> Jan 2 11:51:09 2013 pluto[11287]: | sending 180 bytes for
>>> STATE_MAIN_I1 through eth9.102:500 to RIGHT_EXT_IP:500 (using #1)
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: STATE_MAIN_I2:
>>> sent MI2, expecting MR2
>>> Jan 2 11:51:09 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:51:09 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:51:09 2013 pluto[11287]: | complete state transition with
>>> STF_INLINE
>>> Jan 2 11:51:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: |
>>> Jan 2 11:51:09 2013 pluto[11287]: | *received 256 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_IDPROT (2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 peer and cookies match on #1,
>>> provided msgid 00000000 vs 00000000
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 state object #1 found, in
>>> STATE_MAIN_I2
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: received Vendor
>>> ID payload [Cisco-Unity]
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: received Vendor
>>> ID payload [Dead Peer Detection]
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: ignoring unknown
>>> Vendor ID payload [0945ede60c8fb9c4504193ecabbc79ce]
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: received Vendor
>>> ID payload [XAUTH]
>>> Jan 2 11:51:09 2013 pluto[11287]: | started looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:51:09 2013 pluto[11287]: | actually looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:51:09 2013 pluto[11287]: | 1: compared key 10.6.202.3 to
>>> LEFT_EXT_IP / 10.6.202.3 -> 4
>>> Jan 2 11:51:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 12
>>> Jan 2 11:51:09 2013 pluto[11287]: | line 2: match=12
>>> Jan 2 11:51:09 2013 pluto[11287]: | best_match 0>12 best=0xb7b6fe10
>>> (line=2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | 1: compared key RIGHT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 0
>>> Jan 2 11:51:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 8
>>> Jan 2 11:51:09 2013 pluto[11287]: | line 1: match=8
>>> Jan 2 11:51:09 2013 pluto[11287]: | concluding with best_match=12
>>> best=0xb7b6fe10 (lineno=2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | parent1 type: 7 group: 2 len: 2680
>>> Jan 2 11:51:09 2013 pluto[11287]: | helper -1 doing compute dh+iv op id:
>>> 0
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | thinking about whether to send my
>>> certificate:
>>> Jan 2 11:51:09 2013 pluto[11287]: | I have RSA key:
>>> OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
>>> Jan 2 11:51:09 2013 pluto[11287]: | sendcert: CERT_ALWAYSSEND and I
>>> did not get a certificate request
>>> Jan 2 11:51:09 2013 pluto[11287]: | so do not send cert.
>>> Jan 2 11:51:09 2013 pluto[11287]: | I did not send a certificate
>>> because digital signatures are not being used. (PSK)
>>> Jan 2 11:51:09 2013 pluto[11287]: | I am not sending a certificate
>>> request
>>> Jan 2 11:51:09 2013 pluto[11287]: | peer supports dpd
>>> Jan 2 11:51:09 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: transition from
>>> state STATE_MAIN_I2 to state STATE_MAIN_I3
>>> Jan 2 11:51:09 2013 pluto[11287]: | sending reply packet to
>>> RIGHT_EXT_IP:500 (from port 500)
>>> Jan 2 11:51:09 2013 pluto[11287]: | sending 60 bytes for
>>> STATE_MAIN_I2 through eth9.102:500 to RIGHT_EXT_IP:500 (using #1)
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: STATE_MAIN_I3:
>>> sent MI3, expecting MR3
>>> Jan 2 11:51:09 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:51:09 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:51:09 2013 pluto[11287]: | complete state transition with
>>> STF_INLINE
>>> Jan 2 11:51:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: |
>>> Jan 2 11:51:09 2013 pluto[11287]: | *received 68 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_IDPROT (2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 peer and cookies match on #1,
>>> provided msgid 00000000 vs 00000000
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 state object #1 found, in
>>> STATE_MAIN_I3
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: Main mode peer ID
>>> is ID_IPV4_ADDR: \'10.6.202.3\'
>>> Jan 2 11:51:09 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: transition from
>>> state STATE_MAIN_I3 to state STATE_MAIN_I4
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting event EVENT_SA_REPLACE,
>>> timeout in 85407 seconds for #1
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #1: STATE_MAIN_I4:
>>> ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY
>>> cipher=oakley_3des_cbc_192 prf=oakley_md5 group=modp1024}
>>> Jan 2 11:51:09 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:51:09 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:51:09 2013 pluto[11287]: | unpending state #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | unqueuing pending Quick Mode with
>>> RIGHT_EXT_IP \"myvpn/0x1\" import:admin initiate
>>> Jan 2 11:51:09 2013 pluto[11287]: | duplicating state object #1
>>> Jan 2 11:51:09 2013 pluto[11287]: | creating state object #2 at
>>> 0xb7b8a240
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting state object #2
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting event EVENT_SO_DISCARD,
>>> timeout in 0 seconds for #2
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #2: initiating Quick
>>> Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK {using isakmp#1
>>> msgid:15c8c2e4 proposal=3DES(3)_192-MD5(1)_096
>>> pfsgroup=OAKLEY_GROUP_MODP1024}
>>> Jan 2 11:51:09 2013 pluto[11287]: | helper -1 doing build_kenonce op id:
>>> 0
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | kernel_alg_db_new() will return
>>> p_new->protoid=3, p_new->trans_cnt=1
>>> Jan 2 11:51:09 2013 pluto[11287]: | kernel_alg_db_new() trans[0]:
>>> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
>>> Jan 2 11:51:09 2013 pluto[11287]: | returning new proposal from esp_info
>>> Jan 2 11:51:09 2013 pluto[11287]: | sending 292 bytes for quick_outI1
>>> through eth9.102:500 to RIGHT_EXT_IP:500 (using #2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #2
>>> Jan 2 11:51:09 2013 pluto[11287]: | removing pending policy for
>>> \"none\" {0xb7b70780}
>>> Jan 2 11:51:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #2
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #2
>>> Jan 2 11:51:09 2013 pluto[11287]: |
>>> Jan 2 11:51:09 2013 pluto[11287]: | *received 324 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_QUICK (32)
>>> Jan 2 11:51:09 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:51:09 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 peer and cookies match on #2,
>>> provided msgid e4c2c815 vs e4c2c815
>>> Jan 2 11:51:09 2013 pluto[11287]: | v1 state object #2 found, in
>>> STATE_QUICK_I1
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #2: ignoring
>>> informational payload, type IPSEC_RESPONDER_LIFETIME msgid=15c8c2e4
>>> Jan 2 11:51:09 2013 pluto[11287]: | started looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:51:09 2013 pluto[11287]: | actually looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:51:09 2013 pluto[11287]: | 1: compared key 10.6.202.3 to
>>> LEFT_EXT_IP / 10.6.202.3 -> 4
>>> Jan 2 11:51:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 12
>>> Jan 2 11:51:09 2013 pluto[11287]: | line 2: match=12
>>> Jan 2 11:51:09 2013 pluto[11287]: | best_match 0>12 best=0xb7b6fe10
>>> (line=2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | 1: compared key RIGHT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 0
>>> Jan 2 11:51:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 8
>>> Jan 2 11:51:09 2013 pluto[11287]: | line 1: match=8
>>> Jan 2 11:51:09 2013 pluto[11287]: | concluding with best_match=12
>>> best=0xb7b6fe10 (lineno=2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | helper -1 doing compute dh(p2) op id:
>>> 0
>>> Jan 2 11:51:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:51:09 2013 pluto[11287]: | our client is subnet 10.46.0.0/16
>>> Jan 2 11:51:09 2013 pluto[11287]: | our client protocol/port is 0/0
>>> Jan 2 11:51:09 2013 pluto[11287]: | peer client is subnet 10.6.0.0/16
>>> Jan 2 11:51:09 2013 pluto[11287]: | peer client protocol/port is 0/0
>>> Jan 2 11:51:09 2013 pluto[11287]: | install_ipsec_sa() for #2:
>>> inbound and outbound
>>> Jan 2 11:51:09 2013 pluto[11287]: | route owner of \"myvpn/0x1\"
>>> unrouted: NULL; eroute owner: NULL
>>> Jan 2 11:51:09 2013 pluto[11287]: | could_route called for myvpn/0x1
>>> (kind=CK_PERMANENT)
>>> Jan 2 11:51:09 2013 pluto[11287]: | add inbound eroute 10.6.0.0/16:0
>>> --0-> 10.46.0.0/16:0 => tun.10000 at LEFT_EXT_IP (raw_eroute)
>>> Jan 2 11:51:09 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:51:09 2013 pluto[11287]: | sr for #2: unrouted
>>> Jan 2 11:51:09 2013 pluto[11287]: | route owner of \"myvpn/0x1\"
>>> unrouted: NULL; eroute owner: NULL
>>> Jan 2 11:51:09 2013 pluto[11287]: | eroute_connection add eroute
>>> 10.46.0.0/16:0 --0-> 10.6.0.0/16:0 => tun.0 at RIGHT_EXT_IP (raw_eroute)
>>> Jan 2 11:51:09 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:51:09 2013 pluto[11287]: | command executing up-client
>>> Jan 2 11:51:09 2013 pluto[11287]: | executing up-client: 2>&1
>>> PLUTO_VERB=\'up-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0.0/16\' PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:51:09 2013 pluto[11287]: | popen(): cmd is 845 chars long
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'up-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\':
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 80):
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\' PL:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd(
>>> 160):UTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.4:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 240):6.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL=\'0:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 320):\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 400):.0/16\'
>>> PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLU:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 480):TO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\' :
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 560):
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 640):ADDRFAMILY=\'ipv4\'
>>> PLUTO_XAUTH_USERNAME=\'\' PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 720):_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER_BA:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 800):NNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:51:09 2013 pluto[11287]: | route_and_eroute: firewall_notified:
>>> true
>>> Jan 2 11:51:09 2013 pluto[11287]: | command executing prepare-client
>>> Jan 2 11:51:09 2013 pluto[11287]: | executing prepare-client: 2>&1
>>> PLUTO_VERB=\'prepare-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0.0/16\' PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:51:09 2013 pluto[11287]: | popen(): cmd is 850 chars long
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'prepare-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 80):/0x1\'
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'RIGHT_EXT_IP:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 160):8\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 240):\'10.46.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOC:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 320):OL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'1:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 400):0.6.0.0/16\'
>>> PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 480):\'
>>> PLUTO_PEER_PORT=\'0\' PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\'
>>> PLUTO_STACK=\'netk:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 560):ey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd(
>>> 640):CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLU:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 720):TO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PE:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 800):ER_BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:51:09 2013 pluto[11287]: | command executing route-client
>>> Jan 2 11:51:09 2013 pluto[11287]: | executing route-client: 2>&1
>>> PLUTO_VERB=\'route-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0.0/16\' PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:51:09 2013 pluto[11287]: | popen(): cmd is 848 chars long
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'route-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 80):x1\'
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\':
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 160):
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'1:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 240):0.46.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 320):=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 400):6.0.0/16\'
>>> PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' :
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 480):PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 560):\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CO:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 640):NN_ADDRFAMILY=\'ipv4\'
>>> PLUTO_XAUTH_USERNAME=\'\' PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 720):_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER:
>>> Jan 2 11:51:09 2013 pluto[11287]: | cmd( 800):_BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #2: route-client
>>> output: /usr/libexec/ipsec/_updown.netkey: doroute `ip route replace
>>> 10.6.0.0/16 via 10.46.1.5 dev lo src 10.46.1.5\' failed (RTNETLINK
>>> answers: No such process)
>>> Jan 2 11:51:09 2013 pluto[11287]: | route_and_eroute: instance
>>> \"myvpn/0x1\", setting eroute_owner {spd=0xb7b74a80,sr=0xb7b74a80} to
>>> #2 (was #0) (newest_ipsec_sa=#0)
>>> Jan 2 11:51:09 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #2: transition from
>>> state STATE_QUICK_I1 to state STATE_QUICK_I2
>>> Jan 2 11:51:09 2013 pluto[11287]: | sending reply packet to
>>> RIGHT_EXT_IP:500 (from port 500)
>>> Jan 2 11:51:09 2013 pluto[11287]: | sending 52 bytes for
>>> STATE_QUICK_I1 through eth9.102:500 to RIGHT_EXT_IP:500 (using #2)
>>> Jan 2 11:51:09 2013 pluto[11287]: | inserting event EVENT_SA_REPLACE,
>>> timeout in 85648 seconds for #2
>>> Jan 2 11:51:09 2013 pluto[11287]: \"myvpn/0x1\" #2: STATE_QUICK_I2:
>>> sent QI2, IPsec SA established tunnel mode {ESP=>0xd56c8c25
>>> <0x6701882f xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
>>> Jan 2 11:51:09 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:51:09 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:51:09 2013 pluto[11287]: | complete state transition with
>>> STF_INLINE
>>> Jan 2 11:51:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 13
>>> seconds
>>> Jan 2 11:51:09 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 13
>>> seconds
>>> 11:51:11.804502 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x3), length 116
>>> 11:51:11.804506 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x3), length 116
>>> 11:51:11.822761 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x3), length 116
>>> 11:51:11.822761 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x3), length 116
>>> 11:51:12.804975 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x4), length 116
>>> 11:51:12.804979 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x4), length 116
>>> 11:51:12.824570 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x4), length 116
>>> 11:51:12.824570 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x4), length 116
>>> 11:51:13.805980 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x5), length 116
>>> 11:51:13.805984 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x5), length 116
>>> 11:51:13.824712 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x5), length 116
>>> 11:51:13.824712 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x5), length 116
>>> 11:51:14.806976 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x6), length 116
>>> 11:51:14.806980 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x6), length 116
>>> 11:51:14.826454 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x6), length 116
>>> 11:51:14.826454 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x6), length 116
>>> 11:51:15.808527 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x7), length 116
>>> 11:51:15.808530 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x7), length 116
>>> 11:51:15.844341 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x7), length 116
>>> 11:51:15.844341 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x7), length 116
>>> 11:51:16.810325 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x8), length 116
>>> 11:51:16.810329 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x8), length 116
>>> 11:51:16.828815 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x8), length 116
>>> 11:51:16.828815 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x8), length 116
>>> 11:51:17.810973 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x9), length 116
>>> 11:51:17.810978 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0x9), length 116
>>> 11:51:17.829091 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x9), length 116
>>> 11:51:17.829091 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0x9), length 116
>>> 11:51:18.811974 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0xa), length 116
>>> 11:51:18.811979 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0xa), length 116
>>> 11:51:18.830322 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0xa), length 116
>>> 11:51:18.830322 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0xa), length 116
>>> 11:51:19.812972 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0xb), length 116
>>> 11:51:19.812976 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0xd56c8c25,seq=0xb), length 116
>>> 11:51:19.831121 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0xb), length 116
>>> 11:51:19.831121 IP RIGHT_EXT_IP > LEFT_EXT_IP:
>>> ESP(spi=0x6701882f,seq=0xb), length 116
>>> Jan 2 11:51:23 2013 pluto[11287]: |
>>> Jan 2 11:51:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in -1
>>> seconds
>>> Jan 2 11:51:23 2013 pluto[11287]: | *time to handle event
>>> Jan 2 11:51:23 2013 pluto[11287]: | handling event EVENT_PENDING_DDNS
>>> Jan 2 11:51:23 2013 pluto[11287]: | event after this is
>>> EVENT_PENDING_PHASE2 in -1 seconds
>>> Jan 2 11:51:23 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_DDNS, timeout in 60 seconds
>>> Jan 2 11:51:23 2013 pluto[11287]: | handling event EVENT_PENDING_PHASE2
>>> Jan 2 11:51:23 2013 pluto[11287]: | event after this is
>>> EVENT_PENDING_DDNS in 60 seconds
>>> Jan 2 11:51:23 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_PHASE2, timeout in 120 seconds
>>> Jan 2 11:51:23 2013 pluto[11287]: | pending review: connection
>>> \"myvpn/0x1\" checked
>>> Jan 2 11:51:23 2013 pluto[11287]: | pending review: connection
>>> \"myvpn/0x2\" was not up, skipped
>>> Jan 2 11:51:23 2013 pluto[11287]: | pending review: connection
>>> \"passthru\" has no negotiated policy, skipped
>>> Jan 2 11:51:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 60
>>> seconds
>>> Jan 2 11:51:27 2013 pluto[11287]: |
>>> Jan 2 11:51:27 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:51:27 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:51:27 2013 pluto[11287]: \"myvpn/0x2\": terminating SAs
>>> using this connection
>>> Jan 2 11:51:27 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:51:27 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 56
>>> seconds
>>> Jan 2 11:51:27 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 56
>>> seconds
>>>
>>>
>>>
>>> 11:51:28: Connection STATE_QUICK_I2
>>>
>>>
>>>
>>>
>>> Jan 2 11:51:28 2013 pluto[11287]: |
>>> Jan 2 11:51:28 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:51:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:51:28 2013 pluto[11287]: | kernel_alg_db_new() will return
>>> p_new->protoid=3, p_new->trans_cnt=1
>>> Jan 2 11:51:28 2013 pluto[11287]: | kernel_alg_db_new() trans[0]:
>>> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
>>> Jan 2 11:51:28 2013 pluto[11287]: | returning new proposal from esp_info
>>> Jan 2 11:51:28 2013 pluto[11287]: | duplicating state object #1
>>> Jan 2 11:51:28 2013 pluto[11287]: | creating state object #3 at
>>> 0xb7b8cd10
>>> Jan 2 11:51:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:51:28 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:28 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:51:28 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:51:28 2013 pluto[11287]: | inserting state object #3
>>> Jan 2 11:51:28 2013 pluto[11287]: | inserting event EVENT_SO_DISCARD,
>>> timeout in 0 seconds for #3
>>> Jan 2 11:51:28 2013 pluto[11287]: \"myvpn/0x2\" #3: initiating Quick
>>> Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK {using isakmp#1
>>> msgid:1dd05db8 proposal=3DES(3)_192-MD5(1)_096
>>> pfsgroup=OAKLEY_GROUP_MODP1024}
>>> Jan 2 11:51:28 2013 pluto[11287]: | helper -1 doing build_kenonce op id:
>>> 0
>>> Jan 2 11:51:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:51:28 2013 pluto[11287]: | kernel_alg_db_new() will return
>>> p_new->protoid=3, p_new->trans_cnt=1
>>> Jan 2 11:51:28 2013 pluto[11287]: | kernel_alg_db_new() trans[0]:
>>> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
>>> Jan 2 11:51:28 2013 pluto[11287]: | returning new proposal from esp_info
>>> Jan 2 11:51:28 2013 pluto[11287]: | sending 292 bytes for quick_outI1
>>> through eth9.102:500 to RIGHT_EXT_IP:500 (using #3)
>>> Jan 2 11:51:28 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #3
>>> Jan 2 11:51:28 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:51:28 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #3
>>> Jan 2 11:51:28 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #3
>>> Jan 2 11:51:28 2013 pluto[11287]: |
>>> Jan 2 11:51:28 2013 pluto[11287]: | *received 324 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:51:28 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_QUICK (32)
>>> Jan 2 11:51:28 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:51:28 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:51:28 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:51:28 2013 pluto[11287]: | v1 peer and cookies match on #3,
>>> provided msgid b85dd01d vs b85dd01d
>>> Jan 2 11:51:28 2013 pluto[11287]: | v1 state object #3 found, in
>>> STATE_QUICK_I1
>>> Jan 2 11:51:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:51:28 2013 pluto[11287]: \"myvpn/0x2\" #3: ignoring
>>> informational payload, type IPSEC_RESPONDER_LIFETIME msgid=1dd05db8
>>> Jan 2 11:51:28 2013 pluto[11287]: | started looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:51:28 2013 pluto[11287]: | actually looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:51:28 2013 pluto[11287]: | 1: compared key 10.6.202.3 to
>>> LEFT_EXT_IP / 10.6.202.3 -> 4
>>> Jan 2 11:51:28 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 12
>>> Jan 2 11:51:28 2013 pluto[11287]: | line 2: match=12
>>> Jan 2 11:51:28 2013 pluto[11287]: | best_match 0>12 best=0xb7b6fe10
>>> (line=2)
>>> Jan 2 11:51:28 2013 pluto[11287]: | 1: compared key RIGHT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 0
>>> Jan 2 11:51:28 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 8
>>> Jan 2 11:51:28 2013 pluto[11287]: | line 1: match=8
>>> Jan 2 11:51:28 2013 pluto[11287]: | concluding with best_match=12
>>> best=0xb7b6fe10 (lineno=2)
>>> Jan 2 11:51:28 2013 pluto[11287]: | helper -1 doing compute dh(p2) op id:
>>> 0
>>> Jan 2 11:51:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:51:28 2013 pluto[11287]: | our client is subnet 10.46.0.0/16
>>> Jan 2 11:51:28 2013 pluto[11287]: | our client protocol/port is 0/0
>>> Jan 2 11:51:28 2013 pluto[11287]: | peer client is subnet 192.168.2.0/24
>>> Jan 2 11:51:28 2013 pluto[11287]: | peer client protocol/port is 0/0
>>> Jan 2 11:51:28 2013 pluto[11287]: | install_ipsec_sa() for #3:
>>> inbound and outbound
>>> Jan 2 11:51:28 2013 pluto[11287]: | route owner of \"myvpn/0x2\"
>>> unrouted: NULL; eroute owner: NULL
>>> Jan 2 11:51:28 2013 pluto[11287]: | could_route called for myvpn/0x2
>>> (kind=CK_PERMANENT)
>>> Jan 2 11:51:28 2013 pluto[11287]: | add inbound eroute
>>> 192.168.2.0/24:0 --0-> 10.46.0.0/16:0 => tun.10000 at LEFT_EXT_IP
>>> (raw_eroute)
>>> Jan 2 11:51:28 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:51:28 2013 pluto[11287]: | sr for #3: unrouted
>>> Jan 2 11:51:28 2013 pluto[11287]: | route owner of \"myvpn/0x2\"
>>> unrouted: NULL; eroute owner: NULL
>>> Jan 2 11:51:28 2013 pluto[11287]: | eroute_connection add eroute
>>> 10.46.0.0/16:0 --0-> 192.168.2.0/24:0 => tun.0 at RIGHT_EXT_IP
>>> (raw_eroute)
>>> Jan 2 11:51:28 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:51:28 2013 pluto[11287]: | command executing up-client
>>> Jan 2 11:51:28 2013 pluto[11287]: | executing up-client: 2>&1
>>> PLUTO_VERB=\'up-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x2\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192.168.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.255.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:51:28 2013 pluto[11287]: | popen(): cmd is 853 chars long
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'up-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x2\':
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 80):
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\' PL:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd(
>>> 160):UTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.4:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 240):6.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL=\'0:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 320):\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192.16:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 400):8.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.25:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 480):5.0\'
>>> PLUTO_PEER_PORT=\'0\' PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\'
>>> PLUTO_STACK=\'n:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 560):etkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLU:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd(
>>> 640):TO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' :
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd(
>>> 720):PLUTO_IS_PEER_CISCO=\'0\' PLUTO_CISCO_DNS_INFO=\'\'
>>> PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 800):_PEER_BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:51:28 2013 pluto[11287]: | route_and_eroute: firewall_notified:
>>> true
>>> Jan 2 11:51:28 2013 pluto[11287]: | command executing prepare-client
>>> Jan 2 11:51:28 2013 pluto[11287]: | executing prepare-client: 2>&1
>>> PLUTO_VERB=\'prepare-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x2\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192.168.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.255.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:51:28 2013 pluto[11287]: | popen(): cmd is 858 chars long
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'prepare-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 80):/0x2\'
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'RIGHT_EXT_IP:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 160):8\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 240):\'10.46.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOC:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 320):OL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'1:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 400):92.168.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\' PLUTO_PEER_CLIENT_MASK=\'255.2:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 480):55.255.0\'
>>> PLUTO_PEER_PORT=\'0\' PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\'
>>> PLUTO_STA:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 560):CK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 640):\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 720):1.5\'
>>> PLUTO_IS_PEER_CISCO=\'0\' PLUTO_CISCO_DNS_INFO=\'\'
>>> PLUTO_CISCO_DOMAIN_INFO=\'\' :
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 800):PLUTO_PEER_BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:51:28 2013 pluto[11287]: | command executing route-client
>>> Jan 2 11:51:28 2013 pluto[11287]: | executing route-client: 2>&1
>>> PLUTO_VERB=\'route-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x2\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192.168.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.255.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:51:28 2013 pluto[11287]: | popen(): cmd is 856 chars long
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'route-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 80):x2\'
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\':
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 160):
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'1:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 240):0.46.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 320):=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 400):.168.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 480):.255.0\'
>>> PLUTO_PEER_PORT=\'0\' PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\'
>>> PLUTO_STACK:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 560):=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> :
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd(
>>> 640):PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 720):5\'
>>> PLUTO_IS_PEER_CISCO=\'0\' PLUTO_CISCO_DNS_INFO=\'\'
>>> PLUTO_CISCO_DOMAIN_INFO=\'\' PL:
>>> Jan 2 11:51:28 2013 pluto[11287]: | cmd( 800):UTO_PEER_BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:51:28 2013 pluto[11287]: \"myvpn/0x2\" #3: route-client
>>> output: /usr/libexec/ipsec/_updown.netkey: doroute `ip route replace
>>> 192.168.2.0/24 via 10.46.1.5 dev lo src 10.46.1.5\' failed (RTNETLINK
>>> answers: No such process)
>>> Jan 2 11:51:28 2013 pluto[11287]: | route_and_eroute: instance
>>> \"myvpn/0x2\", setting eroute_owner {spd=0xb7b75808,sr=0xb7b75808} to
>>> #3 (was #0) (newest_ipsec_sa=#0)
>>> Jan 2 11:51:28 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:51:28 2013 pluto[11287]: \"myvpn/0x2\" #3: transition from
>>> state STATE_QUICK_I1 to state STATE_QUICK_I2
>>> Jan 2 11:51:28 2013 pluto[11287]: | sending reply packet to
>>> RIGHT_EXT_IP:500 (from port 500)
>>> Jan 2 11:51:28 2013 pluto[11287]: | sending 52 bytes for
>>> STATE_QUICK_I1 through eth9.102:500 to RIGHT_EXT_IP:500 (using #3)
>>> Jan 2 11:51:28 2013 pluto[11287]: | inserting event EVENT_SA_REPLACE,
>>> timeout in 85438 seconds for #3
>>> Jan 2 11:51:28 2013 pluto[11287]: \"myvpn/0x2\" #3: STATE_QUICK_I2:
>>> sent QI2, IPsec SA established tunnel mode {ESP=>0x6a888967
>>> <0x2c7a6d85 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
>>> Jan 2 11:51:28 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:51:28 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:51:28 2013 pluto[11287]: | complete state transition with
>>> STF_INLINE
>>> Jan 2 11:51:28 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:51:28 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 55
>>> seconds
>>> Jan 2 11:51:28 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 55
>>> seconds
>>> 11:51:31.354216 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1), length 84
>>> 11:51:31.354219 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1), length 84
>>> 11:51:31.354249 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x2), length 84
>>> 11:51:31.354251 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x2), length 84
>>> 11:51:31.572952 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x3), length 84
>>> 11:51:31.572956 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x3), length 84
>>> Jan 2 11:52:23 2013 pluto[11287]: |
>>> Jan 2 11:52:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 0
>>> seconds
>>> Jan 2 11:52:23 2013 pluto[11287]: | *time to handle event
>>> Jan 2 11:52:23 2013 pluto[11287]: | handling event EVENT_PENDING_DDNS
>>> Jan 2 11:52:23 2013 pluto[11287]: | event after this is
>>> EVENT_PENDING_PHASE2 in 60 seconds
>>> Jan 2 11:52:23 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_DDNS, timeout in 60 seconds
>>> Jan 2 11:52:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 60
>>> seconds
>>>
>>>
>>>
>>>
>>>
>>>
>>> 11:54:28: Connection STATE_QUICK_I2
>>>
>>>
>>>
>>>
>>>
>>> Jan 2 11:53:04 2013 pluto[11287]: |
>>> Jan 2 11:53:04 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:53:04 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:53:04 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 19
>>> seconds
>>> Jan 2 11:53:04 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 19
>>> seconds
>>> Jan 2 11:53:04 2013 sshd[14623]: pam_unix(sshd:session): session
>>> closed for user root
>>> 11:53:14.429868 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0xd), length 84
>>> 11:53:14.429872 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0xd), length 84
>>> 11:53:14.430215 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0xe), length 84
>>> 11:53:14.430218 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0xe), length 84
>>> 11:53:14.802997 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0xf), length 84
>>> 11:53:14.803002 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0xf), length 84
>>> 11:53:17.342457 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x10), length 84
>>> 11:53:17.342461 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x10), length 84
>>> 11:53:17.342491 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x11), length 84
>>> 11:53:17.342492 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x11), length 84
>>> 11:53:17.670548 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x12), length 84
>>> 11:53:17.670553 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x12), length 84
>>> 11:53:23.358268 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x13), length 84
>>> 11:53:23.358273 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x13), length 84
>>> 11:53:23.358301 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x14), length 84
>>> 11:53:23.358304 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x14), length 84
>>> 11:53:23.686416 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x15), length 84
>>> 11:53:23.686421 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x15), length 84
>>> Jan 2 11:53:23 2013 pluto[11287]: |
>>> Jan 2 11:53:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 0
>>> seconds
>>> Jan 2 11:53:23 2013 pluto[11287]: | *time to handle event
>>> Jan 2 11:53:23 2013 pluto[11287]: | handling event EVENT_PENDING_DDNS
>>> Jan 2 11:53:23 2013 pluto[11287]: | event after this is
>>> EVENT_PENDING_PHASE2 in 0 seconds
>>> Jan 2 11:53:23 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_DDNS, timeout in 60 seconds
>>> Jan 2 11:53:23 2013 pluto[11287]: | handling event EVENT_PENDING_PHASE2
>>> Jan 2 11:53:23 2013 pluto[11287]: | event after this is
>>> EVENT_PENDING_DDNS in 60 seconds
>>> Jan 2 11:53:23 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_PHASE2, timeout in 120 seconds
>>> Jan 2 11:53:23 2013 pluto[11287]: | pending review: connection
>>> \"myvpn/0x2\" checked
>>> Jan 2 11:53:23 2013 pluto[11287]: | pending review: connection
>>> \"myvpn/0x1\" checked
>>> Jan 2 11:53:23 2013 pluto[11287]: | pending review: connection
>>> \"passthru\" has no negotiated policy, skipped
>>> Jan 2 11:53:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 60
>>> seconds
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> Jan 2 11:54:05 2013 pluto[11287]: |
>>> Jan 2 11:54:05 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:54:05 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:05 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 18
>>> seconds
>>> Jan 2 11:54:05 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 18
>>> seconds
>>> Jan 2 11:54:08 2013 pluto[11287]: |
>>> Jan 2 11:54:08 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:54:08 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:08 2013 pluto[11287]: \"myvpn/0x1\": terminating SAs
>>> using this connection
>>> Jan 2 11:54:08 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:08 2013 pluto[11287]: \"myvpn/0x1\" #2: deleting state
>>> (STATE_QUICK_I2)
>>> Jan 2 11:54:08 2013 pluto[11287]: | deleting state #2
>>> Jan 2 11:54:08 2013 pluto[11287]: | sending 68 bytes for delete
>>> notify through eth9.102:500 to RIGHT_EXT_IP:500 (using #1)
>>> Jan 2 11:54:08 2013 pluto[11287]: | command executing down-client
>>> Jan 2 11:54:08 2013 pluto[11287]: | executing down-client: 2>&1
>>> PLUTO_VERB=\'down-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0.0/16\' PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:54:08 2013 pluto[11287]: | popen(): cmd is 844 chars long
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'down-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x:
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 80):1\'
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\' :
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd(
>>> 160):PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10:
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 240):.46.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL=:
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 320):\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6:
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 400):.0.0/16\'
>>> PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' P:
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 480):LUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\':
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 560):
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_A:
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 640):DDRFAMILY=\'ipv4\'
>>> PLUTO_XAUTH_USERNAME=\'\' PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_:
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 720):PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER_BAN:
>>> Jan 2 11:54:08 2013 pluto[11287]: | cmd( 800):NER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:54:08 2013 pluto[11287]: | request to replace with shunt a
>>> prospective erouted policy with netkey kernel --- experimental
>>> Jan 2 11:54:08 2013 pluto[11287]: | delete inbound eroute
>>> 10.6.0.0/16:0 --0-> 10.46.0.0/16:0 => unk255.10000 at LEFT_EXT_IP
>>> (raw_eroute)
>>> Jan 2 11:54:08 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:54:08 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:08 2013 pluto[11287]: \"myvpn/0x1\" #1: deleting state
>>> (STATE_MAIN_I4)
>>> Jan 2 11:54:08 2013 pluto[11287]: | deleting state #1
>>> Jan 2 11:54:08 2013 pluto[11287]: | sending 76 bytes for delete
>>> notify through eth9.102:500 to RIGHT_EXT_IP:500 (using #1)
>>> Jan 2 11:54:08 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:08 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 15
>>> seconds
>>> Jan 2 11:54:08 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 15
>>> seconds
>>> Jan 2 11:54:08 2013 pluto[11287]: |
>>> Jan 2 11:54:08 2013 pluto[11287]: | *received 84 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:54:08 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_INFO (5)
>>> Jan 2 11:54:08 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:54:08 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:54:08 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:54:08 2013 pluto[11287]: | peer and cookies match on #3,
>>> provided msgid 00000000 vs b85dd01d/00000000
>>> Jan 2 11:54:08 2013 pluto[11287]: | p15 state object not found
>>> Jan 2 11:54:08 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:54:08 2013 pluto[11287]: | RCOOKIE: 00 00 00 00 00 00 00 00
>>> Jan 2 11:54:08 2013 pluto[11287]: | state hash entry 17
>>> Jan 2 11:54:08 2013 pluto[11287]: | v1 state object not found
>>> Jan 2 11:54:08 2013 pluto[11287]: packet from RIGHT_EXT_IP:500:
>>> Informational Exchange is for an unknown (expired?) SA with
>>> MSGID:0xfced3903
>>> Jan 2 11:54:08 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:08 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 15
>>> seconds
>>> Jan 2 11:54:08 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 15
>>> seconds
>>> Jan 2 11:54:09 2013 pluto[11287]: |
>>> Jan 2 11:54:09 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | kernel_alg_db_new() will return
>>> p_new->protoid=3, p_new->trans_cnt=1
>>> Jan 2 11:54:09 2013 pluto[11287]: | kernel_alg_db_new() trans[0]:
>>> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
>>> Jan 2 11:54:09 2013 pluto[11287]: | returning new proposal from esp_info
>>> Jan 2 11:54:09 2013 pluto[11287]: | creating state object #4 at
>>> 0xb7b76028
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: 00 00 00 00 00 00 00 00
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 24
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting state object #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting event EVENT_SO_DISCARD,
>>> timeout in 0 seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | Queuing pending Quick Mode with
>>> RIGHT_EXT_IP \"myvpn/0x1\"
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: initiating Main Mode
>>> Jan 2 11:54:09 2013 pluto[11287]: | sending 120 bytes for main_outI1
>>> through eth9.102:500 to RIGHT_EXT_IP:500 (using #4)
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: |
>>> Jan 2 11:54:09 2013 pluto[11287]: | *received 84 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_IDPROT (2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 05 71 9b 3d
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 13
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 state object not found
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: 00 00 00 00 00 00 00 00
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 24
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 peer and cookies match on #4,
>>> provided msgid 00000000 vs 00000000
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 state object #4 found, in
>>> STATE_MAIN_I1
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | started looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:54:09 2013 pluto[11287]: | actually looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:54:09 2013 pluto[11287]: | 1: compared key 10.6.202.3 to
>>> LEFT_EXT_IP / 10.6.202.3 -> 4
>>> Jan 2 11:54:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 12
>>> Jan 2 11:54:09 2013 pluto[11287]: | line 2: match=12
>>> Jan 2 11:54:09 2013 pluto[11287]: | best_match 0>12 best=0xb7b6fe10
>>> (line=2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | 1: compared key RIGHT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 0
>>> Jan 2 11:54:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 8
>>> Jan 2 11:54:09 2013 pluto[11287]: | line 1: match=8
>>> Jan 2 11:54:09 2013 pluto[11287]: | concluding with best_match=12
>>> best=0xb7b6fe10 (lineno=2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | helper -1 doing build_kenonce op id:
>>> 0
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: 00 00 00 00 00 00 00 00
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 24
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 05 71 9b 3d
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 13
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting state object #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: transition from
>>> state STATE_MAIN_I1 to state STATE_MAIN_I2
>>> Jan 2 11:54:09 2013 pluto[11287]: | sending reply packet to
>>> RIGHT_EXT_IP:500 (from port 500)
>>> Jan 2 11:54:09 2013 pluto[11287]: | sending 180 bytes for
>>> STATE_MAIN_I1 through eth9.102:500 to RIGHT_EXT_IP:500 (using #4)
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: STATE_MAIN_I2:
>>> sent MI2, expecting MR2
>>> Jan 2 11:54:09 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:54:09 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:54:09 2013 pluto[11287]: | complete state transition with
>>> STF_INLINE
>>> Jan 2 11:54:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: |
>>> Jan 2 11:54:09 2013 pluto[11287]: | *received 256 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_IDPROT (2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 05 71 9b 3d
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 13
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 peer and cookies match on #4,
>>> provided msgid 00000000 vs 00000000
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 state object #4 found, in
>>> STATE_MAIN_I2
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: received Vendor
>>> ID payload [Cisco-Unity]
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: received Vendor
>>> ID payload [Dead Peer Detection]
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: ignoring unknown
>>> Vendor ID payload [0945ede605709b3d7bfd4d757cbb572d]
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: received Vendor
>>> ID payload [XAUTH]
>>> Jan 2 11:54:09 2013 pluto[11287]: | started looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:54:09 2013 pluto[11287]: | actually looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:54:09 2013 pluto[11287]: | 1: compared key 10.6.202.3 to
>>> LEFT_EXT_IP / 10.6.202.3 -> 4
>>> Jan 2 11:54:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 12
>>> Jan 2 11:54:09 2013 pluto[11287]: | line 2: match=12
>>> Jan 2 11:54:09 2013 pluto[11287]: | best_match 0>12 best=0xb7b6fe10
>>> (line=2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | 1: compared key RIGHT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 0
>>> Jan 2 11:54:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 8
>>> Jan 2 11:54:09 2013 pluto[11287]: | line 1: match=8
>>> Jan 2 11:54:09 2013 pluto[11287]: | concluding with best_match=12
>>> best=0xb7b6fe10 (lineno=2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | parent1 type: 7 group: 2 len: 2680
>>> Jan 2 11:54:09 2013 pluto[11287]: | helper -1 doing compute dh+iv op id:
>>> 0
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | thinking about whether to send my
>>> certificate:
>>> Jan 2 11:54:09 2013 pluto[11287]: | I have RSA key:
>>> OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
>>> Jan 2 11:54:09 2013 pluto[11287]: | sendcert: CERT_ALWAYSSEND and I
>>> did not get a certificate request
>>> Jan 2 11:54:09 2013 pluto[11287]: | so do not send cert.
>>> Jan 2 11:54:09 2013 pluto[11287]: | I did not send a certificate
>>> because digital signatures are not being used. (PSK)
>>> Jan 2 11:54:09 2013 pluto[11287]: | I am not sending a certificate
>>> request
>>> Jan 2 11:54:09 2013 pluto[11287]: | peer supports dpd
>>> Jan 2 11:54:09 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: transition from
>>> state STATE_MAIN_I2 to state STATE_MAIN_I3
>>> Jan 2 11:54:09 2013 pluto[11287]: | sending reply packet to
>>> RIGHT_EXT_IP:500 (from port 500)
>>> Jan 2 11:54:09 2013 pluto[11287]: | sending 60 bytes for
>>> STATE_MAIN_I2 through eth9.102:500 to RIGHT_EXT_IP:500 (using #4)
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: STATE_MAIN_I3:
>>> sent MI3, expecting MR3
>>> Jan 2 11:54:09 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:54:09 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:54:09 2013 pluto[11287]: | complete state transition with
>>> STF_INLINE
>>> Jan 2 11:54:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: |
>>> Jan 2 11:54:09 2013 pluto[11287]: | *received 68 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_IDPROT (2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 05 71 9b 3d
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 13
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 peer and cookies match on #4,
>>> provided msgid 00000000 vs 00000000
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 state object #4 found, in
>>> STATE_MAIN_I3
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: Main mode peer ID
>>> is ID_IPV4_ADDR: \'10.6.202.3\'
>>> Jan 2 11:54:09 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: transition from
>>> state STATE_MAIN_I3 to state STATE_MAIN_I4
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting event EVENT_SA_REPLACE,
>>> timeout in 85429 seconds for #4
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #4: STATE_MAIN_I4:
>>> ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY
>>> cipher=oakley_3des_cbc_192 prf=oakley_md5 group=modp1024}
>>> Jan 2 11:54:09 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:54:09 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:54:09 2013 pluto[11287]: | unpending state #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | unqueuing pending Quick Mode with
>>> RIGHT_EXT_IP \"myvpn/0x1\" import:admin initiate
>>> Jan 2 11:54:09 2013 pluto[11287]: | duplicating state object #4
>>> Jan 2 11:54:09 2013 pluto[11287]: | creating state object #5 at
>>> 0xb7b8a240
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 05 71 9b 3d
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 13
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting state object #5
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting event EVENT_SO_DISCARD,
>>> timeout in 0 seconds for #5
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #5: initiating Quick
>>> Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK {using isakmp#4
>>> msgid:7fbfab9f proposal=3DES(3)_192-MD5(1)_096
>>> pfsgroup=OAKLEY_GROUP_MODP1024}
>>> Jan 2 11:54:09 2013 pluto[11287]: | helper -1 doing build_kenonce op id:
>>> 0
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | kernel_alg_db_new() will return
>>> p_new->protoid=3, p_new->trans_cnt=1
>>> Jan 2 11:54:09 2013 pluto[11287]: | kernel_alg_db_new() trans[0]:
>>> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
>>> Jan 2 11:54:09 2013 pluto[11287]: | returning new proposal from esp_info
>>> Jan 2 11:54:09 2013 pluto[11287]: | sending 292 bytes for quick_outI1
>>> through eth9.102:500 to RIGHT_EXT_IP:500 (using #5)
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #5
>>> Jan 2 11:54:09 2013 pluto[11287]: | removing pending policy for
>>> \"none\" {0xb7b7e1f8}
>>> Jan 2 11:54:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #5
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #5
>>> Jan 2 11:54:09 2013 pluto[11287]: |
>>> Jan 2 11:54:09 2013 pluto[11287]: | *received 324 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_QUICK (32)
>>> Jan 2 11:54:09 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:09 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 05 71 9b 3d
>>> Jan 2 11:54:09 2013 pluto[11287]: | state hash entry 13
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 peer and cookies match on #5,
>>> provided msgid 9fabbf7f vs 9fabbf7f
>>> Jan 2 11:54:09 2013 pluto[11287]: | v1 state object #5 found, in
>>> STATE_QUICK_I1
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #5: ignoring
>>> informational payload, type IPSEC_RESPONDER_LIFETIME msgid=7fbfab9f
>>> Jan 2 11:54:09 2013 pluto[11287]: | started looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:54:09 2013 pluto[11287]: | actually looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:54:09 2013 pluto[11287]: | 1: compared key 10.6.202.3 to
>>> LEFT_EXT_IP / 10.6.202.3 -> 4
>>> Jan 2 11:54:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 12
>>> Jan 2 11:54:09 2013 pluto[11287]: | line 2: match=12
>>> Jan 2 11:54:09 2013 pluto[11287]: | best_match 0>12 best=0xb7b6fe10
>>> (line=2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | 1: compared key RIGHT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 0
>>> Jan 2 11:54:09 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 8
>>> Jan 2 11:54:09 2013 pluto[11287]: | line 1: match=8
>>> Jan 2 11:54:09 2013 pluto[11287]: | concluding with best_match=12
>>> best=0xb7b6fe10 (lineno=2)
>>> Jan 2 11:54:09 2013 pluto[11287]: | helper -1 doing compute dh(p2) op id:
>>> 0
>>> Jan 2 11:54:09 2013 pluto[11287]: | processing connection myvpn/0x1
>>> Jan 2 11:54:09 2013 pluto[11287]: | our client is subnet 10.46.0.0/16
>>> Jan 2 11:54:09 2013 pluto[11287]: | our client protocol/port is 0/0
>>> Jan 2 11:54:09 2013 pluto[11287]: | peer client is subnet 10.6.0.0/16
>>> Jan 2 11:54:09 2013 pluto[11287]: | peer client protocol/port is 0/0
>>> Jan 2 11:54:09 2013 pluto[11287]: | install_ipsec_sa() for #5:
>>> inbound and outbound
>>> Jan 2 11:54:09 2013 pluto[11287]: | route owner of \"myvpn/0x1\"
>>> prospective erouted: self; eroute owner: self
>>> Jan 2 11:54:09 2013 pluto[11287]: | could_route called for myvpn/0x1
>>> (kind=CK_PERMANENT)
>>> Jan 2 11:54:09 2013 pluto[11287]: | add inbound eroute 10.6.0.0/16:0
>>> --0-> 10.46.0.0/16:0 => tun.10000 at LEFT_EXT_IP (raw_eroute)
>>> Jan 2 11:54:09 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:54:09 2013 pluto[11287]: | sr for #5: prospective erouted
>>> Jan 2 11:54:09 2013 pluto[11287]: | route owner of \"myvpn/0x1\"
>>> prospective erouted: self; eroute owner: self
>>> Jan 2 11:54:09 2013 pluto[11287]: | eroute_connection replace eroute
>>> 10.46.0.0/16:0 --0-> 10.6.0.0/16:0 => tun.0 at RIGHT_EXT_IP (raw_eroute)
>>> Jan 2 11:54:09 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:54:09 2013 pluto[11287]: | command executing up-client
>>> Jan 2 11:54:09 2013 pluto[11287]: | executing up-client: 2>&1
>>> PLUTO_VERB=\'up-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0.0/16\' PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:54:09 2013 pluto[11287]: | popen(): cmd is 845 chars long
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'up-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x1\':
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 80):
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\' PL:
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd(
>>> 160):UTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.4:
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 240):6.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL=\'0:
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 320):\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'10.6.0:
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 400):.0/16\'
>>> PLUTO_PEER_CLIENT_NET=\'10.6.0.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.0.0\' PLU:
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 480):TO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\' :
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 560):
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_:
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 640):ADDRFAMILY=\'ipv4\'
>>> PLUTO_XAUTH_USERNAME=\'\' PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS:
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 720):_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_PEER_BA:
>>> Jan 2 11:54:09 2013 pluto[11287]: | cmd( 800):NNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:54:09 2013 pluto[11287]: | route_and_eroute: firewall_notified:
>>> true
>>> Jan 2 11:54:09 2013 pluto[11287]: | route_and_eroute: instance
>>> \"myvpn/0x1\", setting eroute_owner {spd=0xb7b74a80,sr=0xb7b74a80} to
>>> #5 (was #0) (newest_ipsec_sa=#0)
>>> Jan 2 11:54:09 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #5: transition from
>>> state STATE_QUICK_I1 to state STATE_QUICK_I2
>>> Jan 2 11:54:09 2013 pluto[11287]: | sending reply packet to
>>> RIGHT_EXT_IP:500 (from port 500)
>>> Jan 2 11:54:09 2013 pluto[11287]: | sending 52 bytes for
>>> STATE_QUICK_I1 through eth9.102:500 to RIGHT_EXT_IP:500 (using #5)
>>> Jan 2 11:54:09 2013 pluto[11287]: | inserting event EVENT_SA_REPLACE,
>>> timeout in 85368 seconds for #5
>>> Jan 2 11:54:09 2013 pluto[11287]: \"myvpn/0x1\" #5: STATE_QUICK_I2:
>>> sent QI2, IPsec SA established tunnel mode {ESP=>0x200299c1
>>> <0x6fa1e7e1 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
>>> Jan 2 11:54:09 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:54:09 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:54:09 2013 pluto[11287]: | complete state transition with
>>> STF_INLINE
>>> Jan 2 11:54:09 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 14
>>> seconds
>>> Jan 2 11:54:09 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 14
>>> seconds
>>> 11:54:10.439255 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x16), length 84
>>> 11:54:10.439259 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x16), length 84
>>> 11:54:10.439604 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x17), length 84
>>> 11:54:10.439607 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x17), length 84
>>> 11:54:10.844762 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x18), length 84
>>> 11:54:10.844766 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x18), length 84
>>> 11:54:13.344494 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x19), length 84
>>> 11:54:13.344498 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x19), length 84
>>> 11:54:13.344528 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1a), length 84
>>> 11:54:13.344531 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1a), length 84
>>> 11:54:13.782002 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1b), length 84
>>> 11:54:13.782006 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1b), length 84
>>> 11:54:19.360295 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1c), length 84
>>> 11:54:19.360299 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1c), length 84
>>> 11:54:19.360329 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1d), length 84
>>> 11:54:19.360332 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1d), length 84
>>> 11:54:19.797809 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1e), length 84
>>> 11:54:19.797813 IP LEFT_EXT_IP > RIGHT_EXT_IP:
>>> ESP(spi=0x6a888967,seq=0x1e), length 84
>>> Jan 2 11:54:23 2013 pluto[11287]: |
>>> Jan 2 11:54:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 0
>>> seconds
>>> Jan 2 11:54:23 2013 pluto[11287]: | *time to handle event
>>> Jan 2 11:54:23 2013 pluto[11287]: | handling event EVENT_PENDING_DDNS
>>> Jan 2 11:54:23 2013 pluto[11287]: | event after this is
>>> EVENT_PENDING_PHASE2 in 60 seconds
>>> Jan 2 11:54:23 2013 pluto[11287]: | inserting event
>>> EVENT_PENDING_DDNS, timeout in 60 seconds
>>> Jan 2 11:54:23 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 60
>>> seconds
>>> Jan 2 11:54:27 2013 pluto[11287]: |
>>> Jan 2 11:54:27 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:54:27 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:54:27 2013 pluto[11287]: \"myvpn/0x2\": terminating SAs
>>> using this connection
>>> Jan 2 11:54:27 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:54:27 2013 pluto[11287]: \"myvpn/0x2\" #3: deleting state
>>> (STATE_QUICK_I2)
>>> Jan 2 11:54:27 2013 pluto[11287]: | deleting state #3
>>> Jan 2 11:54:27 2013 pluto[11287]: | sending 68 bytes for delete
>>> notify through eth9.102:500 to RIGHT_EXT_IP:500 (using #4)
>>> Jan 2 11:54:27 2013 pluto[11287]: | ICOOKIE: f8 ad 5c ad 78 34 05 6c
>>> Jan 2 11:54:27 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 0c 8e b9 c4
>>> Jan 2 11:54:27 2013 pluto[11287]: | state hash entry 29
>>> Jan 2 11:54:27 2013 pluto[11287]: | command executing down-client
>>> Jan 2 11:54:27 2013 pluto[11287]: | executing down-client: 2>&1
>>> PLUTO_VERB=\'down-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x2\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192.168.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.255.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:54:27 2013 pluto[11287]: | popen(): cmd is 852 chars long
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'down-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd( 80):2\'
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\' :
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd(
>>> 160):PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd( 240):.46.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL=:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd( 320):\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192.:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd( 400):168.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd( 480):255.0\'
>>> PLUTO_PEER_PORT=\'0\' PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\'
>>> PLUTO_STACK=:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd( 560):\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK\'
>>> PLUT:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd(
>>> 640):O_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' P:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd(
>>> 720):LUTO_IS_PEER_CISCO=\'0\' PLUTO_CISCO_DNS_INFO=\'\'
>>> PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO_:
>>> Jan 2 11:54:27 2013 pluto[11287]: | cmd( 800):PEER_BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:54:27 2013 pluto[11287]: | request to replace with shunt a
>>> prospective erouted policy with netkey kernel --- experimental
>>> Jan 2 11:54:27 2013 pluto[11287]: | delete inbound eroute
>>> 192.168.2.0/24:0 --0-> 10.46.0.0/16:0 => unk255.10000 at LEFT_EXT_IP
>>> (raw_eroute)
>>> Jan 2 11:54:27 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:54:27 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:27 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 56
>>> seconds
>>> Jan 2 11:54:27 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 56
>>> seconds
>>> Jan 2 11:54:28 2013 pluto[11287]: |
>>> Jan 2 11:54:28 2013 pluto[11287]: | *received whack message
>>> Jan 2 11:54:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:54:28 2013 pluto[11287]: | kernel_alg_db_new() will return
>>> p_new->protoid=3, p_new->trans_cnt=1
>>> Jan 2 11:54:28 2013 pluto[11287]: | kernel_alg_db_new() trans[0]:
>>> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
>>> Jan 2 11:54:28 2013 pluto[11287]: | returning new proposal from esp_info
>>> Jan 2 11:54:28 2013 pluto[11287]: | duplicating state object #4
>>> Jan 2 11:54:28 2013 pluto[11287]: | creating state object #6 at
>>> 0xb7b8cd10
>>> Jan 2 11:54:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:54:28 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:28 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 05 71 9b 3d
>>> Jan 2 11:54:28 2013 pluto[11287]: | state hash entry 13
>>> Jan 2 11:54:28 2013 pluto[11287]: | inserting state object #6
>>> Jan 2 11:54:28 2013 pluto[11287]: | inserting event EVENT_SO_DISCARD,
>>> timeout in 0 seconds for #6
>>> Jan 2 11:54:28 2013 pluto[11287]: \"myvpn/0x2\" #6: initiating Quick
>>> Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK {using isakmp#4
>>> msgid:334da0a5 proposal=3DES(3)_192-MD5(1)_096
>>> pfsgroup=OAKLEY_GROUP_MODP1024}
>>> Jan 2 11:54:28 2013 pluto[11287]: | helper -1 doing build_kenonce op id:
>>> 0
>>> Jan 2 11:54:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:54:28 2013 pluto[11287]: | kernel_alg_db_new() will return
>>> p_new->protoid=3, p_new->trans_cnt=1
>>> Jan 2 11:54:28 2013 pluto[11287]: | kernel_alg_db_new() trans[0]:
>>> transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=1
>>> Jan 2 11:54:28 2013 pluto[11287]: | returning new proposal from esp_info
>>> Jan 2 11:54:28 2013 pluto[11287]: | sending 292 bytes for quick_outI1
>>> through eth9.102:500 to RIGHT_EXT_IP:500 (using #6)
>>> Jan 2 11:54:28 2013 pluto[11287]: | inserting event EVENT_RETRANSMIT,
>>> timeout in 10 seconds for #6
>>> Jan 2 11:54:28 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:28 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #6
>>> Jan 2 11:54:28 2013 pluto[11287]: | next event EVENT_RETRANSMIT in 10
>>> seconds for #6
>>> Jan 2 11:54:28 2013 pluto[11287]: |
>>> Jan 2 11:54:28 2013 pluto[11287]: | *received 324 bytes from
>>> RIGHT_EXT_IP:500 on eth9.102 (port=500)
>>> Jan 2 11:54:28 2013 pluto[11287]: | processing version=1.0 packet
>>> with exchange type=ISAKMP_XCHG_QUICK (32)
>>> Jan 2 11:54:28 2013 pluto[11287]: | ICOOKIE: c0 e6 2c 93 5b 91 11 86
>>> Jan 2 11:54:28 2013 pluto[11287]: | RCOOKIE: fc 82 4a fb 05 71 9b 3d
>>> Jan 2 11:54:28 2013 pluto[11287]: | state hash entry 13
>>> Jan 2 11:54:28 2013 pluto[11287]: | v1 peer and cookies match on #6,
>>> provided msgid a5a04d33 vs a5a04d33
>>> Jan 2 11:54:28 2013 pluto[11287]: | v1 state object #6 found, in
>>> STATE_QUICK_I1
>>> Jan 2 11:54:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:54:28 2013 pluto[11287]: \"myvpn/0x2\" #6: ignoring
>>> informational payload, type IPSEC_RESPONDER_LIFETIME msgid=334da0a5
>>> Jan 2 11:54:28 2013 pluto[11287]: | started looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:54:28 2013 pluto[11287]: | actually looking for secret for
>>> LEFT_EXT_IP->10.6.202.3 of kind PPK_PSK
>>> Jan 2 11:54:28 2013 pluto[11287]: | 1: compared key 10.6.202.3 to
>>> LEFT_EXT_IP / 10.6.202.3 -> 4
>>> Jan 2 11:54:28 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 12
>>> Jan 2 11:54:28 2013 pluto[11287]: | line 2: match=12
>>> Jan 2 11:54:28 2013 pluto[11287]: | best_match 0>12 best=0xb7b6fe10
>>> (line=2)
>>> Jan 2 11:54:28 2013 pluto[11287]: | 1: compared key RIGHT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 0
>>> Jan 2 11:54:28 2013 pluto[11287]: | 2: compared key LEFT_EXT_IP to
>>> LEFT_EXT_IP / 10.6.202.3 -> 8
>>> Jan 2 11:54:28 2013 pluto[11287]: | line 1: match=8
>>> Jan 2 11:54:28 2013 pluto[11287]: | concluding with best_match=12
>>> best=0xb7b6fe10 (lineno=2)
>>> Jan 2 11:54:28 2013 pluto[11287]: | helper -1 doing compute dh(p2) op id:
>>> 0
>>> Jan 2 11:54:28 2013 pluto[11287]: | processing connection myvpn/0x2
>>> Jan 2 11:54:28 2013 pluto[11287]: | our client is subnet 10.46.0.0/16
>>> Jan 2 11:54:28 2013 pluto[11287]: | our client protocol/port is 0/0
>>> Jan 2 11:54:28 2013 pluto[11287]: | peer client is subnet 192.168.2.0/24
>>> Jan 2 11:54:28 2013 pluto[11287]: | peer client protocol/port is 0/0
>>> Jan 2 11:54:28 2013 pluto[11287]: | install_ipsec_sa() for #6:
>>> inbound and outbound
>>> Jan 2 11:54:28 2013 pluto[11287]: | route owner of \"myvpn/0x2\"
>>> prospective erouted: self; eroute owner: self
>>> Jan 2 11:54:28 2013 pluto[11287]: | could_route called for myvpn/0x2
>>> (kind=CK_PERMANENT)
>>> Jan 2 11:54:28 2013 pluto[11287]: | add inbound eroute
>>> 192.168.2.0/24:0 --0-> 10.46.0.0/16:0 => tun.10000 at LEFT_EXT_IP
>>> (raw_eroute)
>>> Jan 2 11:54:28 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:54:28 2013 pluto[11287]: | sr for #6: prospective erouted
>>> Jan 2 11:54:28 2013 pluto[11287]: | route owner of \"myvpn/0x2\"
>>> prospective erouted: self; eroute owner: self
>>> Jan 2 11:54:28 2013 pluto[11287]: | eroute_connection replace eroute
>>> 10.46.0.0/16:0 --0-> 192.168.2.0/24:0 => tun.0 at RIGHT_EXT_IP
>>> (raw_eroute)
>>> Jan 2 11:54:28 2013 pluto[11287]: | raw_eroute result=1
>>> Jan 2 11:54:28 2013 pluto[11287]: | command executing up-client
>>> Jan 2 11:54:28 2013 pluto[11287]: | executing up-client: 2>&1
>>> PLUTO_VERB=\'up-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x2\' PLUTO_INTERFACE=\'eth9.102\'
>>> PLUTO_NEXT_HOP=\'10.46.1.5\' PLUTO_ME=\'LEFT_EXT_IP\'
>>> PLUTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.46.0.0\' PLUTO_MY_CLIENT_MASK=\'255.255.0.0\'
>>> PLUTO_MY_PORT=\'0\' PLUTO_MY_PROTOCOL=\'0\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192.168.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.255.0\' PLUTO_PEER_PORT=\'0\'
>>> PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\' PLUTO_STACK=\'netkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLUTO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' PLUTO_IS_PEER_CISCO=\'0\'
>>> PLUTO_CISCO_DNS_INFO=\'\' PLUTO_CISCO_DOMAIN_INFO=\'\'
>>> PLUTO_PEER_BANNER=\'\' PLUTO_NM_CONFIGURED=\'0\' ipsec _updown
>>> Jan 2 11:54:28 2013 pluto[11287]: | popen(): cmd is 853 chars long
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd( 0):2>&1
>>> PLUTO_VERB=\'up-client\' PLUTO_VERSION=\'2.0\'
>>> PLUTO_CONNECTION=\'myvpn/0x2\':
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd( 80):
>>> PLUTO_INTERFACE=\'eth9.102\' PLUTO_NEXT_HOP=\'10.46.1.5\'
>>> PLUTO_ME=\'LEFT_EXT_IP\' PL:
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd(
>>> 160):UTO_MY_ID=\'LEFT_EXT_IP\' PLUTO_MY_CLIENT=\'10.46.0.0/16\'
>>> PLUTO_MY_CLIENT_NET=\'10.4:
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd( 240):6.0.0\'
>>> PLUTO_MY_CLIENT_MASK=\'255.255.0.0\' PLUTO_MY_PORT=\'0\'
>>> PLUTO_MY_PROTOCOL=\'0:
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd( 320):\'
>>> PLUTO_PEER=\'RIGHT_EXT_IP\' PLUTO_PEER_ID=\'10.6.202.3\'
>>> PLUTO_PEER_CLIENT=\'192.16:
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd( 400):8.2.0/24\'
>>> PLUTO_PEER_CLIENT_NET=\'192.168.2.0\'
>>> PLUTO_PEER_CLIENT_MASK=\'255.255.25:
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd( 480):5.0\'
>>> PLUTO_PEER_PORT=\'0\' PLUTO_PEER_PROTOCOL=\'0\' PLUTO_PEER_CA=\'\'
>>> PLUTO_STACK=\'n:
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd( 560):etkey\'
>>> PLUTO_CONN_POLICY=\'PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+SAREFTRACK\'
>>> PLU:
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd(
>>> 640):TO_CONN_ADDRFAMILY=\'ipv4\' PLUTO_XAUTH_USERNAME=\'\'
>>> PLUTO_MY_SOURCEIP=\'10.46.1.5\' :
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd(
>>> 720):PLUTO_IS_PEER_CISCO=\'0\' PLUTO_CISCO_DNS_INFO=\'\'
>>> PLUTO_CISCO_DOMAIN_INFO=\'\' PLUTO:
>>> Jan 2 11:54:28 2013 pluto[11287]: | cmd( 800):_PEER_BANNER=\'\'
>>> PLUTO_NM_CONFIGURED=\'0\' ipsec _updown:
>>> Jan 2 11:54:28 2013 pluto[11287]: | route_and_eroute: firewall_notified:
>>> true
>>> Jan 2 11:54:28 2013 pluto[11287]: | route_and_eroute: instance
>>> \"myvpn/0x2\", setting eroute_owner {spd=0xb7b75808,sr=0xb7b75808} to
>>> #6 (was #0) (newest_ipsec_sa=#0)
>>> Jan 2 11:54:28 2013 pluto[11287]: | complete state transition with STF_OK
>>> Jan 2 11:54:28 2013 pluto[11287]: \"myvpn/0x2\" #6: transition from
>>> state STATE_QUICK_I1 to state STATE_QUICK_I2
>>> Jan 2 11:54:28 2013 pluto[11287]: | sending reply packet to
>>> RIGHT_EXT_IP:500 (from port 500)
>>> Jan 2 11:54:28 2013 pluto[11287]: | sending 52 bytes for
>>> STATE_QUICK_I1 through eth9.102:500 to RIGHT_EXT_IP:500 (using #6)
>>> Jan 2 11:54:28 2013 pluto[11287]: | inserting event EVENT_SA_REPLACE,
>>> timeout in 85754 seconds for #6
>>> Jan 2 11:54:28 2013 pluto[11287]: \"myvpn/0x2\" #6: STATE_QUICK_I2:
>>> sent QI2, IPsec SA established tunnel mode {ESP=>0x6be0409c
>>> <0x5386fe04 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
>>> Jan 2 11:54:28 2013 pluto[11287]: | modecfg pull: noquirk policy:push
>>> not-client
>>> Jan 2 11:54:28 2013 pluto[11287]: | phase 1 is done, looking for
>>> phase 2 to unpend
>>> Jan 2 11:54:28 2013 pluto[11287]: | complete state transition with
>>> STF_INLINE
>>> Jan 2 11:54:28 2013 pluto[11287]: | * processed 0 messages from
>>> cryptographic helpers
>>> Jan 2 11:54:28 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 55
>>> seconds
>>> Jan 2 11:54:28 2013 pluto[11287]: | next event EVENT_PENDING_DDNS in 55
>>> seconds
>>> _______________________________________________
>>> Swan mailing list
>>> Swan at lists.libreswan.org
>>> https://lists.libreswan.org/mailman/listinfo/swan
>>>
More information about the Swan
mailing list