[vpn-help] Connection failure with client. Debug information doesn't seem helpful.

Thu Jun 30 23:32:31 CDT 2011

On 07/01/2011 12:15 AM, Eric B. wrote:
> Hi,
>
> I am looking to configured my FC14 box as an IPSEC client to connect to
> my office VPN. I do not know what server the office VPN is using. All
> I know are the specs that they have given me. This is my first attempt
> in getting the IPSEC tunnel to work from Linux. I don't know if anyone
> else has managed successfully. I do know that Mac users have gotten it
> working with ipsecuritas.
>
>
> I enabled debug messages, but that didn't seem to give me a whole lot
> more information:
> /var/log/ike/iked.log:
> 11/07/01 00:01:52 ## : IKE Daemon, ver 2.1.7
> 11/07/01 00:01:52 ## : Copyright 2010 Shrew Soft Inc.
> 11/07/01 00:01:52 ## : This product linked OpenSSL 1.0.0d-fips 8 Feb 2011
> 11/07/01 00:01:52 K! : recv X_SPDDUMP message failure ( errno = 2 )
> 11/07/01 00:01:58 !! : '/home/eric/Documents/VPN/ericb.p12' load failed,
> requesting password
> 11/07/01 00:02:32 !! : unprocessed payload data
> 11/07/01 00:02:32 !! : unprocessed payload data
> 11/07/01 00:02:32 !! : unhandled phase1 payload 'unknown' ( 245 )
> 11/07/01 00:02:32 !! : unprocessed payload data

