[Openswan Users] pluto: deleting connection instance with peer -- why?
JOR HAY
flexbumpchest at gmail.com
Sun May 13 22:02:39 EDT 2007
Hi,
I'm having some trouble with a Windows XP IPSEC connection to my l2tpd.
I've changed my OpenSWAN server's ip to yyy.yyy.yyy.254 and my client's
(which is natted on a network) external IP to xxx.xxx.xxx.xxx. OpenSWAN is
on Fedora Core 6 with the KLIPS and NAT-T patches compiled into the kernel.
I made a VPN connection setup through windows and have checked and
re-checked and all the settings are right. When I go to connect, after
about a minute, it gives Error 678:
Error Connecting to yyy.yyy.yyy.254
Error 678: The remote computer did not respond. For further assistance,
click More Info or search Help and Support Center for this error number.
I'm fairly certain it's the IPSEC connection (see log below). If I need to
run any other commands for you to see other confs or logs, let me know.
ipsec verify:
Version check and ipsec on-path [OK]
Linux Openswan Uopenswan-2.4.7-27.fc6.at/K2.4.7 (klips)
Checking for IPsec support in kernel [OK]
Checking for RSA private key (/etc/ipsec.d/hostkey.secrets) [OK]
Checking that pluto is running [OK]
Two or more interfaces found, checking IP forwarding [FAILED]
Checking for 'ip' command [OK]
Checking for 'iptables' command [OK]
Opportunistic Encryption Support [DISABLED]
Contents of /etc/ipsec.conf
# /etc/ipsec.conf - Openswan IPsec configuration file
#
# Manual: ipsec.conf.5
#
# Please place your own config files in /etc/ipsec.d/ ending in .conf
version 2.0 # conforms to second version of ipsec.conf specification
# basic configuration
config setup
# Debug-logging controls: "none" for (almost) none, "all" for lots.
klipsdebug=none
plutodebug=control
interfaces="ipsec0=eth0:3"
nat_traversal=yes
virtual_private=%v4:10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16,%v4:172.23.23.0/24
<http://10.0.0.0/8,%25v4:172.16.0.0/12,%25v4:192.168.0.0/16,%25v4:172.23.23.0/24>
include /etc/ipsec.d/*.conf
Contents of /etc/ipsec.d/no_oe.conf
# 'include' this file to disable Opportunistic Encryption.
# See /usr/share/doc/openswan/policygroups.html for details.
#
# RCSID $Id: no_oe.conf.in,v 1.2 2004/10/03 19:33:10 paul Exp $
conn block
auto=ignore
conn private
auto=ignore
conn private-or-clear
auto=ignore
conn clear-or-private
auto=ignore
conn clear
auto=ignore
conn packetdefault
auto=ignore
Contents of /etc/ipsec.d/l2tpd.conf
# Configuration supporting multiple users with any type of
# IPsec/L2TP client. This includes the updated Windows 2000/XP
# (MS KB Q818043), Vista and Mac OS X 10.3+ but excludes the
# non-updated Windows 2000/XP.
#
# Authenticates through a Pre-Shared Key. Supports clients that
# are not behind NAT. Does not support clients that are behind NAT.
conn L2TP-WINXP
#
type=transport
authby=secret
pfs=no
rekey=no
keyingtries=3
#
# ----------------------------------------------------------
# The VPN server.
#
# Allow incoming connections on the external network interface.
# If you want to use a different interface or if there is no
# %defaultroute, you can use: left=your.ip.addr.ess
#
left=yyy.yyy.yyy.254
leftprotoport=17/1701
# If you insist on supporting non-updated Windows clients,
# you can use: leftprotoport=17/%any
#
# ----------------------------------------------------------
# The remote user(s).
#
# Allow incoming connections only from this IP address.
right=%any
# If you want to allow multiple connections from any IP address,
# you can use: right=%any
#
rightprotoport=17/%any
#
# ----------------------------------------------------------
# Change 'ignore' to 'add' to enable this configuration.
#
auto=add
Contents of /var/log/secure
May 13 18:47:22 myserver ipsec__plutorun: Starting Pluto subsystem...
May 13 18:47:22 myserver pluto[28835]: Starting Pluto (Openswan Version
openswan-2.4.7-27.fc6.at PLUTO_SENDS_VENDORID PLUTO_USES_KEYRR; Vendor ID
OEOY\177IH|k}Gs)
May 13 18:47:22 myserver pluto[28835]: Setting NAT-Traversal port-4500
floating to on
May 13 18:47:22 myserver pluto[28835]: port floating activation criteria
nat_t=1/port_fload=1
May 13 18:47:22 myserver pluto[28835]: including NAT-Traversal patch
(Version 0.6c)
May 13 18:47:22 myserver pluto[28835]: | opening /dev/urandom
May 13 18:47:22 myserver pluto[28835]: | inserting event
EVENT_REINIT_SECRET, timeout in 3600 seconds
May 13 18:47:22 myserver pluto[28835]: | inserting event
EVENT_PENDING_PHASE2, timeout in 120 seconds
May 13 18:47:22 myserver pluto[28835]: ike_alg_register_enc(): Activating
OAKLEY_AES_CBC: Ok (ret=0)
May 13 18:47:22 myserver pluto[28835]: starting up 3 cryptographic helpers
May 13 18:47:22 myserver pluto[28876]: | opening /dev/urandom
May 13 18:47:22 myserver pluto[28835]: started helper pid=28876 (fd:6)
May 13 18:47:22 myserver pluto[28876]: ! helper 0 waiting on fd: 7
May 13 18:47:22 myserver pluto[28877]: | opening /dev/urandom
May 13 18:47:22 myserver pluto[28835]: started helper pid=28877 (fd:7)
May 13 18:47:22 myserver pluto[28877]: ! helper 1 waiting on fd: 8
May 13 18:47:22 myserver pluto[28878]: | opening /dev/urandom
May 13 18:47:22 myserver pluto[28835]: started helper pid=28878 (fd:8)
May 13 18:47:23 myserver pluto[28878]: ! helper 2 waiting on fd: 9
May 13 18:47:23 myserver pluto[28835]: Using KLIPS IPsec interface code on
2.6.18
May 13 18:47:23 myserver pluto[28835]: | inserting event EVENT_SHUNT_SCAN,
timeout in 120 seconds
May 13 18:47:23 myserver pluto[28835]: Changing to directory
'/etc/ipsec.d/cacerts'
May 13 18:47:23 myserver pluto[28835]: Changing to directory
'/etc/ipsec.d/aacerts'
May 13 18:47:23 myserver pluto[28835]: Changing to directory
'/etc/ipsec.d/ocspcerts'
May 13 18:47:23 myserver pluto[28835]: Changing to directory
'/etc/ipsec.d/crls'
May 13 18:47:23 myserver pluto[28835]: Warning: empty directory
May 13 18:47:23 myserver pluto[28835]: | inserting event EVENT_LOG_DAILY,
timeout in 18757 seconds
May 13 18:47:23 myserver pluto[28835]: | next event EVENT_PENDING_PHASE2 in
119 seconds
May 13 18:47:23 myserver pluto[28835]: |
May 13 18:47:23 myserver pluto[28835]: | *received whack message
May 13 18:47:23 myserver pluto[28835]: | Added new connection L2TP-WINXP
with policy PSK+ENCRYPT+DONTREKEY
May 13 18:47:23 myserver pluto[28835]: | counting wild cards for (none) is
15
May 13 18:47:23 myserver pluto[28835]: | counting wild cards for (none) is
15
May 13 18:47:23 myserver pluto[28835]: | based upon policy, the connection
is a template.
May 13 18:47:24 myserver pluto[28835]: added connection description
"L2TP-WINXP"
May 13 18:47:24 myserver pluto[28835]: | yyy.yyy.yyy.254
:17/1701...%any:17/%any
May 13 18:47:24 myserver pluto[28835]: | ike_life: 3600s; ipsec_life:
28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 3; policy:
PSK+ENCRYPT+DONTREKEY
May 13 18:47:24 myserver pluto[28835]: | next event EVENT_PENDING_PHASE2 in
118 seconds
May 13 18:47:24 myserver pluto[28835]: |
May 13 18:47:24 myserver pluto[28835]: | *received whack message
May 13 18:47:24 myserver pluto[28835]: listening for IKE messages
May 13 18:47:24 myserver pluto[28835]: | found ipsec0 with address
yyy.yyy.yyy.254
May 13 18:47:24 myserver pluto[28835]: | found lo with address 127.0.0.1
May 13 18:47:24 myserver pluto[28835]: | found eth0 with address
yyy.yyy.yyy.250
May 13 18:47:24 myserver pluto[28835]: | found eth0:5 with address
172.23.23.99
May 13 18:47:24 myserver pluto[28835]: | found eth0:0 with address
yyy.yyy.yyy.251
May 13 18:47:24 myserver pluto[28835]: | found eth0:1 with address
yyy.yyy.yyy.252
May 13 18:47:24 myserver pluto[28835]: | found eth0:2 with address
yyy.yyy.yyy.253
May 13 18:47:24 myserver pluto[28835]: | found eth0:3 with address
yyy.yyy.yyy.254
May 13 18:47:24 myserver pluto[28835]: adding interface ipsec0/eth0:3
yyy.yyy.yyy.254:500
May 13 18:47:24 myserver pluto[28835]: adding interface ipsec0/eth0:3
yyy.yyy.yyy.254:4500
May 13 18:47:25 myserver pluto[28835]: | IP interface eth0:2
yyy.yyy.yyy.253has no matching ipsec* interface -- ignored
May 13 18:47:25 myserver pluto[28835]: | IP interface eth0:1
yyy.yyy.yyy.252has no matching ipsec* interface -- ignored
May 13 18:47:25 myserver pluto[28835]: | IP interface eth0:0
yyy.yyy.yyy.251has no matching ipsec* interface -- ignored
May 13 18:47:25 myserver pluto[28835]: | IP interface eth0:5
172.23.23.99has no matching ipsec* interface -- ignored
May 13 18:47:25 myserver pluto[28835]: | IP interface eth0
yyy.yyy.yyy.250has no matching ipsec* interface -- ignored
May 13 18:47:25 myserver pluto[28835]: | IP interface lo 127.0.0.1 has no
matching ipsec* interface -- ignored
May 13 18:47:25 myserver pluto[28835]: | could not open /proc/net/if_inet6
May 13 18:47:25 myserver pluto[28835]: loading secrets from
"/etc/ipsec.secrets"
May 13 18:47:25 myserver pluto[28835]: | next event EVENT_PENDING_PHASE2 in
117 seconds
May 13 18:47:31 myserver pluto[28835]: |
May 13 18:47:31 myserver pluto[28835]: | *received 312 bytes from
xxx.xxx.xxx.xxx:22133 on eth0:3 (port=500)
May 13 18:47:31 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_IDPROT (2)
May 13 18:47:31 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22133:
ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000004]
May 13 18:47:31 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22133:
ignoring Vendor ID payload [FRAGMENTATION]
May 13 18:47:31 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22133:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] method set
to=106
May 13 18:47:31 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22133:
ignoring Vendor ID payload [Vid-Initial-Contact]
May 13 18:47:31 myserver pluto[28835]: | instantiated "L2TP-WINXP" for
xxx.xxx.xxx.xxx
May 13 18:47:31 myserver pluto[28835]: | creating state object #1 at
0x81008f8
May 13 18:47:31 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:31 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:31 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:31 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:31 myserver pluto[28835]: | state hash entry 16
May 13 18:47:31 myserver pluto[28835]: | inserting event EVENT_SO_DISCARD,
timeout in 0 seconds for #1
May 13 18:47:31 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
responding to Main Mode from unknown peer xxx.xxx.xxx.xxx
May 13 18:47:31 myserver pluto[28835]: | started looking for secret for
yyy.yyy.yyy.254->xxx.xxx.xxx.xxx of kind PPK_PSK
May 13 18:47:31 myserver pluto[28835]: | instantiating him to 0.0.0.0
May 13 18:47:31 myserver pluto[28835]: | actually looking for secret for
yyy.yyy.yyy.254->0.0.0.0 of kind PPK_PSK
May 13 18:47:31 myserver pluto[28835]: | 1: compared PSK 0.0.0.0 to
yyy.yyy.yyy.254 / xxx.xxx.xxx.xxx -> 2
May 13 18:47:31 myserver pluto[28835]: | 2: compared PSK yyy.yyy.yyy.254 to
yyy.yyy.yyy.254 / xxx.xxx.xxx.xxx -> 6
May 13 18:47:31 myserver pluto[28835]: | best_match 0>6 best=0x80ff260
(line=3)
May 13 18:47:32 myserver pluto[28835]: | concluding with best_match=6
best=0x80ff260 (lineno=3)
May 13 18:47:32 myserver pluto[28835]: | complete state transition with
STF_OK
May 13 18:47:32 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
May 13 18:47:32 myserver pluto[28835]: | sending reply packet to
xxx.xxx.xxx.xxx:22133 (from port=500)
May 13 18:47:32 myserver pluto[28835]: | sending 140 bytes for STATE_MAIN_R0
through eth0:3:500 to xxx.xxx.xxx.xxx:22133:
May 13 18:47:32 myserver pluto[28835]: | inserting event EVENT_RETRANSMIT,
timeout in 10 seconds for #1
May 13 18:47:32 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
STATE_MAIN_R1: sent MR1, expecting MI2
May 13 18:47:32 myserver pluto[28835]: | modecfg pull: noquirk policy:push
not-client
May 13 18:47:32 myserver pluto[28835]: | phase 1 is done, looking for phase
1 to unpend
May 13 18:47:32 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 10
seconds for #1
May 13 18:47:32 myserver pluto[28835]: |
May 13 18:47:32 myserver pluto[28835]: | *received 312 bytes from
xxx.xxx.xxx.xxx:22133 on eth0:3 (port=500)
May 13 18:47:32 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_IDPROT (2)
May 13 18:47:32 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22133:
ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000004]
May 13 18:47:32 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22133:
ignoring Vendor ID payload [FRAGMENTATION]
May 13 18:47:32 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22133:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] method set
to=106
May 13 18:47:32 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22133:
ignoring Vendor ID payload [Vid-Initial-Contact]
May 13 18:47:33 myserver pluto[28835]: | creating state object #2 at
0x8100e68
May 13 18:47:33 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:33 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:33 myserver pluto[28835]: | RCOOKIE: ae 98 87 4e 5b 8d 38 62
May 13 18:47:33 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:33 myserver pluto[28835]: | state hash entry 8
May 13 18:47:33 myserver pluto[28835]: | inserting event EVENT_SO_DISCARD,
timeout in 0 seconds for #2
May 13 18:47:33 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #2:
responding to Main Mode from unknown peer xxx.xxx.xxx.xxx
May 13 18:47:33 myserver pluto[28835]: | started looking for secret for
yyy.yyy.yyy.254->xxx.xxx.xxx.xxx of kind PPK_PSK
May 13 18:47:33 myserver pluto[28835]: | instantiating him to 0.0.0.0
May 13 18:47:33 myserver pluto[28835]: | actually looking for secret for
yyy.yyy.yyy.254->0.0.0.0 of kind PPK_PSK
May 13 18:47:33 myserver pluto[28835]: | 1: compared PSK 0.0.0.0 to
yyy.yyy.yyy.254 / xxx.xxx.xxx.xxx -> 2
May 13 18:47:33 myserver pluto[28835]: | 2: compared PSK yyy.yyy.yyy.254 to
yyy.yyy.yyy.254 / xxx.xxx.xxx.xxx -> 6
May 13 18:47:33 myserver pluto[28835]: | best_match 0>6 best=0x80ff260
(line=3)
May 13 18:47:33 myserver pluto[28835]: | concluding with best_match=6
best=0x80ff260 (lineno=3)
May 13 18:47:33 myserver pluto[28835]: | complete state transition with
STF_OK
May 13 18:47:33 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #2:
transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
May 13 18:47:34 myserver pluto[28835]: | sending reply packet to
xxx.xxx.xxx.xxx:22133 (from port=500)
May 13 18:47:34 myserver pluto[28835]: | sending 140 bytes for STATE_MAIN_R0
through eth0:3:500 to xxx.xxx.xxx.xxx:22133:
May 13 18:47:34 myserver pluto[28835]: | inserting event EVENT_RETRANSMIT,
timeout in 10 seconds for #2
May 13 18:47:34 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #2:
STATE_MAIN_R1: sent MR1, expecting MI2
May 13 18:47:34 myserver pluto[28835]: | modecfg pull: noquirk policy:push
not-client
May 13 18:47:34 myserver pluto[28835]: | phase 1 is done, looking for phase
1 to unpend
May 13 18:47:34 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 8
seconds for #1
May 13 18:47:34 myserver pluto[28835]: |
May 13 18:47:34 myserver pluto[28835]: | *received 360 bytes from
xxx.xxx.xxx.xxx:22133 on eth0:3 (port=500)
May 13 18:47:34 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_IDPROT (2)
May 13 18:47:34 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:34 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:34 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:34 myserver pluto[28835]: | state hash entry 16
May 13 18:47:34 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000
May 13 18:47:34 myserver pluto[28835]: | state object #1 found, in
STATE_MAIN_R1
May 13 18:47:34 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:35 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike-02/03: peer is NATed
May 13 18:47:35 myserver pluto[28835]: | inserting event
EVENT_NAT_T_KEEPALIVE, timeout in 20 seconds
May 13 18:47:35 myserver pluto[28835]: | 1: w->pcw_dead: 0 w->pcw_work: 0
cnt: 3
May 13 18:47:35 myserver pluto[28835]: | asking helper 1 to do build_kenonce
op on seq: 1
May 13 18:47:35 myserver pluto[28835]: | inserting event
EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
May 13 18:47:35 myserver pluto[28877]: ! helper -1 doing build_kenonce op
id: 1
May 13 18:47:35 myserver pluto[28835]: | complete state transition with
STF_SUSPEND
May 13 18:47:35 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 9
seconds for #2
May 13 18:47:35 myserver pluto[28835]: |
May 13 18:47:35 myserver pluto[28835]: | *received 360 bytes from
xxx.xxx.xxx.xxx:22133 on eth0:3 (port=500)
May 13 18:47:35 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_IDPROT (2)
May 13 18:47:35 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:35 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:35 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:35 myserver pluto[28835]: | state hash entry 16
May 13 18:47:35 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000
May 13 18:47:35 myserver pluto[28835]: | state object #1 found, in
STATE_MAIN_R1
May 13 18:47:36 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:36 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
discarding packet received during asynchronous work (DNS or crypto) in
STATE_MAIN_R1
May 13 18:47:36 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:36 myserver pluto[28835]: | started looking for secret for
yyy.yyy.yyy.254->xxx.xxx.xxx.xxx of kind PPK_PSK
May 13 18:47:36 myserver pluto[28835]: | instantiating him to 0.0.0.0
May 13 18:47:36 myserver pluto[28835]: | actually looking for secret for
yyy.yyy.yyy.254->0.0.0.0 of kind PPK_PSK
May 13 18:47:36 myserver pluto[28835]: | 1: compared PSK 0.0.0.0 to
yyy.yyy.yyy.254 / xxx.xxx.xxx.xxx -> 2
May 13 18:47:36 myserver pluto[28835]: | 2: compared PSK yyy.yyy.yyy.254 to
yyy.yyy.yyy.254 / xxx.xxx.xxx.xxx -> 6
May 13 18:47:36 myserver pluto[28835]: | best_match 0>6 best=0x80ff260
(line=3)
May 13 18:47:36 myserver pluto[28835]: | concluding with best_match=6
best=0x80ff260 (lineno=3)
May 13 18:47:36 myserver pluto[28835]: | complete state transition with
STF_OK
May 13 18:47:36 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
May 13 18:47:36 myserver pluto[28835]: | sending reply packet to
xxx.xxx.xxx.xxx:22133 (from port=500)
May 13 18:47:36 myserver pluto[28835]: | sending 356 bytes for STATE_MAIN_R1
through eth0:3:500 to xxx.xxx.xxx.xxx:22133:
May 13 18:47:36 myserver pluto[28835]: | inserting event EVENT_RETRANSMIT,
timeout in 10 seconds for #1
May 13 18:47:36 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
STATE_MAIN_R2: sent MR2, expecting MI3
May 13 18:47:36 myserver pluto[28835]: | modecfg pull: noquirk policy:push
not-client
May 13 18:47:36 myserver pluto[28835]: | phase 1 is done, looking for phase
1 to unpend
May 13 18:47:37 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 7
seconds for #2
May 13 18:47:37 myserver pluto[28835]: |
May 13 18:47:37 myserver pluto[28835]: | *received 68 bytes from
xxx.xxx.xxx.xxx:22155 on eth0:3 (port=4500)
May 13 18:47:37 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_IDPROT (2)
May 13 18:47:37 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:37 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:37 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:37 myserver pluto[28835]: | state hash entry 16
May 13 18:47:37 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000
May 13 18:47:37 myserver pluto[28835]: | state object #1 found, in
STATE_MAIN_R2
May 13 18:47:37 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:37 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
Main mode peer ID is ID_FQDN: '@vader'
May 13 18:47:37 myserver pluto[28835]: | started looking for secret for
yyy.yyy.yyy.254->xxx.xxx.xxx.xxx of kind PPK_PSK
May 13 18:47:37 myserver pluto[28835]: | instantiating him to 0.0.0.0
May 13 18:47:37 myserver pluto[28835]: | actually looking for secret for
yyy.yyy.yyy.254->0.0.0.0 of kind PPK_PSK
May 13 18:47:37 myserver pluto[28835]: | 1: compared PSK 0.0.0.0 to
yyy.yyy.yyy.254 / xxx.xxx.xxx.xxx -> 2
May 13 18:47:37 myserver pluto[28835]: | 2: compared PSK yyy.yyy.yyy.254 to
yyy.yyy.yyy.254 / xxx.xxx.xxx.xxx -> 6
May 13 18:47:38 myserver pluto[28835]: | best_match 0>6 best=0x80ff260
(line=3)
May 13 18:47:38 myserver pluto[28835]: | concluding with best_match=6
best=0x80ff260 (lineno=3)
May 13 18:47:38 myserver pluto[28835]: | started looking for secret for
yyy.yyy.yyy.254->(none) of kind PPK_PSK
May 13 18:47:38 myserver pluto[28835]: | replace him to 0.0.0.0
May 13 18:47:38 myserver pluto[28835]: | actually looking for secret for
yyy.yyy.yyy.254->0.0.0.0 of kind PPK_PSK
May 13 18:47:38 myserver pluto[28835]: | 1: compared PSK 0.0.0.0 to
yyy.yyy.yyy.254 / (none) -> 2
May 13 18:47:38 myserver pluto[28835]: | 2: compared PSK yyy.yyy.yyy.254 to
yyy.yyy.yyy.254 / (none) -> 6
May 13 18:47:38 myserver pluto[28835]: | best_match 0>6 best=0x80ff260
(line=3)
May 13 18:47:38 myserver pluto[28835]: | concluding with best_match=6
best=0x80ff260 (lineno=3)
May 13 18:47:38 myserver pluto[28835]: | offered CA: '%none'
May 13 18:47:38 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #1:
switched from "L2TP-WINXP" to "L2TP-WINXP"
May 13 18:47:38 myserver pluto[28835]: | instantiated "L2TP-WINXP" for
xxx.xxx.xxx.xxx
May 13 18:47:38 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:38 myserver pluto[28835]: | thinking about whether to send my
certificate:
May 13 18:47:38 myserver pluto[28835]: | I have RSA key:
OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
May 13 18:47:38 myserver pluto[28835]: | sendcert: CERT_ALWAYSSEND and I
did not get a certificate request
May 13 18:47:38 myserver pluto[28835]: | so do not send cert.
May 13 18:47:39 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1: I
did not send a certificate because I do not have one.
May 13 18:47:39 myserver pluto[28835]: | complete state transition with
STF_OK
May 13 18:47:39 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1:
transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
May 13 18:47:39 myserver pluto[28835]: | sending reply packet to
xxx.xxx.xxx.xxx:22133 (from port=500)
May 13 18:47:39 myserver pluto[28835]: | NAT-T: new mapping xxx.xxx.xxx.xxx
:22133/22155)
May 13 18:47:39 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:39 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:39 myserver pluto[28835]: | sending 68 bytes for STATE_MAIN_R2
through eth0:3:4500 to xxx.xxx.xxx.xxx:22155:
May 13 18:47:39 myserver pluto[28835]: | inserting event EVENT_SA_EXPIRE,
timeout in 28800 seconds for #1
May 13 18:47:39 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1:
STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY
cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp2048}
May 13 18:47:39 myserver pluto[28835]: | modecfg pull: noquirk policy:push
not-client
May 13 18:47:39 myserver pluto[28835]: | phase 1 is done, looking for phase
1 to unpend
May 13 18:47:39 myserver pluto[28835]: |
May 13 18:47:39 myserver pluto[28835]: | *received 360 bytes from
xxx.xxx.xxx.xxx:22133 on eth0:3 (port=500)
May 13 18:47:39 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_IDPROT (2)
May 13 18:47:40 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:40 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:40 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:40 myserver pluto[28835]: | state hash entry 16
May 13 18:47:40 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000
May 13 18:47:40 myserver pluto[28835]: | state object #1 found, in
STATE_MAIN_R3
May 13 18:47:40 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:40 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1:
packet rejected: should have been encrypted
May 13 18:47:40 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1:
sending notification INVALID_FLAGS to xxx.xxx.xxx.xxx:22155
May 13 18:47:40 myserver pluto[28835]: | sending 40 bytes for notification
packet through eth0:3:4500 to xxx.xxx.xxx.xxx:22155:
May 13 18:47:40 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 4
seconds for #2
May 13 18:47:40 myserver pluto[28835]: |
May 13 18:47:40 myserver pluto[28835]: | *received 68 bytes from
xxx.xxx.xxx.xxx:22155 on eth0:3 (port=4500)
May 13 18:47:40 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_IDPROT (2)
May 13 18:47:40 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:40 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:40 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:41 myserver pluto[28835]: | state hash entry 16
May 13 18:47:41 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000
May 13 18:47:41 myserver pluto[28835]: | state object #1 found, in
STATE_MAIN_R3
May 13 18:47:41 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:41 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1:
retransmitting in response to duplicate packet; already STATE_MAIN_R3
May 13 18:47:41 myserver pluto[28835]: | sending 68 bytes for retransmit in
response to duplicate through eth0:3:4500 to xxx.xxx.xxx.xxx:22155:
May 13 18:47:41 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 3
seconds for #2
May 13 18:47:41 myserver pluto[28835]: |
May 13 18:47:41 myserver pluto[28835]: | *received 300 bytes from
xxx.xxx.xxx.xxx:22155 on eth0:3 (port=4500)
May 13 18:47:41 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_QUICK (32)
May 13 18:47:41 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:41 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:41 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:41 myserver pluto[28835]: | state hash entry 16
May 13 18:47:41 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid c7e064a0 vs 00000000
May 13 18:47:41 myserver pluto[28835]: | state object not found
May 13 18:47:42 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:42 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:42 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:42 myserver pluto[28835]: | state hash entry 16
May 13 18:47:42 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000
May 13 18:47:42 myserver pluto[28835]: | state object #1 found, in
STATE_MAIN_R3
May 13 18:47:42 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:42 myserver pluto[28835]: | our client is yyy.yyy.yyy.254
May 13 18:47:42 myserver pluto[28835]: | our client protocol/port is 17/1701
May 13 18:47:42 myserver pluto[28835]: | duplicating state object #1
May 13 18:47:42 myserver pluto[28835]: | creating state object #3 at
0x8102d60
May 13 18:47:42 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:42 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:42 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:42 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:42 myserver pluto[28835]: | state hash entry 16
May 13 18:47:42 myserver pluto[28835]: | inserting event EVENT_SO_DISCARD,
timeout in 0 seconds for #3
May 13 18:47:43 myserver pluto[28835]: | 2: w->pcw_dead: 0 w->pcw_work: 0
cnt: 3
May 13 18:47:43 myserver pluto[28835]: | asking helper 2 to do build_nonce
op on seq: 2
May 13 18:47:43 myserver pluto[28835]: | inserting event
EVENT_CRYPTO_FAILED, timeout in 300 seconds for #3
May 13 18:47:43 myserver pluto[28878]: ! helper -1 doing build_nonce op id:
2
May 13 18:47:43 myserver pluto[28835]: | complete state transition with
STF_SUSPEND
May 13 18:47:43 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 1
seconds for #2
May 13 18:47:43 myserver pluto[28835]: |
May 13 18:47:43 myserver pluto[28835]: | *received 300 bytes from
xxx.xxx.xxx.xxx:22155 on eth0:3 (port=4500)
May 13 18:47:43 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_QUICK (32)
May 13 18:47:43 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:43 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:43 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:43 myserver pluto[28835]: | state hash entry 16
May 13 18:47:43 myserver pluto[28835]: | peer and cookies match on #3,
provided msgid c7e064a0 vs c7e064a0
May 13 18:47:43 myserver pluto[28835]: | state object #3 found, in
STATE_QUICK_R0
May 13 18:47:43 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:43 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
message received while calculating. Ignored.
May 13 18:47:44 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:44 myserver pluto[28835]: | generate SPI: 69 7c c7 4c
May 13 18:47:44 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
responding to Quick Mode {msgid:a064e0c7}
May 13 18:47:44 myserver pluto[28835]: | install_inbound_ipsec_sa() checking
if we can route
May 13 18:47:44 myserver pluto[28835]: | route owner of "L2TP-WINXP"[2]
xxx.xxx.xxx.xxx unrouted: NULL; eroute owner: NULL
May 13 18:47:44 myserver pluto[28835]: | could_route called for L2TP-WINXP
(kind=CK_INSTANCE)
May 13 18:47:44 myserver pluto[28835]: | complete state transition with
STF_OK
May 13 18:47:44 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
May 13 18:47:44 myserver pluto[28835]: | sending reply packet to
xxx.xxx.xxx.xxx:22155 (from port=4500)
May 13 18:47:44 myserver pluto[28835]: | sending 164 bytes for
STATE_QUICK_R0 through eth0:3:4500 to xxx.xxx.xxx.xxx:22155:
May 13 18:47:44 myserver pluto[28835]: | inserting event EVENT_RETRANSMIT,
timeout in 10 seconds for #3
May 13 18:47:44 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
May 13 18:47:44 myserver pluto[28835]: | modecfg pull: noquirk policy:push
not-client
May 13 18:47:45 myserver pluto[28835]: | phase 1 is done, looking for phase
1 to unpend
May 13 18:47:45 myserver pluto[28835]: | next event EVENT_RETRANSMIT in -1
seconds for #2
May 13 18:47:45 myserver pluto[28835]: |
May 13 18:47:45 myserver pluto[28835]: | *time to handle event
May 13 18:47:45 myserver pluto[28835]: | handling event EVENT_RETRANSMIT
May 13 18:47:45 myserver pluto[28835]: | event after this is
EVENT_RETRANSMIT in 9 seconds
May 13 18:47:45 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:45 myserver pluto[28835]: | handling event EVENT_RETRANSMIT for
xxx.xxx.xxx.xxx "L2TP-WINXP" #2
May 13 18:47:45 myserver pluto[28835]: | sending 140 bytes for
EVENT_RETRANSMIT through eth0:3:500 to xxx.xxx.xxx.xxx:22155:
May 13 18:47:45 myserver pluto[28835]: | inserting event EVENT_RETRANSMIT,
timeout in 20 seconds for #2
May 13 18:47:45 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 9
seconds for #3
May 13 18:47:45 myserver pluto[28835]: |
May 13 18:47:46 myserver pluto[28835]: | *received 300 bytes from
xxx.xxx.xxx.xxx:22155 on eth0:3 (port=4500)
May 13 18:47:46 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_QUICK (32)
May 13 18:47:46 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:46 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:46 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:46 myserver pluto[28835]: | state hash entry 16
May 13 18:47:46 myserver pluto[28835]: | peer and cookies match on #3,
provided msgid c7e064a0 vs c7e064a0
May 13 18:47:46 myserver pluto[28835]: | state object #3 found, in
STATE_QUICK_R1
May 13 18:47:46 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:46 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
next payload type of ISAKMP Hash Payload has an unknown value: 249
May 13 18:47:46 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
malformed payload in packet
May 13 18:47:46 myserver pluto[28835]: | payload malformed after IV
May 13 18:47:46 myserver pluto[28835]: | 30 77 78 c0 ff 5c 8a 10
May 13 18:47:46 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
sending notification PAYLOAD_MALFORMED to xxx.xxx.xxx.xxx:22155
May 13 18:47:46 myserver pluto[28835]: | sending 40 bytes for notification
packet through eth0:3:4500 to xxx.xxx.xxx.xxx:22155:
May 13 18:47:46 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 8
seconds for #3
May 13 18:47:46 myserver pluto[28835]: |
May 13 18:47:47 myserver pluto[28835]: | *received 52 bytes from
xxx.xxx.xxx.xxx:22155 on eth0:3 (port=4500)
May 13 18:47:47 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_QUICK (32)
May 13 18:47:47 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:47:47 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:47:47 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:47:47 myserver pluto[28835]: | state hash entry 16
May 13 18:47:47 myserver pluto[28835]: | peer and cookies match on #3,
provided msgid c7e064a0 vs c7e064a0
May 13 18:47:47 myserver pluto[28835]: | state object #3 found, in
STATE_QUICK_R1
May 13 18:47:47 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:47 myserver pluto[28835]: | install_ipsec_sa() for #3: outbound
only
May 13 18:47:47 myserver pluto[28835]: | route owner of "L2TP-WINXP"[2]
xxx.xxx.xxx.xxx unrouted: NULL; eroute owner: NULL
May 13 18:47:47 myserver pluto[28835]: | could_route called for L2TP-WINXP
(kind=CK_INSTANCE)
May 13 18:47:47 myserver pluto[28835]: | sr for #3: unrouted
May 13 18:47:47 myserver pluto[28835]: | route owner of "L2TP-WINXP"[2]
xxx.xxx.xxx.xxx unrouted: NULL; eroute owner: NULL
May 13 18:47:47 myserver pluto[28835]: | eroute_connection add eroute
yyy.yyy.yyy.254/32:1701 --17-> xxx.xxx.xxx.xxx/32:1701 =>
esp.4e864e6a at xxx.xxx.xxx.xxx (raw_eroute)
May 13 18:47:47 myserver pluto[28835]: | command executing up-host
May 13 18:47:47 myserver pluto[28835]: | executing up-host: 2>&1
PLUTO_VERSION='1.1' PLUTO_VERB='up-host' PLUTO_CONNECTION='L2TP-WINXP'
PLUTO_NEXT_HOP='xxx.xxx.xxx.xxx' PLUTO_INTERFACE='ipsec0' PLUTO_ME='
yyy.yyy.yyy.254' PLUTO_MY_ID='yyy.yyy.yyy.254' PLUTO_MY_CLIENT='
yyy.yyy.yyy.254/32' PLUTO_MY_CLIENT_NET='yyy.yyy.yyy.254'
PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701'
PLUTO_MY_PROTOCOL='17' PLUTO_PEER='xxx.xxx.xxx.xxx' PLUTO_PEER_ID='@vader'
PLUTO_PEER_CLIENT='xxx.xxx.xxx.xxx/32' PLUTO_PEER_CLIENT_NET='
xxx.xxx.xxx.xxx' PLUTO_PEER_CLIENT_MASK='255.255.255.255'
PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA=''
PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown
May 13 18:47:47 myserver pluto[28835]: | route_and_eroute:
firewall_notified: true
May 13 18:47:48 myserver pluto[28835]: | command executing prepare-host
May 13 18:47:48 myserver pluto[28835]: | executing prepare-host: 2>&1
PLUTO_VERSION='1.1' PLUTO_VERB='prepare-host' PLUTO_CONNECTION='L2TP-WINXP'
PLUTO_NEXT_HOP='xxx.xxx.xxx.xxx' PLUTO_INTERFACE='ipsec0' PLUTO_ME='
yyy.yyy.yyy.254' PLUTO_MY_ID='yyy.yyy.yyy.254' PLUTO_MY_CLIENT='
yyy.yyy.yyy.254/32' PLUTO_MY_CLIENT_NET='yyy.yyy.yyy.254'
PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701'
PLUTO_MY_PROTOCOL='17' PLUTO_PEER='xxx.xxx.xxx.xxx' PLUTO_PEER_ID='@vader'
PLUTO_PEER_CLIENT='xxx.xxx.xxx.xxx/32' PLUTO_PEER_CLIENT_NET='
xxx.xxx.xxx.xxx' PLUTO_PEER_CLIENT_MASK='255.255.255.255'
PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA=''
PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown
May 13 18:47:48 myserver pluto[28835]: | command executing route-host
May 13 18:47:48 myserver pluto[28835]: | executing route-host: 2>&1
PLUTO_VERSION='1.1' PLUTO_VERB='route-host' PLUTO_CONNECTION='L2TP-WINXP'
PLUTO_NEXT_HOP='xxx.xxx.xxx.xxx' PLUTO_INTERFACE='ipsec0' PLUTO_ME='
yyy.yyy.yyy.254' PLUTO_MY_ID='yyy.yyy.yyy.254' PLUTO_MY_CLIENT='
yyy.yyy.yyy.254/32' PLUTO_MY_CLIENT_NET='yyy.yyy.yyy.254'
PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701'
PLUTO_MY_PROTOCOL='17' PLUTO_PEER='xxx.xxx.xxx.xxx' PLUTO_PEER_ID='@vader'
PLUTO_PEER_CLIENT='xxx.xxx.xxx.xxx/32' PLUTO_PEER_CLIENT_NET='
xxx.xxx.xxx.xxx' PLUTO_PEER_CLIENT_MASK='255.255.255.255'
PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA=''
PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown
May 13 18:47:48 myserver pluto[28835]: | route_and_eroute: instance
"L2TP-WINXP"[2] xxx.xxx.xxx.xxx, setting eroute_owner
{spd=0x8102b04,sr=0x8102b04} to #3 (was #0) (newest_ipsec_sa=#0)
May 13 18:47:48 myserver pluto[28835]: | complete state transition with
STF_OK
May 13 18:47:48 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
May 13 18:47:48 myserver pluto[28835]: | inserting event EVENT_SA_EXPIRE,
timeout in 3600 seconds for #3
May 13 18:47:48 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #3:
STATE_QUICK_R2: IPsec SA established {ESP=>0x4e864e6a <0x697cc74c
xfrm=3DES_0-HMAC_MD5 NATD=xxx.xxx.xxx.xxx:22155 DPD=none}
May 13 18:47:48 myserver pluto[28835]: | modecfg pull: noquirk policy:push
not-client
May 13 18:47:48 myserver pluto[28835]: | phase 1 is done, looking for phase
1 to unpend
May 13 18:47:48 myserver pluto[28835]: | next event EVENT_NAT_T_KEEPALIVE in
7 seconds
May 13 18:47:55 myserver pluto[28835]: |
May 13 18:47:55 myserver pluto[28835]: | *time to handle event
May 13 18:47:55 myserver pluto[28835]: | handling event
EVENT_NAT_T_KEEPALIVE
May 13 18:47:55 myserver pluto[28835]: | event after this is
EVENT_RETRANSMIT in 10 seconds
May 13 18:47:55 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:47:55 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:55 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:47:55 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 10
seconds for #2
May 13 18:48:05 myserver pluto[28835]: |
May 13 18:48:05 myserver pluto[28835]: | *time to handle event
May 13 18:48:05 myserver pluto[28835]: | handling event EVENT_RETRANSMIT
May 13 18:48:05 myserver pluto[28835]: | event after this is
EVENT_PENDING_PHASE2 in 77 seconds
May 13 18:48:05 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:48:05 myserver pluto[28835]: | handling event EVENT_RETRANSMIT for
xxx.xxx.xxx.xxx "L2TP-WINXP" #2
May 13 18:48:05 myserver pluto[28835]: | sending 140 bytes for
EVENT_RETRANSMIT through eth0:3:500 to xxx.xxx.xxx.xxx:22155:
May 13 18:48:05 myserver pluto[28835]: | inserting event EVENT_RETRANSMIT,
timeout in 40 seconds for #2
May 13 18:48:05 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 40
seconds for #2
May 13 18:48:19 myserver pluto[28835]: |
May 13 18:48:19 myserver pluto[28835]: | *received 68 bytes from
xxx.xxx.xxx.xxx:22155 on eth0:3 (port=4500)
May 13 18:48:19 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_INFO (5)
May 13 18:48:19 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:48:19 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:48:19 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:48:19 myserver pluto[28835]: | state hash entry 16
May 13 18:48:19 myserver pluto[28835]: | peer and cookies match on #3,
provided msgid 00000000 vs c7e064a0/00000000
May 13 18:48:19 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000/00000000
May 13 18:48:19 myserver pluto[28835]: | p15 state object #1 found, in
STATE_MAIN_R3
May 13 18:48:19 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:48:19 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:48:19 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1:
received Delete SA(0x4e864e6a) payload: deleting IPSEC State #3
May 13 18:48:20 myserver pluto[28835]: | deleting state #3
May 13 18:48:20 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:48:20 myserver pluto[28835]: | sending 68 bytes for delete notify
through eth0:3:4500 to xxx.xxx.xxx.xxx:22155:
May 13 18:48:20 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:48:20 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:48:20 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:48:20 myserver pluto[28835]: | state hash entry 16
May 13 18:48:20 myserver pluto[28835]: | command executing down-host
May 13 18:48:20 myserver pluto[28835]: | executing down-host: 2>&1
PLUTO_VERSION='1.1' PLUTO_VERB='down-host' PLUTO_CONNECTION='L2TP-WINXP'
PLUTO_NEXT_HOP='xxx.xxx.xxx.xxx' PLUTO_INTERFACE='ipsec0' PLUTO_ME='
yyy.yyy.yyy.254' PLUTO_MY_ID='yyy.yyy.yyy.254' PLUTO_MY_CLIENT='
yyy.yyy.yyy.254/32' PLUTO_MY_CLIENT_NET='yyy.yyy.yyy.254'
PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701'
PLUTO_MY_PROTOCOL='17' PLUTO_PEER='xxx.xxx.xxx.xxx' PLUTO_PEER_ID='@vader'
PLUTO_PEER_CLIENT='xxx.xxx.xxx.xxx/32' PLUTO_PEER_CLIENT_NET='
xxx.xxx.xxx.xxx' PLUTO_PEER_CLIENT_MASK='255.255.255.255'
PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA=''
PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown
May 13 18:48:20 myserver pluto[28835]: | eroute_connection delete eroute
yyy.yyy.yyy.254/32:1701 --17-> xxx.xxx.xxx.xxx/32:1701 =>
int.0 at 0.0.0.0(raw_eroute)
May 13 18:48:20 myserver pluto[28835]: | route owner of "L2TP-WINXP"[2]
xxx.xxx.xxx.xxx unrouted: NULL
May 13 18:48:20 myserver pluto[28835]: | command executing unroute-host
May 13 18:48:20 myserver pluto[28835]: | executing unroute-host: 2>&1
PLUTO_VERSION='1.1' PLUTO_VERB='unroute-host' PLUTO_CONNECTION='L2TP-WINXP'
PLUTO_NEXT_HOP='xxx.xxx.xxx.xxx' PLUTO_INTERFACE='ipsec0' PLUTO_ME='
yyy.yyy.yyy.254' PLUTO_MY_ID='yyy.yyy.yyy.254' PLUTO_MY_CLIENT='
yyy.yyy.yyy.254/32' PLUTO_MY_CLIENT_NET='yyy.yyy.yyy.254'
PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701'
PLUTO_MY_PROTOCOL='17' PLUTO_PEER='xxx.xxx.xxx.xxx' PLUTO_PEER_ID='@vader'
PLUTO_PEER_CLIENT='xxx.xxx.xxx.xxx/32' PLUTO_PEER_CLIENT_NET='
xxx.xxx.xxx.xxx' PLUTO_PEER_CLIENT_MASK='255.255.255.255'
PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA=''
PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown
May 13 18:48:20 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1:
received and ignored informational message
May 13 18:48:21 myserver pluto[28835]: | complete state transition with
STF_IGNORE
May 13 18:48:21 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 24
seconds for #2
May 13 18:48:21 myserver pluto[28835]: |
May 13 18:48:21 myserver pluto[28835]: | *received 84 bytes from
xxx.xxx.xxx.xxx:22155 on eth0:3 (port=4500)
May 13 18:48:21 myserver pluto[28835]: | processing packet with exchange
type=ISAKMP_XCHG_INFO (5)
May 13 18:48:21 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:48:21 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:48:21 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:48:21 myserver pluto[28835]: | state hash entry 16
May 13 18:48:21 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000/00000000
May 13 18:48:21 myserver pluto[28835]: | p15 state object #1 found, in
STATE_MAIN_R3
May 13 18:48:21 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:48:21 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:48:21 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:48:21 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:48:21 myserver pluto[28835]: | state hash entry 16
May 13 18:48:21 myserver pluto[28835]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000
May 13 18:48:21 myserver pluto[28835]: | state object #1 found, in
STATE_MAIN_R3
May 13 18:48:21 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:48:22 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx #1:
received Delete SA payload: deleting ISAKMP State #1
May 13 18:48:22 myserver pluto[28835]: | deleting state #1
May 13 18:48:22 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:48:22 myserver pluto[28835]: | sending 84 bytes for delete notify
through eth0:3:4500 to xxx.xxx.xxx.xxx:22155:
May 13 18:48:22 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:48:22 myserver pluto[28835]: | RCOOKIE: 67 29 6b a6 32 6c c0 be
May 13 18:48:22 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:48:22 myserver pluto[28835]: | state hash entry 16
May 13 18:48:22 myserver pluto[28835]: | processing connection L2TP-WINXP[2]
xxx.xxx.xxx.xxx
May 13 18:48:22 myserver pluto[28835]: "L2TP-WINXP"[2] xxx.xxx.xxx.xxx:
deleting connection "L2TP-WINXP" instance with peer
xxx.xxx.xxx.xxx{isakmp=#0/ipsec=#0}
May 13 18:48:22 myserver pluto[28835]: packet from xxx.xxx.xxx.xxx:22155:
received and ignored informational message
May 13 18:48:22 myserver pluto[28835]: | complete state transition with
STF_IGNORE
May 13 18:48:22 myserver pluto[28835]: | next event EVENT_RETRANSMIT in 23
seconds for #2
May 13 18:48:45 myserver pluto[28835]: |
May 13 18:48:45 myserver pluto[28835]: | *time to handle event
May 13 18:48:45 myserver pluto[28835]: | handling event EVENT_RETRANSMIT
May 13 18:48:45 myserver pluto[28835]: | event after this is
EVENT_PENDING_PHASE2 in 37 seconds
May 13 18:48:45 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:48:45 myserver pluto[28835]: | handling event EVENT_RETRANSMIT for
xxx.xxx.xxx.xxx "L2TP-WINXP" #2
May 13 18:48:45 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx #2:
max number of retransmissions (2) reached STATE_MAIN_R1
May 13 18:48:45 myserver pluto[28835]: | deleting state #2
May 13 18:48:45 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:48:45 myserver pluto[28835]: | ICOOKIE: 71 df 33 eb 9c 73 ff 53
May 13 18:48:45 myserver pluto[28835]: | RCOOKIE: ae 98 87 4e 5b 8d 38 62
May 13 18:48:45 myserver pluto[28835]: | peer: 46 fb 0f d6
May 13 18:48:45 myserver pluto[28835]: | state hash entry 8
May 13 18:48:45 myserver pluto[28835]: | processing connection L2TP-WINXP[1]
xxx.xxx.xxx.xxx
May 13 18:48:45 myserver pluto[28835]: "L2TP-WINXP"[1] xxx.xxx.xxx.xxx:
deleting connection "L2TP-WINXP" instance with peer
xxx.xxx.xxx.xxx{isakmp=#0/ipsec=#0}
May 13 18:48:46 myserver pluto[28835]: | next event EVENT_PENDING_PHASE2 in
36 seconds
My oakley.log file on my windows xp machine (which doesn't tell me much):
5-13: 18:43:57:906:15c QM PolicyName: L2TP Require Encryption Quick Mode
Policy dwFlags 0
5-13: 18:43:57:906:15c QMOffer[0] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[0] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: ESP Algo: Triple DES CBC HMAC:
MD5
5-13: 18:43:57:906:15c QMOffer[1] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[1] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: ESP Algo: Triple DES CBC HMAC:
SHA
5-13: 18:43:57:906:15c QMOffer[2] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[2] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: AH Algo: SHA
5-13: 18:43:57:906:15c Algo[1] Operation: ESP Algo: Triple DES CBC HMAC: 0
5-13: 18:43:57:906:15c QMOffer[3] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[3] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: AH Algo: MD5
5-13: 18:43:57:906:15c Algo[1] Operation: ESP Algo: Triple DES CBC HMAC: 0
5-13: 18:43:57:906:15c QMOffer[4] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[4] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: AH Algo: SHA
5-13: 18:43:57:906:15c Algo[1] Operation: ESP Algo: Triple DES CBC HMAC:
SHA
5-13: 18:43:57:906:15c QMOffer[5] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[5] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: AH Algo: MD5
5-13: 18:43:57:906:15c Algo[1] Operation: ESP Algo: Triple DES CBC HMAC:
MD5
5-13: 18:43:57:906:15c QMOffer[6] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[6] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: ESP Algo: DES CBC HMAC: MD5
5-13: 18:43:57:906:15c QMOffer[7] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[7] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: ESP Algo: DES CBC HMAC: SHA
5-13: 18:43:57:906:15c QMOffer[8] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[8] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: AH Algo: SHA
5-13: 18:43:57:906:15c Algo[1] Operation: ESP Algo: DES CBC HMAC: 0
5-13: 18:43:57:906:15c QMOffer[9] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[9] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: AH Algo: MD5
5-13: 18:43:57:906:15c Algo[1] Operation: ESP Algo: DES CBC HMAC: 0
5-13: 18:43:57:906:15c QMOffer[10] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[10] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: AH Algo: SHA
5-13: 18:43:57:906:15c Algo[1] Operation: ESP Algo: DES CBC HMAC: SHA
5-13: 18:43:57:906:15c QMOffer[11] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:15c QMOffer[11] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:15c Algo[0] Operation: AH Algo: MD5
5-13: 18:43:57:906:15c Algo[1] Operation: ESP Algo: DES CBC HMAC: MD5
5-13: 18:43:57:906:15c Internal Acquire: op=00000001 src=172.23.23.10.1701dst=
yyy.yyy.yyy.254.1701 proto = 17, SrcMask=255.255.255.255,
DstMask=255.255.255.255,
Tunnel 0, TunnelEndpt=0.0.0.0 Inbound TunnelEndpt= 0.0.0.0,
InitiateEvent=00000608, IKE SrcPort=500 IKE DstPort=500
5-13: 18:43:57:906:a30 Filter to match: Src yyy.yyy.yyy.254 Dst
172.23.23.10
5-13: 18:43:57:906:a30 MM PolicyName: L2TP Main Mode Policy
5-13: 18:43:57:906:a30 MMPolicy dwFlags 8 SoftSAExpireTime 28800
5-13: 18:43:57:906:a30 MMOffer[0] LifetimeSec 28800 QMLimit 0 DHGroup
268435457
5-13: 18:43:57:906:a30 MMOffer[0] Encrypt: Triple DES CBC Hash: SHA
5-13: 18:43:57:906:a30 MMOffer[1] LifetimeSec 28800 QMLimit 0 DHGroup 2
5-13: 18:43:57:906:a30 MMOffer[1] Encrypt: Triple DES CBC Hash: SHA
5-13: 18:43:57:906:a30 MMOffer[2] LifetimeSec 28800 QMLimit 0 DHGroup 2
5-13: 18:43:57:906:a30 MMOffer[2] Encrypt: Triple DES CBC Hash: MD5
5-13: 18:43:57:906:a30 MMOffer[3] LifetimeSec 28800 QMLimit 0 DHGroup 1
5-13: 18:43:57:906:a30 MMOffer[3] Encrypt: DES CBC Hash: SHA
5-13: 18:43:57:906:a30 MMOffer[4] LifetimeSec 28800 QMLimit 0 DHGroup 1
5-13: 18:43:57:906:a30 MMOffer[4] Encrypt: DES CBC Hash: MD5
5-13: 18:43:57:906:a30 Auth[0]:PresharedKey KeyLen 40
5-13: 18:43:57:906:a30 QM PolicyName: L2TP Require Encryption Quick Mode
Policy dwFlags 0
5-13: 18:43:57:906:a30 QMOffer[0] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[0] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: ESP Algo: Triple DES CBC HMAC:
MD5
5-13: 18:43:57:906:a30 QMOffer[1] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[1] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: ESP Algo: Triple DES CBC HMAC:
SHA
5-13: 18:43:57:906:a30 QMOffer[2] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[2] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: AH Algo: SHA
5-13: 18:43:57:906:a30 Algo[1] Operation: ESP Algo: Triple DES CBC HMAC: 0
5-13: 18:43:57:906:a30 QMOffer[3] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[3] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: AH Algo: MD5
5-13: 18:43:57:906:a30 Algo[1] Operation: ESP Algo: Triple DES CBC HMAC: 0
5-13: 18:43:57:906:a30 QMOffer[4] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[4] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: AH Algo: SHA
5-13: 18:43:57:906:a30 Algo[1] Operation: ESP Algo: Triple DES CBC HMAC:
SHA
5-13: 18:43:57:906:a30 QMOffer[5] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[5] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: AH Algo: MD5
5-13: 18:43:57:906:a30 Algo[1] Operation: ESP Algo: Triple DES CBC HMAC:
MD5
5-13: 18:43:57:906:a30 QMOffer[6] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[6] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: ESP Algo: DES CBC HMAC: MD5
5-13: 18:43:57:906:a30 QMOffer[7] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[7] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: ESP Algo: DES CBC HMAC: SHA
5-13: 18:43:57:906:a30 QMOffer[8] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[8] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: AH Algo: SHA
5-13: 18:43:57:906:a30 Algo[1] Operation: ESP Algo: DES CBC HMAC: 0
5-13: 18:43:57:906:a30 QMOffer[9] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[9] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: AH Algo: MD5
5-13: 18:43:57:906:a30 Algo[1] Operation: ESP Algo: DES CBC HMAC: 0
5-13: 18:43:57:906:a30 QMOffer[10] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[10] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: AH Algo: SHA
5-13: 18:43:57:906:a30 Algo[1] Operation: ESP Algo: DES CBC HMAC: SHA
5-13: 18:43:57:906:a30 QMOffer[11] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:43:57:906:a30 QMOffer[11] dwFlags 0 dwPFSGroup 0
5-13: 18:43:57:906:a30 Algo[0] Operation: AH Algo: MD5
5-13: 18:43:57:906:a30 Algo[1] Operation: ESP Algo: DES CBC HMAC: MD5
5-13: 18:43:57:906:a30 Starting Negotiation: src = 172.23.23.10.0500, dst =
yyy.yyy.yyy.254.0500, proto = 17, context = 00000000, ProxySrc =
172.23.23.10.1701, ProxyDst = yyy.yyy.yyy.254.1701 SrcMask = 0.0.0.0 DstMask
= 0.0.0.0
5-13: 18:43:57:906:a30 constructing ISAKMP Header
5-13: 18:43:57:906:a30 constructing SA (ISAKMP)
5-13: 18:43:57:906:a30 Constructing Vendor MS NT5 ISAKMPOAKLEY
5-13: 18:43:57:906:a30 Constructing Vendor FRAGMENTATION
5-13: 18:43:57:906:a30 Constructing Vendor draft-ietf-ipsec-nat-t-ike-02
5-13: 18:43:57:906:a30 Constructing Vendor Vid-Initial-Contact
5-13: 18:43:57:906:a30
5-13: 18:43:57:906:a30 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.500
5-13: 18:43:57:906:a30 ISAKMP Header: (V1.0), len = 312
5-13: 18:43:57:906:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:43:57:906:a30 R-COOKIE 0000000000000000
5-13: 18:43:57:906:a30 exchange: Oakley Main Mode
5-13: 18:43:57:906:a30 flags: 0
5-13: 18:43:57:906:a30 next payload: SA
5-13: 18:43:57:906:a30 message ID: 00000000
5-13: 18:43:57:906:a30 Ports S:f401 D:f401
5-13: 18:43:57:906:a30 Activating InitiateEvent 00000608
5-13: 18:43:58:625:690 retransmit: sa = 000EB018 centry 00000000 , count =
1
5-13: 18:43:58:625:690
5-13: 18:43:58:625:690 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.500
5-13: 18:43:58:625:690 ISAKMP Header: (V1.0), len = 312
5-13: 18:43:58:625:690 I-COOKIE 71df33eb9c73ff53
5-13: 18:43:58:625:690 R-COOKIE 0000000000000000
5-13: 18:43:58:625:690 exchange: Oakley Main Mode
5-13: 18:43:58:625:690 flags: 0
5-13: 18:43:58:625:690 next payload: SA
5-13: 18:43:58:625:690 message ID: 00000000
5-13: 18:43:58:625:690 Ports S:f401 D:f401
5-13: 18:43:58:875:a30
5-13: 18:43:58:875:a30 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.500
5-13: 18:43:58:875:a30 ISAKMP Header: (V1.0), len = 140
5-13: 18:43:58:875:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:43:58:875:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:43:58:875:a30 exchange: Oakley Main Mode
5-13: 18:43:58:875:a30 flags: 0
5-13: 18:43:58:875:a30 next payload: SA
5-13: 18:43:58:875:a30 message ID: 00000000
5-13: 18:43:58:875:a30 processing payload SA
5-13: 18:43:58:875:a30 Received Phase 1 Transform 1
5-13: 18:43:58:875:a30 Encryption Alg Triple DES CBC(5)
5-13: 18:43:58:875:a30 Hash Alg SHA(2)
5-13: 18:43:58:875:a30 Oakley Group 14
5-13: 18:43:58:875:a30 Auth Method Preshared Key(1)
5-13: 18:43:58:875:a30 Life type in Seconds
5-13: 18:43:58:875:a30 Life duration of 28800
5-13: 18:43:58:875:a30 Phase 1 SA accepted: transform=1
5-13: 18:43:58:875:a30 SA - Oakley proposal accepted
5-13: 18:43:58:875:a30 processing payload VENDOR ID
5-13: 18:43:58:875:a30 processing payload VENDOR ID
5-13: 18:43:58:875:a30 processing payload VENDOR ID
5-13: 18:43:58:875:a30 Received VendorId draft-ietf-ipsec-nat-t-ike-02
5-13: 18:43:58:875:a30 ClearFragList
5-13: 18:43:58:875:a30 constructing ISAKMP Header
5-13: 18:43:58:968:a30 constructing KE
5-13: 18:43:58:968:a30 constructing NONCE (ISAKMP)
5-13: 18:43:58:968:a30 Constructing NatDisc
5-13: 18:43:58:968:a30
5-13: 18:43:58:968:a30 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.500
5-13: 18:43:58:968:a30 ISAKMP Header: (V1.0), len = 360
5-13: 18:43:58:968:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:43:58:968:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:43:58:968:a30 exchange: Oakley Main Mode
5-13: 18:43:58:968:a30 flags: 0
5-13: 18:43:58:968:a30 next payload: KE
5-13: 18:43:58:968:a30 message ID: 00000000
5-13: 18:43:58:968:a30 Ports S:f401 D:f401
5-13: 18:43:59:625:690 retransmit: sa = 000EB018 centry 00000000 , count =
1
5-13: 18:43:59:625:690
5-13: 18:43:59:625:690 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.500
5-13: 18:43:59:625:690 ISAKMP Header: (V1.0), len = 360
5-13: 18:43:59:625:690 I-COOKIE 71df33eb9c73ff53
5-13: 18:43:59:625:690 R-COOKIE 67296ba6326cc0be
5-13: 18:43:59:625:690 exchange: Oakley Main Mode
5-13: 18:43:59:625:690 flags: 0
5-13: 18:43:59:625:690 next payload: KE
5-13: 18:43:59:625:690 message ID: 00000000
5-13: 18:43:59:625:690 Ports S:f401 D:f401
5-13: 18:44:00:703:a30
5-13: 18:44:00:718:a30 Receive: (get) SA = 0x00000000 from
yyy.yyy.yyy.254.500
5-13: 18:44:00:718:a30 ISAKMP Header: (V1.0), len = 140
5-13: 18:44:00:718:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:00:718:a30 R-COOKIE ae98874e5b8d3862
5-13: 18:44:00:718:a30 exchange: Oakley Main Mode
5-13: 18:44:00:718:a30 flags: 0
5-13: 18:44:00:718:a30 next payload: SA
5-13: 18:44:00:718:a30 message ID: 00000000
5-13: 18:44:00:718:a30 Cookie exists, or new receive throttle hit
5-13: 18:44:00:718:a30 Responding with new SA 0
5-13: 18:44:00:718:a30 HandleFirstPacketResponder failed 35ec
5-13: 18:44:01:625:690 retransmit: sa = 000EB018 centry 00000000 , count =
2
5-13: 18:44:01:625:690
5-13: 18:44:01:625:690 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.500
5-13: 18:44:01:625:690 ISAKMP Header: (V1.0), len = 360
5-13: 18:44:01:625:690 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:01:625:690 R-COOKIE 67296ba6326cc0be
5-13: 18:44:01:625:690 exchange: Oakley Main Mode
5-13: 18:44:01:625:690 flags: 0
5-13: 18:44:01:625:690 next payload: KE
5-13: 18:44:01:625:690 message ID: 00000000
5-13: 18:44:01:625:690 Ports S:f401 D:f401
5-13: 18:44:03:390:a30
5-13: 18:44:03:390:a30 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.500
5-13: 18:44:03:390:a30 ISAKMP Header: (V1.0), len = 356
5-13: 18:44:03:390:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:03:390:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:03:390:a30 exchange: Oakley Main Mode
5-13: 18:44:03:390:a30 flags: 0
5-13: 18:44:03:390:a30 next payload: KE
5-13: 18:44:03:390:a30 message ID: 00000000
5-13: 18:44:03:390:a30 processing payload KE
5-13: 18:44:03:421:a30 processing payload NONCE
5-13: 18:44:03:421:a30 processing payload NATDISC
5-13: 18:44:03:421:a30 Processing NatHash
5-13: 18:44:03:421:a30 Nat hash 857dccee60582ab8bedd7a66c3810073
5-13: 18:44:03:421:a30 e570f1d6
5-13: 18:44:03:421:a30 SA StateMask2 1e
5-13: 18:44:03:421:a30 processing payload NATDISC
5-13: 18:44:03:421:a30 Processing NatHash
5-13: 18:44:03:421:a30 Nat hash 65f97de3c7928ec94ee10212f1836874
5-13: 18:44:03:421:a30 028b4f68
5-13: 18:44:03:421:a30 SA StateMask2 9e
5-13: 18:44:03:421:a30 ClearFragList
5-13: 18:44:03:421:a30 Floated Ports Orig Me:f401 Peer:f401
5-13: 18:44:03:421:a30 Floated Ports Me:9411 Peer:9411
5-13: 18:44:03:421:a30 constructing ISAKMP Header
5-13: 18:44:03:421:a30 constructing ID
5-13: 18:44:03:421:a30 MM ID Type 2
5-13: 18:44:03:421:a30 MM ID 7661646572
5-13: 18:44:03:421:a30 constructing HASH
5-13: 18:44:03:421:a30
5-13: 18:44:03:421:a30 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.4500
5-13: 18:44:03:421:a30 ISAKMP Header: (V1.0), len = 68
5-13: 18:44:03:421:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:03:421:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:03:421:a30 exchange: Oakley Main Mode
5-13: 18:44:03:421:a30 flags: 1 ( encrypted )
5-13: 18:44:03:421:a30 next payload: ID
5-13: 18:44:03:421:a30 message ID: 00000000
5-13: 18:44:03:421:a30 Ports S:9411 D:9411
5-13: 18:44:04:625:690 retransmit: sa = 000EB018 centry 00000000 , count =
1
5-13: 18:44:04:625:690
5-13: 18:44:04:625:690 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.4500
5-13: 18:44:04:625:690 ISAKMP Header: (V1.0), len = 68
5-13: 18:44:04:625:690 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:04:625:690 R-COOKIE 67296ba6326cc0be
5-13: 18:44:04:625:690 exchange: Oakley Main Mode
5-13: 18:44:04:625:690 flags: 1 ( encrypted )
5-13: 18:44:04:625:690 next payload: ID
5-13: 18:44:04:625:690 message ID: 00000000
5-13: 18:44:04:625:690 Ports S:9411 D:9411
5-13: 18:44:06:93:a30
5-13: 18:44:06:93:a30 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.4500
5-13: 18:44:06:93:a30 ISAKMP Header: (V1.0), len = 68
5-13: 18:44:06:93:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:06:93:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:06:93:a30 exchange: Oakley Main Mode
5-13: 18:44:06:93:a30 flags: 1 ( encrypted )
5-13: 18:44:06:93:a30 next payload: ID
5-13: 18:44:06:93:a30 message ID: 00000000
5-13: 18:44:06:93:a30 processing payload ID
5-13: 18:44:06:93:a30 processing payload HASH
5-13: 18:44:06:93:a30 AUTH: Phase I authentication accepted
5-13: 18:44:06:93:a30 ClearFragList
5-13: 18:44:06:93:a30 MM established. SA: 000EB018
5-13: 18:44:06:93:a30 QM PolicyName: L2TP Require Encryption Quick Mode
Policy dwFlags 0
5-13: 18:44:06:93:a30 QMOffer[0] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:44:06:93:a30 QMOffer[0] dwFlags 0 dwPFSGroup 0
5-13: 18:44:06:93:a30 Algo[0] Operation: ESP Algo: Triple DES CBC HMAC:
MD5
5-13: 18:44:06:93:a30 QMOffer[1] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:44:06:93:a30 QMOffer[1] dwFlags 0 dwPFSGroup 0
5-13: 18:44:06:93:a30 Algo[0] Operation: ESP Algo: Triple DES CBC HMAC:
SHA
5-13: 18:44:06:93:a30 QMOffer[2] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:44:06:93:a30 QMOffer[2] dwFlags 0 dwPFSGroup 0
5-13: 18:44:06:93:a30 Algo[0] Operation: ESP Algo: DES CBC HMAC: MD5
5-13: 18:44:06:93:a30 QMOffer[3] LifetimeKBytes 250000 LifetimeSec 3600
5-13: 18:44:06:93:a30 QMOffer[3] dwFlags 0 dwPFSGroup 0
5-13: 18:44:06:93:a30 Algo[0] Operation: ESP Algo: DES CBC HMAC: SHA
5-13: 18:44:06:93:a30 GetSpi: src = yyy.yyy.yyy.254.1701, dst =
172.23.23.10.1701, proto = 17, context = 00000000, srcMask = 255.255.255.255,
destMask = 255.255.255.255, TunnelFilter 0
5-13: 18:44:06:93:a30 Setting SPI 1317424746
5-13: 18:44:06:93:a30 constructing ISAKMP Header
5-13: 18:44:06:93:a30 constructing HASH (null)
5-13: 18:44:06:93:a30 constructing SA (IPSEC)
5-13: 18:44:06:93:a30 constructing NONCE (IPSEC)
5-13: 18:44:06:93:a30 constructing ID (proxy)
5-13: 18:44:06:93:a30 FQDN ID 7661646572
5-13: 18:44:06:93:a30 constructing ID (proxy)
5-13: 18:44:06:93:a30 Construct NATOA
5-13: 18:44:06:93:a30 constructing HASH (QM)
5-13: 18:44:06:93:a30
5-13: 18:44:06:93:a30 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.4500
5-13: 18:44:06:93:a30 ISAKMP Header: (V1.0), len = 300
5-13: 18:44:06:93:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:06:93:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:06:93:a30 exchange: Oakley Quick Mode
5-13: 18:44:06:93:a30 flags: 1 ( encrypted )
5-13: 18:44:06:93:a30 next payload: HASH
5-13: 18:44:06:93:a30 message ID: c7e064a0
5-13: 18:44:06:93:a30 Ports S:9411 D:9411
5-13: 18:44:06:625:690 retransmit: sa = 000EB018 centry 000F0E10 , count =
1
5-13: 18:44:06:625:690
5-13: 18:44:06:625:690 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.4500
5-13: 18:44:06:625:690 ISAKMP Header: (V1.0), len = 300
5-13: 18:44:06:625:690 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:06:625:690 R-COOKIE 67296ba6326cc0be
5-13: 18:44:06:625:690 exchange: Oakley Quick Mode
5-13: 18:44:06:625:690 flags: 1 ( encrypted )
5-13: 18:44:06:625:690 next payload: HASH
5-13: 18:44:06:625:690 message ID: c7e064a0
5-13: 18:44:06:625:690 Ports S:9411 D:9411
5-13: 18:44:07:203:a30
5-13: 18:44:07:203:a30 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.4500
5-13: 18:44:07:203:a30 ISAKMP Header: (V1.0), len = 40
5-13: 18:44:07:203:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:07:203:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:07:203:a30 exchange: ISAKMP Informational Exchange
5-13: 18:44:07:203:a30 flags: 0
5-13: 18:44:07:203:a30 next payload: NOTIFY
5-13: 18:44:07:203:a30 message ID: 18f45f4d
5-13: 18:44:07:203:a30 received an unencrypted packet when crypto active
5-13: 18:44:07:203:a30 GetPacket failed 35ec
5-13: 18:44:07:984:a30
5-13: 18:44:07:984:a30 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.4500
5-13: 18:44:07:984:a30 ISAKMP Header: (V1.0), len = 68
5-13: 18:44:07:984:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:07:984:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:07:984:a30 exchange: Oakley Main Mode
5-13: 18:44:07:984:a30 flags: 1 ( encrypted )
5-13: 18:44:07:984:a30 next payload: ID
5-13: 18:44:07:984:a30 message ID: 00000000
5-13: 18:44:07:984:a30 invalid payload received
5-13: 18:44:07:984:a30 GetPacket failed 3613
5-13: 18:44:08:625:690 retransmit: sa = 000EB018 centry 000F0E10 , count =
2
5-13: 18:44:08:625:690
5-13: 18:44:08:625:690 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
2.4500
5-13: 18:44:08:625:690 ISAKMP Header: (V1.0), len = 300
5-13: 18:44:08:625:690 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:08:625:690 R-COOKIE 67296ba6326cc0be
5-13: 18:44:08:625:690 exchange: Oakley Quick Mode
5-13: 18:44:08:625:690 flags: 1 ( encrypted )
5-13: 18:44:08:625:690 next payload: HASH
5-13: 18:44:08:625:690 message ID: c7e064a0
5-13: 18:44:08:625:690 Ports S:9411 D:9411
5-13: 18:44:11:343:a30
5-13: 18:44:11:343:a30 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.4500
5-13: 18:44:11:343:a30 ISAKMP Header: (V1.0), len = 164
5-13: 18:44:11:343:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:11:343:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:11:343:a30 exchange: Oakley Quick Mode
5-13: 18:44:11:343:a30 flags: 1 ( encrypted )
5-13: 18:44:11:343:a30 next payload: HASH
5-13: 18:44:11:343:a30 message ID: c7e064a0
5-13: 18:44:11:343:a30 processing HASH (QM)
5-13: 18:44:11:343:a30 ClearFragList
5-13: 18:44:11:343:a30 processing payload NONCE
5-13: 18:44:11:343:a30 processing payload ID
5-13: 18:44:11:343:a30 processing payload ID
5-13: 18:44:11:343:a30 processing payload SA
5-13: 18:44:11:343:a30 Negotiated Proxy ID: Src 172.23.23.10.1701 Dst
yyy.yyy.yyy.254.1701
5-13: 18:44:11:343:a30 Checking Proposal 1: Proto= ESP(3), num trans=1
Next=0
5-13: 18:44:11:343:a30 Checking Transform # 1: ID=Triple DES CBC(3)
5-13: 18:44:11:343:a30 SA life type in seconds
5-13: 18:44:11:343:a30 SA life duration 00000e10
5-13: 18:44:11:343:a30 SA life type in kilobytes
5-13: 18:44:11:343:a30 SA life duration 0003d090
5-13: 18:44:11:343:a30 tunnel mode is 61444(61444)
5-13: 18:44:11:343:a30 HMAC algorithm is MD5(1)
5-13: 18:44:11:343:a30 Phase 2 SA accepted: proposal=1 transform=1
5-13: 18:44:11:343:a30 constructing ISAKMP Header
5-13: 18:44:11:343:a30 constructing HASH (QM)
5-13: 18:44:11:343:a30 Adding QMs: src = 172.23.23.10.1701, dst =
yyy.yyy.yyy.254.1701, proto = 17, context = 0000000A, my tunnel = 0.0.0.0,
peer tunnel = 0.0.0.0 , SrcMask = 0.0.0.0, DestMask = 0.0.0.0 Lifetime =
3600 LifetimeKBytes 250000 dwFlags 280 Direction 2 EncapType 3
5-13: 18:44:11:343:a30 Algo[0] Operation: ESP Algo: Triple DES CBC HMAC:
MD5
5-13: 18:44:11:343:a30 Algo[0] MySpi: 1317424746 PeerSpi: 1769785164
5-13: 18:44:11:343:a30 Encap Ports Src 4500 Dst 4500
5-13: 18:44:11:343:a30 Skipping Outbound SA add
5-13: 18:44:11:343:a30 Adding QMs: src = 172.23.23.10.1701, dst =
yyy.yyy.yyy.254.1701, proto = 17, context = 0000000A, my tunnel = 0.0.0.0,
peer tunnel = 0.0.0.0 , SrcMask = 0.0.0.0, DestMask = 0.0.0.0 Lifetime =
3600 LifetimeKBytes 250000 dwFlags 280 Direction 3 EncapType 3
5-13: 18:44:11:343:a30 Algo[0] Operation: ESP Algo: Triple DES CBC HMAC:
MD5
5-13: 18:44:11:343:a30 Algo[0] MySpi: 1317424746 PeerSpi: 1769785164
5-13: 18:44:11:343:a30 Encap Ports Src 4500 Dst 4500
5-13: 18:44:11:343:a30 Skipping Inbound SA add
5-13: 18:44:11:343:a30 Leaving adjust_peer_list entry 000E9FE0 MMCount 0
QMCount 1
5-13: 18:44:11:343:a30 isadb_set_status sa:000EB018 centry:000F0E10 status
0
5-13: 18:44:11:343:a30 isadb_set_status InitiateEvent 00000608: Setting
Status 0
5-13: 18:44:11:343:a30 Clearing centry 000F0E10 InitiateEvent 00000608
5-13: 18:44:11:343:a30
5-13: 18:44:11:343:a30 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
4.4500
5-13: 18:44:11:343:a30 ISAKMP Header: (V1.0), len = 52
5-13: 18:44:11:343:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:11:343:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:11:343:a30 exchange: Oakley Quick Mode
5-13: 18:44:11:343:a30 flags: 1 ( encrypted )
5-13: 18:44:11:343:a30 next payload: HASH
5-13: 18:44:11:343:a30 message ID: c7e064a0
5-13: 18:44:11:343:a30 Ports S:9411 D:9411
5-13: 18:44:11:343:c00 CloseNegHandle 00000608
5-13: 18:44:11:343:c00 SE cookie 71df33eb9c73ff53
5-13: 18:44:13:468:a30
5-13: 18:44:13:468:a30 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.4500
5-13: 18:44:13:468:a30 ISAKMP Header: (V1.0), len = 40
5-13: 18:44:13:468:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:13:468:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:13:468:a30 exchange: ISAKMP Informational Exchange
5-13: 18:44:13:468:a30 flags: 0
5-13: 18:44:13:468:a30 next payload: NOTIFY
5-13: 18:44:13:468:a30 message ID: f8f7ac4e
5-13: 18:44:13:468:a30 received an unencrypted packet when crypto active
5-13: 18:44:13:468:a30 GetPacket failed 35ec
5-13: 18:44:46:437:a30 QM Deleted. Notify from driver: Src 172.23.23.10Dest
yyy.yyy.yyy.254 InSPI 1317424746 OutSpi 1769785164 Tunnel 0 TunnelFilter 0
5-13: 18:44:46:437:a30 Leaving adjust_peer_list entry 000E9FE0 MMCount 0
QMCount 0
5-13: 18:44:46:437:a30 constructing ISAKMP Header
5-13: 18:44:46:437:a30 constructing HASH (null)
5-13: 18:44:46:437:a30 Construct QM Delete Spi 1317424746
5-13: 18:44:46:437:a30 constructing HASH (Notify/Delete)
5-13: 18:44:46:437:a30 Not setting retransmit to downlevel client. SA
000EB018 Centry 00000000
5-13: 18:44:46:437:a30
5-13: 18:44:46:437:a30 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
1.4500
5-13: 18:44:46:437:a30 ISAKMP Header: (V1.0), len = 68
5-13: 18:44:46:437:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:46:437:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:46:437:a30 exchange: ISAKMP Informational Exchange
5-13: 18:44:46:437:a30 flags: 1 ( encrypted )
5-13: 18:44:46:437:a30 next payload: HASH
5-13: 18:44:46:437:a30 message ID: 679b666e
5-13: 18:44:46:437:a30 Ports S:9411 D:9411
5-13: 18:44:46:437:a30 PrivatePeerAddr 0
5-13: 18:44:46:453:15c isadb_schedule_kill_oldPolicy_sas:
1bd3ad55-a47f-4681-b65e0ab514f9eff4 4
5-13: 18:44:46:453:f08 isadb_schedule_kill_oldPolicy_sas:
fcff6101-5f40-478d-8c5bd534220ea8fc 3
5-13: 18:44:46:453:c00 isadb_schedule_kill_oldPolicy_sas:
120647e8-eb08-4c94-91da376e0eb75fd1 2
5-13: 18:44:46:453:15c isadb_schedule_kill_oldPolicy_sas:
a797382c-e5d5-42ee-9fc0e47a6c2fa418 1
5-13: 18:44:46:453:a30 entered kill_old_policy_sas 4
5-13: 18:44:46:453:a30 SA Dead. sa:000EB018 status:3619
5-13: 18:44:46:453:a30 isadb_set_status sa:000EB018 centry:00000000 status
3619
5-13: 18:44:46:453:a30 constructing ISAKMP Header
5-13: 18:44:46:453:a30 constructing HASH (null)
5-13: 18:44:46:453:a30 constructing DELETE. MM 000EB018
5-13: 18:44:46:453:a30 constructing HASH (Notify/Delete)
5-13: 18:44:46:453:a30 Not setting retransmit to downlevel client. SA
000EB018 Centry 00000000
5-13: 18:44:46:453:a30
5-13: 18:44:46:453:a30 Sending: SA = 0x000EB018 to yyy.yyy.yyy.254:Type
1.4500
5-13: 18:44:46:453:a30 ISAKMP Header: (V1.0), len = 84
5-13: 18:44:46:453:a30 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:46:453:a30 R-COOKIE 67296ba6326cc0be
5-13: 18:44:46:453:a30 exchange: ISAKMP Informational Exchange
5-13: 18:44:46:453:a30 flags: 1 ( encrypted )
5-13: 18:44:46:453:a30 next payload: HASH
5-13: 18:44:46:453:a30 message ID: 2ff5567e
5-13: 18:44:46:453:a30 Ports S:9411 D:9411
5-13: 18:44:46:453:a30 entered kill_old_policy_sas 3
5-13: 18:44:46:453:a30 entered kill_old_policy_sas 2
5-13: 18:44:46:453:a30 entered kill_old_policy_sas 1
5-13: 18:44:46:953:2b0
5-13: 18:44:46:953:2b0 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.4500
5-13: 18:44:46:953:2b0 ISAKMP Header: (V1.0), len = 68
5-13: 18:44:46:953:2b0 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:46:953:2b0 R-COOKIE 67296ba6326cc0be
5-13: 18:44:46:953:2b0 exchange: ISAKMP Informational Exchange
5-13: 18:44:46:953:2b0 flags: 1 ( encrypted )
5-13: 18:44:46:953:2b0 next payload: HASH
5-13: 18:44:46:953:2b0 message ID: 81af7dc1
5-13: 18:44:46:953:2b0 processing HASH (Notify/Delete)
5-13: 18:44:46:953:2b0 processing payload DELETE
5-13: 18:44:46:953:2b0 Asked to delete phase2 SPI we don't own: 1769785164
proto=3
5-13: 18:44:48:843:2b0
5-13: 18:44:48:843:2b0 Receive: (get) SA = 0x000eb018 from
yyy.yyy.yyy.254.4500
5-13: 18:44:48:843:2b0 ISAKMP Header: (V1.0), len = 84
5-13: 18:44:48:843:2b0 I-COOKIE 71df33eb9c73ff53
5-13: 18:44:48:843:2b0 R-COOKIE 67296ba6326cc0be
5-13: 18:44:48:843:2b0 exchange: ISAKMP Informational Exchange
5-13: 18:44:48:843:2b0 flags: 1 ( encrypted )
5-13: 18:44:48:843:2b0 next payload: HASH
5-13: 18:44:48:843:2b0 message ID: 56b7c11c
5-13: 18:44:48:843:2b0 processing HASH (Notify/Delete)
5-13: 18:44:48:843:2b0 processing payload DELETE
5-13: 18:44:58:93:2b0 ClearFragList
5-13: 18:47:13:93:2b0 Peer List Entry 000E9FE0
5-13: 18:50:58:93:2b0 Peer List Entry 000E9FE0
5-13: 18:50:58:93:2b0 Release Encap state
5-13: 18:50:58:93:2b0 Remove PeerListEntry
Anybody have ANY ideas?
Thanks
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.openswan.org/pipermail/users/attachments/20070513/a07b8038/attachment-0001.html
More information about the Users
mailing list