[vpn-help] "negotiation timout occurred" in Ubuntu 10

Thu Jun 24 19:28:14 CDT 2010

Matthew, 

Here is most of the iked.log:

10/06/24 18:17:25 ii : ipc client process thread begin ...
10/06/24 18:17:25 <A : peer config add message
10/06/24 18:17:25 DB : peer added ( obj count = 1 )
10/06/24 18:17:25 ii : local address 10.1.10.190 selected for peer
10/06/24 18:17:25 DB : tunnel added ( obj count = 1 )
10/06/24 18:17:25 <A : proposal config message
10/06/24 18:17:25 <A : proposal config message
10/06/24 18:17:25 <A : client config message
10/06/24 18:17:25 <A : xauth username message
10/06/24 18:17:25 <A : xauth password message
10/06/24 18:17:25 <A : local id '852430' message
10/06/24 18:17:25 <A : preshared key message
10/06/24 18:17:25 <A : peer tunnel enable message
10/06/24 18:17:25 DB : new phase1 ( ISAKMP initiator )
10/06/24 18:17:25 DB : exchange type is aggressive
10/06/24 18:17:25 DB : 10.1.10.190:500 <-> 98.129.252.61:500
10/06/24 18:17:25 DB : 277f76bb8d8571d8:0000000000000000
10/06/24 18:17:25 DB : phase1 added ( obj count = 1 )
10/06/24 18:17:25 >> : security association payload
10/06/24 18:17:25 >> : - proposal #1 payload 
10/06/24 18:17:25 >> : -- transform #1 payload 
10/06/24 18:17:25 >> : -- transform #2 payload 
10/06/24 18:17:25 >> : -- transform #3 payload 
10/06/24 18:17:25 >> : -- transform #4 payload 
10/06/24 18:17:25 >> : -- transform #5 payload 
10/06/24 18:17:25 >> : -- transform #6 payload 
10/06/24 18:17:25 >> : -- transform #7 payload 
10/06/24 18:17:25 >> : -- transform #8 payload 
10/06/24 18:17:25 >> : -- transform #9 payload 
10/06/24 18:17:25 >> : -- transform #10 payload 
10/06/24 18:17:25 >> : -- transform #11 payload 
10/06/24 18:17:25 >> : -- transform #12 payload 
10/06/24 18:17:25 >> : -- transform #13 payload 
10/06/24 18:17:25 >> : -- transform #14 payload 
10/06/24 18:17:25 >> : -- transform #15 payload 
10/06/24 18:17:25 >> : -- transform #16 payload 
10/06/24 18:17:25 >> : -- transform #17 payload 
10/06/24 18:17:25 >> : -- transform #18 payload 
10/06/24 18:17:25 >> : key exchange payload
10/06/24 18:17:25 >> : nonce payload
10/06/24 18:17:25 >> : identification payload
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local supports XAUTH
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local supports nat-t ( draft v00 )
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local supports nat-t ( draft v01 )
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local supports nat-t ( draft v02 )
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local supports nat-t ( draft v03 )
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local supports nat-t ( rfc )
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local supports FRAGMENTATION
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local supports DPDv1
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local is SHREW SOFT compatible
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local is NETSCREEN compatible
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local is SIDEWINDER compatible
10/06/24 18:17:25 >> : vendor id payload
10/06/24 18:17:25 ii : local is CISCO UNITY compatible
10/06/24 18:17:25 >= : cookies 277f76bb8d8571d8:0000000000000000
10/06/24 18:17:25 >= : message 00000000
10/06/24 18:17:25 -> : send IKE packet 10.1.10.190:500 ->
98.129.252.61:500 ( 1150 bytes )
10/06/24 18:17:25 DB : phase1 resend event scheduled ( ref count = 2 )
10/06/24 18:17:25 ii : opened tap device tap0
10/06/24 18:17:25 <- : recv IKE packet 98.129.252.61:500 ->
10.1.10.190:500 ( 280 bytes )
10/06/24 18:17:25 DB : phase1 found
10/06/24 18:17:25 << : fragment payload
10/06/24 18:17:25 ii : ike fragment received, waiting on complete packet
10/06/24 18:17:25 <- : recv IKE packet 98.129.252.61:500 ->
10.1.10.190:500 ( 548 bytes )
10/06/24 18:17:25 DB : phase1 found
10/06/24 18:17:25 << : fragment payload
10/06/24 18:17:25 ii : ike fragment received, waiting on complete packet
10/06/24 18:17:35 -> : resend 1 phase1 packet(s) 10.1.10.190:500 ->
98.129.252.61:500
10/06/24 18:17:35 <- : recv IKE packet 98.129.252.61:500 ->
10.1.10.190:500 ( 280 bytes )
10/06/24 18:17:35 DB : phase1 found
10/06/24 18:17:35 << : fragment payload
10/06/24 18:17:35 ii : ike fragment received, processing complete packet
10/06/24 18:17:35 ii : processing informational packet ( 756 bytes )
10/06/24 18:17:35 =< : cookies 277f76bb8d8571d8:0237eedfdf50fd1a
10/06/24 18:17:35 =< : message 00000000
10/06/24 18:17:35 << : notification payload
10/06/24 18:17:35 ii : received peer NO-PROPOSAL-CHOSEN notification
10/06/24 18:17:35 ii : - 98.129.252.61:500 -> 10.1.10.190:500
10/06/24 18:17:35 ii : - unknown spi = none
10/06/24 18:17:35 ii : - data size 716
10/06/24 18:17:35 <- : recv IKE packet 98.129.252.61:500 ->
10.1.10.190:500 ( 548 bytes )
10/06/24 18:17:35 DB : phase1 found
10/06/24 18:17:35 << : fragment payload
10/06/24 18:17:35 ii : ike fragment received, waiting on complete packet
10/06/24 18:17:45 -> : resend 1 phase1 packet(s) 10.1.10.190:500 ->
98.129.252.61:500
10/06/24 18:17:45 <- : recv IKE packet 98.129.252.61:500 ->
10.1.10.190:500 ( 280 bytes )
10/06/24 18:17:45 DB : phase1 found
10/06/24 18:17:45 << : fragment payload
10/06/24 18:17:45 ii : ike fragment received, processing complete packet
10/06/24 18:17:45 ii : processing informational packet ( 756 bytes )
10/06/24 18:17:45 =< : cookies 277f76bb8d8571d8:d4dacf99fd19c65d
10/06/24 18:17:45 =< : message 00000000
10/06/24 18:17:45 << : notification payload
10/06/24 18:17:45 ii : received peer NO-PROPOSAL-CHOSEN notification
10/06/24 18:17:45 ii : - 98.129.252.61:500 -> 10.1.10.190:500
10/06/24 18:17:45 ii : - unknown spi = none
10/06/24 18:17:45 ii : - data size 716
10/06/24 18:17:45 <- : recv IKE packet 98.129.252.61:500 ->
10.1.10.190:500 ( 548 bytes )
10/06/24 18:17:45 DB : phase1 found
10/06/24 18:17:45 << : fragment payload
10/06/24 18:17:45 ii : ike fragment received, waiting on complete packet
10/06/24 18:17:55 -> : resend 1 phase1 packet(s) 10.1.10.190:500 ->
98.129.252.61:500
10/06/24 18:17:55 <- : recv IKE packet 98.129.252.61:500 ->
10.1.10.190:500 ( 280 bytes )
10/06/24 18:17:55 DB : phase1 found
10/06/24 18:17:55 << : fragment payload
10/06/24 18:17:55 ii : ike fragment received, processing complete packet
10/06/24 18:17:55 ii : processing informational packet ( 756 bytes )
10/06/24 18:17:55 =< : cookies 277f76bb8d8571d8:71d487f49e661678
10/06/24 18:17:55 =< : message 00000000
10/06/24 18:17:55 << : notification payload
10/06/24 18:17:55 ii : received peer NO-PROPOSAL-CHOSEN notification
10/06/24 18:17:55 ii : - 98.129.252.61:500 -> 10.1.10.190:500
10/06/24 18:17:55 ii : - unknown spi = none
10/06/24 18:17:55 ii : - data size 716
10/06/24 18:17:55 <- : recv IKE packet 98.129.252.61:500 ->
10.1.10.190:500 ( 548 bytes )
10/06/24 18:17:55 DB : phase1 found
10/06/24 18:17:55 << : fragment payload
10/06/24 18:17:55 ii : ike fragment received, waiting on complete packet
10/06/24 18:18:05 ii : resend limit exceeded for phase1 exchange
10/06/24 18:18:05 ii : phase1 removal before expire time
10/06/24 18:18:05 DB : phase1 deleted ( obj count = 0 )
10/06/24 18:18:05 ii : closed tap device tap0
10/06/24 18:18:05 DB : tunnel stats event canceled ( ref count = 1 )
10/06/24 18:18:05 DB : removing tunnel config references
10/06/24 18:18:05 DB : removing tunnel phase2 references
10/06/24 18:18:05 DB : removing tunnel phase1 references
10/06/24 18:18:05 DB : tunnel deleted ( obj count = 0 )
10/06/24 18:18:05 DB : removing all peer tunnel refrences
10/06/24 18:18:05 DB : peer deleted ( obj count = 0 )
10/06/24 18:18:05 ii : ipc client process thread exit ...