A quick followup.  I double checked my /etc/ike/iked.conf file and it 
was misconfigured.  With proper debug level enabled, I now get the 
following trace (I still can't understand it however):
/var/log/ike/iked.log:
11/07/01 00:27:04 ## : IKE Daemon, ver 2.1.7
11/07/01 00:27:04 ## : Copyright 2010 Shrew Soft Inc.
11/07/01 00:27:04 ## : This product linked OpenSSL 1.0.0d-fips 8 Feb 2011
11/07/01 00:27:04 ii : opened '/var/log/iked/iked.log'
11/07/01 00:27:04 ii : network process thread begin ...
11/07/01 00:27:04 ii : pfkey process thread begin ...
11/07/01 00:27:04 ii : ipc server process thread begin ...
11/07/01 00:27:05 K< : recv pfkey REGISTER AH message
11/07/01 00:27:05 K< : recv pfkey REGISTER ESP message
11/07/01 00:27:05 K< : recv pfkey REGISTER IPCOMP message
11/07/01 00:27:05 K! : recv X_SPDDUMP message failure ( errno = 2 )
11/07/01 00:27:17 ii : ipc client process thread begin ...
11/07/01 00:27:17 <A : peer config add message
11/07/01 00:27:17 DB : peer added ( obj count = 1 )
11/07/01 00:27:17 ii : local address 192.168.2.114 selected for peer
11/07/01 00:27:17 DB : tunnel added ( obj count = 1 )
11/07/01 00:27:17 <A : proposal config message
11/07/01 00:27:17 <A : proposal config message
11/07/01 00:27:17 <A : client config message
11/07/01 00:27:17 <A : remote cert '/home/eric/Documents/VPN/ericb.p12' 
message
11/07/01 00:27:17 !! : '/home/eric/Documents/VPN/ericb.p12' load failed, 
requesting password
11/07/01 00:27:21 <A : file password
11/07/01 00:27:21 <A : remote cert '/home/eric/Documents/VPN/ericb.p12' 
message
11/07/01 00:27:21 ii : '/home/eric/Documents/VPN/ericb.p12' loaded
11/07/01 00:27:21 <A : local cert '/home/eric/Documents/VPN/ericb.pem' 
message
11/07/01 00:27:21 ii : '/home/eric/Documents/VPN/ericb.pem' loaded
11/07/01 00:27:21 <A : local key '/home/eric/Documents/VPN/ericb.key' 
message
11/07/01 00:27:21 ii : '/home/eric/Documents/VPN/ericb.key' loaded
11/07/01 00:27:21 <A : peer tunnel enable message
11/07/01 00:27:21 DB : new phase1 ( ISAKMP initiator )
11/07/01 00:27:21 DB : exchange type is identity protect
11/07/01 00:27:21 DB : 192.168.2.114:500 <-> xx.xx.160.179:500
11/07/01 00:27:21 DB : fc65ce98e1ea6e4e:0000000000000000
11/07/01 00:27:21 DB : phase1 added ( obj count = 1 )
11/07/01 00:27:21 >> : security association payload
11/07/01 00:27:21 >> : - proposal #1 payload
11/07/01 00:27:21 >> : -- transform #1 payload
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local supports nat-t ( draft v00 )
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local supports nat-t ( draft v01 )
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local supports nat-t ( draft v02 )
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local supports nat-t ( draft v03 )
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local supports nat-t ( rfc )
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local supports FRAGMENTATION
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local supports DPDv1
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local is SHREW SOFT compatible
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local is NETSCREEN compatible
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local is SIDEWINDER compatible
11/07/01 00:27:21 >> : vendor id payload
11/07/01 00:27:21 ii : local is CISCO UNITY compatible
11/07/01 00:27:21 >= : cookies fc65ce98e1ea6e4e:0000000000000000
11/07/01 00:27:21 >= : message 00000000
11/07/01 00:27:21 -> : send IKE packet 192.168.2.114:500 -> 
xx.xx.160.179:500 ( 344 bytes )
11/07/01 00:27:21 DB : phase1 resend event scheduled ( ref count = 2 )
11/07/01 00:27:21 ii : opened tap device tap0
11/07/01 00:27:22 <- : recv IKE packet xx.xx.160.179:500 -> 
192.168.2.114:500 ( 144 bytes )
11/07/01 00:27:22 DB : phase1 found
11/07/01 00:27:22 ii : processing phase1 packet ( 144 bytes )
11/07/01 00:27:22 =< : cookies fc65ce98e1ea6e4e:1c3396377d7b7fab
11/07/01 00:27:22 =< : message 00000000
11/07/01 00:27:22 << : security association payload
11/07/01 00:27:22 << : - propsal #1 payload
11/07/01 00:27:22 << : -- transform #1 payload
11/07/01 00:27:22 ii : matched isakmp proposal #1 transform #1
11/07/01 00:27:22 ii : - transform    = ike
11/07/01 00:27:22 ii : - cipher type  = aes
11/07/01 00:27:22 ii : - key length   = 128 bits
11/07/01 00:27:22 ii : - hash type    = sha1
11/07/01 00:27:22 ii : - dh group     = modp-1024
11/07/01 00:27:22 ii : - auth type    = sig-rsa
11/07/01 00:27:22 ii : - life seconds = 86400
11/07/01 00:27:22 ii : - life kbytes  = 0
11/07/01 00:27:22 << : vendor id payload
11/07/01 00:27:22 ii : unknown vendor id ( 12 bytes )
11/07/01 00:27:22 0x : 4f456d40 6b675346 4548407f
11/07/01 00:27:22 << : vendor id payload
11/07/01 00:27:22 ii : peer supports DPDv1
11/07/01 00:27:22 << : vendor id payload
11/07/01 00:27:22 ii : peer supports nat-t ( rfc )
11/07/01 00:27:22 >> : key exchange payload
11/07/01 00:27:22 >> : nonce payload
11/07/01 00:27:22 >> : cert request payload
11/07/01 00:27:22 >> : nat discovery payload
11/07/01 00:27:22 >> : nat discovery payload
11/07/01 00:27:22 >= : cookies fc65ce98e1ea6e4e:1c3396377d7b7fab
11/07/01 00:27:22 >= : message 00000000
11/07/01 00:27:22 DB : phase1 resend event canceled ( ref count = 1 )
11/07/01 00:27:22 -> : send IKE packet 192.168.2.114:500 -> 
xx.xx.160.179:500 ( 265 bytes )
11/07/01 00:27:22 DB : phase1 resend event scheduled ( ref count = 2 )
11/07/01 00:27:22 <- : recv IKE packet xx.xx.160.179:500 -> 
192.168.2.114:500 ( 228 bytes )
11/07/01 00:27:22 DB : phase1 found
11/07/01 00:27:22 ii : processing phase1 packet ( 228 bytes )
11/07/01 00:27:22 =< : cookies fc65ce98e1ea6e4e:1c3396377d7b7fab
11/07/01 00:27:22 =< : message 00000000
11/07/01 00:27:22 << : key exchange payload
11/07/01 00:27:22 << : nonce payload
11/07/01 00:27:22 << : nat discovery payload
11/07/01 00:27:22 << : nat discovery payload
11/07/01 00:27:22 ii : nat discovery - local address is translated
11/07/01 00:27:22 ii : nat discovery - remote address is translated
11/07/01 00:27:22 ii : switching to src nat-t udp port 4500
11/07/01 00:27:22 ii : switching to dst nat-t udp port 4500
11/07/01 00:27:22 == : DH shared secret ( 128 bytes )
11/07/01 00:27:22 == : SETKEYID ( 20 bytes )
11/07/01 00:27:22 == : SETKEYID_d ( 20 bytes )
11/07/01 00:27:22 == : SETKEYID_a ( 20 bytes )
11/07/01 00:27:22 == : SETKEYID_e ( 20 bytes )
11/07/01 00:27:22 == : cipher key ( 16 bytes )
11/07/01 00:27:22 == : cipher iv ( 16 bytes )
11/07/01 00:27:22 >> : identification payload
11/07/01 00:27:22 >> : certificate payload
11/07/01 00:27:22 == : phase1 hash_i ( computed ) ( 20 bytes )
11/07/01 00:27:22 >> : signature payload
11/07/01 00:27:22 >= : cookies fc65ce98e1ea6e4e:1c3396377d7b7fab
11/07/01 00:27:22 >= : message 00000000
11/07/01 00:27:22 >= : encrypt iv ( 16 bytes )
11/07/01 00:27:22 == : encrypt packet ( 866 bytes )
11/07/01 00:27:22 == : stored iv ( 16 bytes )
11/07/01 00:27:22 DB : phase1 resend event canceled ( ref count = 1 )
11/07/01 00:27:22 -> : send NAT-T:IKE packet 192.168.2.114:4500 -> 
xx.xx.160.179:4500 ( 908 bytes )
11/07/01 00:27:32 <- : recv IKE packet xx.xx.160.179:500 -> 
192.168.2.114:500 ( 228 bytes )
11/07/01 00:27:32 DB : phase1 found
11/07/01 00:27:32 ww : initiator port values should only float once per 
session
11/07/01 00:27:32 ii : processing phase1 packet ( 228 bytes )
11/07/01 00:27:32 =< : cookies fc65ce98e1ea6e4e:1c3396377d7b7fab
11/07/01 00:27:32 =< : message 00000000
11/07/01 00:27:32 << : ignoring duplicate key excahnge payload
11/07/01 00:27:32 !! : unprocessed payload data
11/07/01 00:27:32 << : ignoring duplicate nonce payload
11/07/01 00:27:32 !! : unprocessed payload data
11/07/01 00:27:32 !! : unhandled phase1 payload 'unknown' ( 42 )
11/07/01 00:27:32 !! : unprocessed payload data
11/07/01 00:27:32 ii : sending peer DELETE message
11/07/01 00:27:32 ii : - 192.168.2.114:4500 -> xx.xx.160.179:4500
11/07/01 00:27:32 ii : - isakmp spi = fc65ce98e1ea6e4e:1c3396377d7b7fab
11/07/01 00:27:32 ii : - data size 0
11/07/01 00:27:32 >> : hash payload
11/07/01 00:27:32 >> : delete payload
11/07/01 00:27:32 == : new informational hash ( 20 bytes )
11/07/01 00:27:32 == : new informational iv ( 16 bytes )
11/07/01 00:27:32 >= : cookies fc65ce98e1ea6e4e:1c3396377d7b7fab
11/07/01 00:27:32 >= : message f0ebee95
11/07/01 00:27:32 >= : encrypt iv ( 16 bytes )
11/07/01 00:27:32 == : encrypt packet ( 80 bytes )
11/07/01 00:27:32 == : stored iv ( 16 bytes )
11/07/01 00:27:32 -> : send NAT-T:IKE packet 192.168.2.114:4500 -> 
xx.xx.160.179:4500 ( 124 bytes )
11/07/01 00:27:32 ii : phase1 removal before expire time
11/07/01 00:27:32 DB : phase1 deleted ( obj count = 0 )
11/07/01 00:27:32 DB : policy not found
11/07/01 00:27:32 DB : policy not found
11/07/01 00:27:32 DB : policy not found
11/07/01 00:27:32 DB : policy not found
11/07/01 00:27:32 ii : removing IPsec over DHCP policies
11/07/01 00:27:32 DB : policy not found
11/07/01 00:27:32 DB : policy not found
11/07/01 00:27:32 ii : closed tap device tap0
11/07/01 00:27:32 DB : tunnel stats event canceled ( ref count = 1 )
11/07/01 00:27:32 DB : removing tunnel config references
11/07/01 00:27:32 DB : removing tunnel phase2 references
11/07/01 00:27:32 DB : removing tunnel phase1 references
11/07/01 00:27:32 DB : tunnel deleted ( obj count = 0 )
11/07/01 00:27:32 DB : removing all peer tunnel refrences
11/07/01 00:27:32 DB : peer deleted ( obj count = 0 )
11/07/01 00:27:32 ii : ipc client process thread exit ...
11/07/01 00:27:33 <- : recv IKE packet xx.xx.160.179:500 -> 
192.168.2.114:500 ( 40 bytes )
11/07/01 00:27:33 DB : phase1 not found
11/07/01 00:27:33 ww : ike packet from xx.xx.160.179 ignored, unknown 
phase1 sa for peer
11/07/01 00:27:33 ww : fc65ce98e1ea6e4e:1c3396377d7b7fab
11/07/01 00:27:52 <- : recv IKE packet xx.xx.160.179:500 -> 
192.168.2.114:500 ( 228 bytes )
11/07/01 00:27:52 DB : phase1 not found
11/07/01 00:27:52 ww : ike packet from xx.xx.160.179 ignored, unknown 
phase1 sa for peer
11/07/01 00:27:52 ww : fc65ce98e1ea6e4e:1c3396377d7b7fab

Thanks for any help!

Eric