[Openswan Users] RSA + XAUTH + Cisco reconnection failures
Andrew Campbell
Andrew.Campbell at madisontech.com.au
Fri Mar 12 08:30:07 EST 2010
Hello Everybody,
Still working on getting Openswan to work with my Cisco router.
I changed my Cisco configuration from a Dynamic Virtual Tunnel Interface
to a Crypto Map and things have improved dramatically. I can now toggle
the IPSec connection up and down and works flawlessly. Errors in logfile
have also cleared up - will be talking to Cisco TAC soon about the
difference between DVTI and crypto maps.
One more problem to solve - after the IPSec lifetime of 28800 seconds it
fails to reconnect.
Any advice will be greatly appreciated.
Openswan log
------------
Mar 12 23:57:31 : packet from 113.192.10.21:4500: received Vendor ID
payload [RFC 3947] method set to=109
Mar 12 23:57:31 : packet from 113.192.10.21:4500: ignoring unknown
Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Mar 12 23:57:31 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using
method 109
Mar 12 23:57:31 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using
method 109
Mar 12 23:57:31 : "vpn" #3: responding to Main Mode
Mar 12 23:57:31 : "vpn" #3: policy mandates Extended Authentication
(XAUTH) with RSA of responder (we are responder). Attribute
OAKLEY_AUTHENTICATION_METHOD
Mar 12 23:57:31 : "vpn" #3: OAKLEY_DES_CBC is not supported. Attribute
OAKLEY_ENCRYPTION_ALGORITHM
Mar 12 23:57:31 : "vpn" #3: no acceptable Oakley Transform
Mar 12 23:57:31 : "vpn" #3: sending notification NO_PROPOSAL_CHOSEN to
113.192.10.21:4500
Mar 12 23:57:41 : packet from 113.192.10.21:4500: received Vendor ID
payload [RFC 3947] method set to=109
Mar 12 23:57:41 : packet from 113.192.10.21:4500: ignoring unknown
Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Mar 12 23:57:41 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using
method 109
Mar 12 23:57:41 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using
method 109
Mar 12 23:57:41 : "vpn" #4: responding to Main Mode
Mar 12 23:57:41 : "vpn" #4: policy mandates Extended Authentication
(XAUTH) with RSA of responder (we are responder). Attribute
OAKLEY_AUTHENTICATION_METHOD
Mar 12 23:57:41 : "vpn" #4: OAKLEY_DES_CBC is not supported. Attribute
OAKLEY_ENCRYPTION_ALGORITHM
Mar 12 23:57:41 : "vpn" #4: no acceptable Oakley Transform
Mar 12 23:57:41 : "vpn" #4: sending notification NO_PROPOSAL_CHOSEN to
113.192.10.21:4500
Mar 12 23:57:51 : packet from 113.192.10.21:4500: received Vendor ID
payload [RFC 3947] method set to=109
Mar 12 23:57:51 : packet from 113.192.10.21:4500: ignoring unknown
Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Mar 12 23:57:51 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using
method 109
Mar 12 23:57:51 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using
method 109
Mar 12 23:57:51 : "vpn" #5: responding to Main Mode
Mar 12 23:57:51 : "vpn" #5: policy mandates Extended Authentication
(XAUTH) with RSA of responder (we are responder). Attribute
OAKLEY_AUTHENTICATION_METHOD
Mar 12 23:57:51 : "vpn" #5: OAKLEY_DES_CBC is not supported. Attribute
OAKLEY_ENCRYPTION_ALGORITHM
Mar 12 23:57:51 : "vpn" #5: no acceptable Oakley Transform
Mar 12 23:57:51 : "vpn" #5: sending notification NO_PROPOSAL_CHOSEN to
113.192.10.21:4500
Mar 12 23:58:01 : packet from 113.192.10.21:4500: received Vendor ID
payload [RFC 3947] method set to=109
Mar 12 23:58:01 : packet from 113.192.10.21:4500: ignoring unknown
Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Mar 12 23:58:01 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using
method 109
Mar 12 23:58:01 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using
method 109
Mar 12 23:58:01 : "vpn" #6: responding to Main Mode
Mar 12 23:58:01 : "vpn" #6: policy mandates Extended Authentication
(XAUTH) with RSA of responder (we are responder). Attribute
OAKLEY_AUTHENTICATION_METHOD
Mar 12 23:58:01 : "vpn" #6: OAKLEY_DES_CBC is not supported. Attribute
OAKLEY_ENCRYPTION_ALGORITHM
Mar 12 23:58:01 : "vpn" #6: no acceptable Oakley Transform
Mar 12 23:58:01 : "vpn" #6: sending notification NO_PROPOSAL_CHOSEN to
113.192.10.21:4500
Mar 12 23:58:11 : packet from 113.192.10.21:4500: received Vendor ID
payload [RFC 3947] method set to=109
Mar 12 23:58:11 : packet from 113.192.10.21:4500: ignoring unknown
Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Mar 12 23:58:11 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using
method 109
Mar 12 23:58:11 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using
method 109
Mar 12 23:58:11 : "vpn" #7: responding to Main Mode
Mar 12 23:58:11 : "vpn" #7: policy mandates Extended Authentication
(XAUTH) with RSA of responder (we are responder). Attribute
OAKLEY_AUTHENTICATION_METHOD
Mar 12 23:58:11 : "vpn" #7: OAKLEY_DES_CBC is not supported. Attribute
OAKLEY_ENCRYPTION_ALGORITHM
Mar 12 23:58:11 : "vpn" #7: no acceptable Oakley Transform
Mar 12 23:58:11 : "vpn" #7: sending notification NO_PROPOSAL_CHOSEN to
113.192.10.21:4500
Mar 12 23:58:21 : packet from 113.192.10.21:4500: received Vendor ID
payload [RFC 3947] method set to=109
Mar 12 23:58:21 : packet from 113.192.10.21:4500: ignoring unknown
Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Mar 12 23:58:21 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using
method 109
Mar 12 23:58:21 : packet from 113.192.10.21:4500: received Vendor ID
payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using
method 109
Mar 12 23:58:21 : "vpn" #8: responding to Main Mode
Mar 12 23:58:21 : "vpn" #8: policy mandates Extended Authentication
(XAUTH) with RSA of responder (we are responder). Attribute
OAKLEY_AUTHENTICATION_METHOD
Mar 12 23:58:21 : "vpn" #8: OAKLEY_DES_CBC is not supported. Attribute
OAKLEY_ENCRYPTION_ALGORITHM
Mar 12 23:58:21 : "vpn" #8: no acceptable Oakley Transform
Mar 12 23:58:21 : "vpn" #8: sending notification NO_PROPOSAL_CHOSEN to
113.192.10.21:4500
Cisco log
---------
Mar 12 23:57:32.499: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 113.192.10.21, remote= 113.192.10.2,
local_proxy= 10.1.1.0/255.255.255.0/0/0 (type=4),
remote_proxy= 192.168.100.200/255.255.255.255/0/0 (type=1),
protocol= ESP, transform= esp-3des esp-sha-hmac (Tunnel),
lifedur= 28800s and 4608000kb,
spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
Mar 12 23:57:32.499: IPSEC(lifetime_expiry): SA lifetime threshold
reached, expiring in 577 seconds
Mar 12 23:57:32.499: ISAKMP:(0): SA request profile is (NULL)
Mar 12 23:57:32.499: ISAKMP: Found a peer struct for 113.192.10.2, peer
port 64770
Mar 12 23:57:32.499: ISAKMP: Locking peer struct 0x4453306C, refcount 1
for isakmp_initiator
Mar 12 23:57:32.499: ISAKMP: local port 4500, remote port 64770
Mar 12 23:57:32.499: ISAKMP: set new node 0 to CONF_XAUTH
Mar 12 23:57:32.499: insert sa successfully sa = 44DE0384
Mar 12 23:57:32.499: ISAKMP:(0):Can not start Aggressive mode, trying
Main mode.
Mar 12 23:57:32.499: ISAKMP:(0):No pre-shared key with 113.192.10.2!
Mar 12 23:57:32.499: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
Mar 12 23:57:32.499: ISAKMP:(0): constructed NAT-T vendor-07 ID
Mar 12 23:57:32.499: ISAKMP:(0): constructed NAT-T vendor-03 ID
Mar 12 23:57:32.499: ISAKMP:(0): constructed NAT-T vendor-02 ID
Mar 12 23:57:32.499: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC,
IKE_SA_REQ_MM
Mar 12 23:57:32.499: ISAKMP:(0):Old State = IKE_READY New State =
IKE_I_MM1
Mar 12 23:57:32.499: ISAKMP:(0): beginning Main Mode exchange
Mar 12 23:57:32.499: ISAKMP:(0): sending packet to 113.192.10.2 my_port
4500 peer_port 64770 (I) MM_NO_STATE
Mar 12 23:57:32.499: ISAKMP:(0):Sending an IKE IPv4 Packet.
Mar 12 23:57:32.503: ISAKMP (0:0): received packet from 113.192.10.2
dport 4500 sport 64770 Global (I) MM_NO_STATE
Mar 12 23:57:32.503: ISAKMP:(0):Notify has no hash. Rejected.
Mar 12 23:57:32.503: ISAKMP (0:0): Unknown Input IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY: state = IKE_I_MM1
Mar 12 23:57:32.503: ISAKMP:(0):Input = IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY
Mar 12 23:57:32.503: ISAKMP:(0):Old State = IKE_I_MM1 New State =
IKE_I_MM1
Mar 12 23:57:32: %CRYPTO-6-IKMP_MODE_FAILURE: Processing of
Informational mode failed with peer at 113.192.10.2
Mar 12 23:57:42.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
Mar 12 23:57:42.500: ISAKMP (0:0): incrementing error counter on sa,
attempt 1 of 5: retransmit phase 1
Mar 12 23:57:42.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
Mar 12 23:57:42.500: ISAKMP:(0): sending packet to 113.192.10.2 my_port
4500 peer_port 64770 (I) MM_NO_STATE
Mar 12 23:57:42.500: ISAKMP:(0):Sending an IKE IPv4 Packet.
Mar 12 23:57:42.500: ISAKMP (0:0): received packet from 113.192.10.2
dport 4500 sport 64770 Global (I) MM_NO_STATE
Mar 12 23:57:42.500: ISAKMP:(0):Notify has no hash. Rejected.
Mar 12 23:57:42.500: ISAKMP (0:0): Unknown Input IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY: state = IKE_I_MM1
Mar 12 23:57:42.500: ISAKMP:(0):Input = IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY
Mar 12 23:57:42.500: ISAKMP:(0):Old State = IKE_I_MM1 New State =
IKE_I_MM1
Mar 12 23:57:52.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
Mar 12 23:57:52.500: ISAKMP (0:0): incrementing error counter on sa,
attempt 2 of 5: retransmit phase 1
Mar 12 23:57:52.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
Mar 12 23:57:52.500: ISAKMP:(0): sending packet to 113.192.10.2 my_port
4500 peer_port 64770 (I) MM_NO_STATE
Mar 12 23:57:52.500: ISAKMP:(0):Sending an IKE IPv4 Packet.
Mar 12 23:57:52.500: ISAKMP (0:0): received packet from 113.192.10.2
dport 4500 sport 64770 Global (I) MM_NO_STATE
Mar 12 23:57:52.500: ISAKMP:(0):Notify has no hash. Rejected.
Mar 12 23:57:52.500: ISAKMP (0:0): Unknown Input IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY: state = IKE_I_MM1
Mar 12 23:57:52.500: ISAKMP:(0):Input = IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY
Mar 12 23:57:52.500: ISAKMP:(0):Old State = IKE_I_MM1 New State =
IKE_I_MM1
Mar 12 23:58:02.500: IPSEC(key_engine): request timer fired: count = 1,
(identity) local= 113.192.10.21, remote= 113.192.10.2,
local_proxy= 10.1.1.0/255.255.255.0/0/0 (type=4),
remote_proxy= 192.168.100.200/255.255.255.255/0/0 (type=1)
Mar 12 23:58:02.500: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 113.192.10.21, remote= 113.192.10.2,
local_proxy= 10.1.1.0/255.255.255.0/0/0 (type=4),
remote_proxy= 192.168.100.200/255.255.255.255/0/0 (type=1),
protocol= ESP, transform= esp-3des esp-sha-hmac (Tunnel),
lifedur= 28800s and 4608000kb,
spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
Mar 12 23:58:02.500: ISAKMP: set new node 0 to CONF_XAUTH
Mar 12 23:58:02.500: ISAKMP:(0):SA is still budding. Attached new ipsec
request to it. (local 113.192.10.21, remote 113.192.10.2)
Mar 12 23:58:02.500: ISAKMP: Error while processing SA request: Failed
to initialize SA
Mar 12 23:58:02.500: ISAKMP: Error while processing KMI message 0, error
2.
Mar 12 23:58:02.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
Mar 12 23:58:02.500: ISAKMP (0:0): incrementing error counter on sa,
attempt 3 of 5: retransmit phase 1
Mar 12 23:58:02.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
Mar 12 23:58:02.500: ISAKMP:(0): sending packet to 113.192.10.2 my_port
4500 peer_port 64770 (I) MM_NO_STATE
Mar 12 23:58:02.500: ISAKMP:(0):Sending an IKE IPv4 Packet.
Mar 12 23:58:02.500: ISAKMP (0:0): received packet from 113.192.10.2
dport 4500 sport 64770 Global (I) MM_NO_STATE
Mar 12 23:58:02.500: ISAKMP:(0):Notify has no hash. Rejected.
Mar 12 23:58:02.500: ISAKMP (0:0): Unknown Input IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY: state = IKE_I_MM1
Mar 12 23:58:02.504: ISAKMP:(0):Input = IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY
Mar 12 23:58:02.504: ISAKMP:(0):Old State = IKE_I_MM1 New State =
IKE_I_MM1
Mar 12 23:58:12.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
Mar 12 23:58:12.500: ISAKMP (0:0): incrementing error counter on sa,
attempt 4 of 5: retransmit phase 1
Mar 12 23:58:12.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
Mar 12 23:58:12.500: ISAKMP:(0): sending packet to 113.192.10.2 my_port
4500 peer_port 64770 (I) MM_NO_STATE
Mar 12 23:58:12.500: ISAKMP:(0):Sending an IKE IPv4 Packet.
Mar 12 23:58:12.500: ISAKMP (0:0): received packet from 113.192.10.2
dport 4500 sport 64770 Global (I) MM_NO_STATE
Mar 12 23:58:12.500: ISAKMP:(0):Notify has no hash. Rejected.
Mar 12 23:58:12.500: ISAKMP (0:0): Unknown Input IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY: state = IKE_I_MM1
Mar 12 23:58:12.500: ISAKMP:(0):Input = IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY
Mar 12 23:58:12.500: ISAKMP:(0):Old State = IKE_I_MM1 New State =
IKE_I_MM1
Mar 12 23:58:22.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
Mar 12 23:58:22.500: ISAKMP (0:0): incrementing error counter on sa,
attempt 5 of 5: retransmit phase 1
Mar 12 23:58:22.500: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
Mar 12 23:58:22.500: ISAKMP:(0): sending packet to 113.192.10.2 my_port
4500 peer_port 64770 (I) MM_NO_STATE
Mar 12 23:58:22.500: ISAKMP:(0):Sending an IKE IPv4 Packet.
Mar 12 23:58:22.500: ISAKMP (0:0): received packet from 113.192.10.2
dport 4500 sport 64770 Global (I) MM_NO_STATE
Mar 12 23:58:22.500: ISAKMP:(0):Notify has no hash. Rejected.
Mar 12 23:58:22.500: ISAKMP (0:0): Unknown Input IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY: state = IKE_I_MM1
Mar 12 23:58:22.500: ISAKMP:(0):Input = IKE_MESG_FROM_PEER,
IKE_INFO_NOTIFY
Mar 12 23:58:22.500: ISAKMP:(0):Old State = IKE_I_MM1 New State =
IKE_I_MM1
Mar 12 23:58:32.501: IPSEC(key_engine): request timer fired: count = 2,
(identity) local= 113.192.10.21, remote= 113.192.10.2,
local_proxy= 10.1.1.0/255.255.255.0/0/0 (type=4),
remote_proxy= 192.168.100.200/255.255.255.255/0/0 (type=1)
Mar 12 23:58:32.501: IPSEC(rte_mgr): VPN Route Event Deleting dynamic
maps
Mar 12 23:58:32.501: IPSEC(rte_mgr): VPN Route Refcount 0
GigabitEthernet0/1
Mar 12 23:58:32.501: IPSEC(rte_mgr): VPN Route Removed 192.168.100.200
255.255.255.255 via 113.192.10.2 in IP DEFAULT TABLE GigabitEthernet0/1
Mar 12 23:58:32.501: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 113.192.10.21, sa_proto= 50,
sa_spi= 0x745CE655(1952245333),
sa_trans= esp-3des esp-sha-hmac , sa_conn_id= 6059,
(identity) local= 113.192.10.21, remote= 113.192.10.2,
local_proxy= 10.1.1.0/255.255.255.0/0/0 (type=4),
remote_proxy= 192.168.100.200/255.255.255.255/0/0 (type=1)
Mar 12 23:58:32.501: IPSEC(update_current_outbound_sa): updated peer
113.192.10.2 current outbound sa to SPI 0
Mar 12 23:58:32.501: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 113.192.10.2, sa_proto= 50,
sa_spi= 0x19BD0B2D(431819565),
sa_trans= esp-3des esp-sha-hmac , sa_conn_id= 6060,
(identity) local= 113.192.10.21, remote= 113.192.10.2,
local_proxy= 10.1.1.0/255.255.255.0/0/0 (type=4),
remote_proxy= 192.168.100.200/255.255.255.255/0/0 (type=1)
Mar 12 23:58:32.501: IPSEC(rte_mgr): VPN Route Event session cleared or
IC
Mar 12 23:58:32.501: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
Mar 12 23:58:32.501: ISAKMP:(0):peer does not do paranoid keepalives.
Mar 12 23:58:32.501: ISAKMP:(0):deleting SA reason "Death by
retransmission P1" state (I) MM_NO_STATE (peer 113.192.10.2)
Mar 12 23:58:32.501: ISAKMP: ignoring request to send delete notify (no
ISAKMP sa) src 113.192.10.21 dst 113.192.10.2 for SPI 0x745CE655
Mar 12 23:58:32.505: ISAKMP:(0):deleting SA reason "Death by
retransmission P1" state (I) MM_NO_STATE (peer 113.192.10.2)
Mar 12 23:58:32.505: ISAKMP: returning address 192.168.100.200 to pool
Mar 12 23:58:32.505: ISAKMP: Unlocking peer struct 0x4453306C for
isadb_mark_sa_deleted(), count 0
Mar 12 23:58:32.505: crypto_ikmp_dpd_refcount_zero: Freeing dpd
profile_name VPN-profile
Mar 12 23:58:32.505: ISAKMP: returning address 192.168.100.200 to pool
Mar 12 23:58:32.505: ISAKMP: Deleting peer node by peer_reap for
113.192.10.2: 4453306C
Mar 12 23:58:32.505: ISAKMP: returning address 192.168.100.200 to pool
Mar 12 23:58:32.505: ISAKMP:(0):deleting node -429765825 error FALSE
reason "IKE deleted"
Mar 12 23:58:32.505: ISAKMP:(0):deleting node 871483634 error FALSE
reason "IKE deleted"
Mar 12 23:58:32.505: ISAKMP:(0):Input = IKE_MESG_INTERNAL,
IKE_PHASE1_DEL
Mar 12 23:58:32.505: ISAKMP:(0):Old State = IKE_I_MM1 New State =
IKE_DEST_SA
Mar 12 23:58:32.505: IPSEC(key_engine): got a queue event with 1 KMI
message(s)
Mar 12 23:59:22.505: ISAKMP:(0):purging node -429765825
Mar 12 23:59:22.505: ISAKMP:(0):purging node 871483634
Mar 12 23:59:32.506: ISAKMP:(0):purging SA., sa=44DE0384, delme=44DE0384
Thanks for looking!
Andrew
______________________________________________________________________
The information contained in this e-mail (including any attachments)
is confidential. It is only intended for the recipient/s named above.
If you are not the intended or one of the intended recipient/s any
unauthorised use is prohibited. If you have received this e-mail in
error, please notify the sender and destroy all copies of this e-mail.
Confidentiality and legal privilege are not waived or lost as a result
of mistaken delivery.
Opinions expressed in this e-mail are those of the sender and unless
expressly stated are not necessarily the opinions of Madison
Technologies Pty Ltd.
This email has been scanned by the MessageLabs Email Security System.
For more information please visit http://www.messagelabs.com/email
______________________________________________________________________
More information about the Users
mailing list