Thanks,
Glen

On Wed, 2010-06-23 at 20:34 -0500, Matthew Grooms wrote:
> On 6/23/2010 5:07 PM, Glen H. Barratt wrote:
> > Hi Matt,
> >
> > I do see this pop up in my syslog when I try to connect:
> >
> > Jun 23 15:52:10 cobra NetworkManager:    SCPlugin-Ifupdown: devices
> > added (path: /sys/devices/virtual/net/tap0, iface: tap0)
> > Jun 23 15:52:10 cobra NetworkManager:    SCPlugin-Ifupdown: device added
> > (path: /sys/devices/virtual/net/tap0, iface: tap0): no ifupdown
> > configuration found.
> > Jun 23 15:52:10 cobra NetworkManager:<WARN>
> > device_creator(): /sys/devices/virtual/net/tap0: couldn't determine
> > device driver; ignoring...
> > Jun 23 15:52:50 cobra NetworkManager:    SCPlugin-Ifupdown: devices
> > removed (path: /sys/devices/virtual/net/tap0, iface: tap0)
> >
> > (My computer's name is "cobra") ... Is there another log that might be
> > useful?
> >
> 
> Yes. Please read the unix bug report page in our support section ...
> 
> http://www.shrew.net/support/wiki/BugReportVpnUnix
> 
> -Matthew