[vpn-help] shrew -> NAT(linux)-> strongswan = disconnected

Wed Jun 23 23:16:43 CDT 2010

I set the debug level in strongswan to maximum (plutodebug=all) but I see no extra info in log during connection.
pluto provide exactly the same amount of info as without debug.
I rechecked connrction without NAT - it works and in log successful connection ends with

pluto[7534]: "rw2"[2] 195.162.52.179 #3: responding to Quick Mode
pluto[7534]: "rw2"[2] 195.162.52.179 #3: Dead Peer Detection (RFC 3706) enabled
pluto[7534]: "rw2"[2] 195.162.52.179 #3: IPsec SA established {ESP=>0xe95cd43e <0xf5d20acc}

As for DPD:
"Nevertheless Pluto will always send the DPD Vendor ID during connection set up
in order to signal the readiness to act passively as a responder if the peer wants to use DPD."
So strongswan should respond to DPD packets by default.
I turn on
dpdaction=clear
dpddelay=10
but with no effect.
Maybe problem only on NAT (some packets/proto do not pass)?
Could you tell how check DPD packets with tcpdump on NAT box?

MG> On 6/23/2010 2:10 AM, sftf wrote:
>> I have successfully configured Shrew VPN Client 2.1.5 to work with strongswan.
>> Without NAT between client and server everything ok.
>> But when client connecting to the gateway through NAT (linux box or DLink DIR-300)
>> connection is established ("tunnel enabled"), but after a while becomes disconnected ("gateway is not responding").
>> client(192.168.0.25)<-->(192.168.0.254)NAT_box(195.162.66.179)<-->gateway(195.162.66.178)
>> NAT_box allow all tarffic. On gateway esp,ah,udp 500, 4500 are opened for inbound and outbound connections.
>>
>> What to look for?
>> Logs below.
>>

MG> So, both the client and the gateway report DPD support ...

>> 10/06/23 09:38:36>>  : vendor id payload
>> 10/06/23 09:38:36 ii : local supports DPDv1

>> 10/06/23 09:38:37<<  : vendor id payload
>> 10/06/23 09:38:37 ii : peer supports DPDv1

MG> The client attempts to send five DPD requests ...

>> 10/06/23 09:38:53 ii : sending peer DPDV1-R-U-THERE notification
>> 10/06/23 09:38:53 ii : - 192.168.0.25:4500 ->  195.162.66.178:4500
>> 10/06/23 09:38:53 ii : - isakmp spi = 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:38:53 ii : - data size 4
>> 10/06/23 09:38:53>>  : hash payload
>> 10/06/23 09:38:53>>  : notification payload
>> 10/06/23 09:38:53 == : new informational hash ( 16 bytes )
>> 10/06/23 09:38:53 == : new informational iv ( 16 bytes )
>> 10/06/23 09:38:53>= : cookies 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:38:53>= : message 648b8432
>> 10/06/23 09:38:53>= : encrypt iv ( 16 bytes )
>> 10/06/23 09:38:53 == : encrypt packet ( 80 bytes )
>> 10/06/23 09:38:53 == : stored iv ( 16 bytes )
>> 10/06/23 09:38:53 ->  : send NAT-T:IKE packet 192.168.0.25:4500 ->  195.162.66.178:4500 ( 124 bytes )
>> 10/06/23 09:38:53 ii : DPD ARE-YOU-THERE sequence 2ba75998 requested
>> 10/06/23 09:38:53 DB : phase1 found
>> 10/06/23 09:39:08 ii : next tunnel DPD retry in 4 secs for peer 195.162.66.178:4500

>> 10/06/23 09:39:08 ii : sending peer DPDV1-R-U-THERE notification
>> 10/06/23 09:39:08 ii : - 192.168.0.25:4500 ->  195.162.66.178:4500
>> 10/06/23 09:39:08 ii : - isakmp spi = 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:39:08 ii : - data size 4
>> 10/06/23 09:39:08>>  : hash payload
>> 10/06/23 09:39:08>>  : notification payload
>> 10/06/23 09:39:08 == : new informational hash ( 16 bytes )
>> 10/06/23 09:39:08 == : new informational iv ( 16 bytes )
>> 10/06/23 09:39:08>= : cookies 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:39:08>= : message 5a8e4cb4
>> 10/06/23 09:39:08>= : encrypt iv ( 16 bytes )
>> 10/06/23 09:39:08 == : encrypt packet ( 80 bytes )
>> 10/06/23 09:39:08 == : stored iv ( 16 bytes )
>> 10/06/23 09:39:08 ->  : send NAT-T:IKE packet 192.168.0.25:4500 ->  195.162.66.178:4500 ( 124 bytes )
>> 10/06/23 09:39:08 ii : DPD ARE-YOU-THERE sequence 2ba75999 requested
>> 10/06/23 09:39:12 DB : phase1 found
>> 10/06/23 09:39:12 ii : next tunnel DPD retry in 3 secs for peer 195.162.66.178:4500

>> 10/06/23 09:39:12 ii : sending peer DPDV1-R-U-THERE notification
>> 10/06/23 09:39:12 ii : - 192.168.0.25:4500 ->  195.162.66.178:4500
>> 10/06/23 09:39:12 ii : - isakmp spi = 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:39:12 ii : - data size 4
>> 10/06/23 09:39:12>>  : hash payload
>> 10/06/23 09:39:12>>  : notification payload
>> 10/06/23 09:39:12 == : new informational hash ( 16 bytes )
>> 10/06/23 09:39:12 == : new informational iv ( 16 bytes )
>> 10/06/23 09:39:12>= : cookies 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:39:12>= : message c3574b54
>> 10/06/23 09:39:12>= : encrypt iv ( 16 bytes )
>> 10/06/23 09:39:12 == : encrypt packet ( 80 bytes )
>> 10/06/23 09:39:12 == : stored iv ( 16 bytes )
>> 10/06/23 09:39:12 ->  : send NAT-T:IKE packet 192.168.0.25:4500 ->  195.162.66.178:4500 ( 124 bytes )
>> 10/06/23 09:39:12 ii : DPD ARE-YOU-THERE sequence 2ba7599a requested
>> 10/06/23 09:39:15 DB : phase1 found
>> 10/06/23 09:39:15 ii : next tunnel DPD retry in 2 secs for peer 195.162.66.178:4500

>> 10/06/23 09:39:15 ii : sending peer DPDV1-R-U-THERE notification
>> 10/06/23 09:39:15 ii : - 192.168.0.25:4500 ->  195.162.66.178:4500
>> 10/06/23 09:39:15 ii : - isakmp spi = 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:39:15 ii : - data size 4
>> 10/06/23 09:39:15>>  : hash payload
>> 10/06/23 09:39:15>>  : notification payload
>> 10/06/23 09:39:15 == : new informational hash ( 16 bytes )
>> 10/06/23 09:39:15 == : new informational iv ( 16 bytes )
>> 10/06/23 09:39:15>= : cookies 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:39:15>= : message 1b3f9b1a
>> 10/06/23 09:39:15>= : encrypt iv ( 16 bytes )
>> 10/06/23 09:39:15 == : encrypt packet ( 80 bytes )
>> 10/06/23 09:39:15 == : stored iv ( 16 bytes )
>> 10/06/23 09:39:15 ->  : send NAT-T:IKE packet 192.168.0.25:4500 ->  195.162.66.178:4500 ( 124 bytes )
>> 10/06/23 09:39:15 ii : DPD ARE-YOU-THERE sequence 2ba7599b requested
>> 10/06/23 09:39:17 DB : phase1 found
>> 10/06/23 09:39:17 ii : next tunnel DPD retry in 1 secs for peer 195.162.66.178:4500

>> 10/06/23 09:39:17 ii : sending peer DPDV1-R-U-THERE notification
>> 10/06/23 09:39:17 ii : - 192.168.0.25:4500 ->  195.162.66.178:4500
>> 10/06/23 09:39:17 ii : - isakmp spi = 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:39:17 ii : - data size 4
>> 10/06/23 09:39:17>>  : hash payload
>> 10/06/23 09:39:17>>  : notification payload
>> 10/06/23 09:39:17 == : new informational hash ( 16 bytes )
>> 10/06/23 09:39:17 == : new informational iv ( 16 bytes )
>> 10/06/23 09:39:17>= : cookies 9ec59efe15fd0ef5:6e150e79e6cbee48
>> 10/06/23 09:39:17>= : message 6abc4117
>> 10/06/23 09:39:17>= : encrypt iv ( 16 bytes )
>> 10/06/23 09:39:17 == : encrypt packet ( 80 bytes )
>> 10/06/23 09:39:17 == : stored iv ( 16 bytes )
>> 10/06/23 09:39:17 ->  : send NAT-T:IKE packet 192.168.0.25:4500 ->  195.162.66.178:4500 ( 124 bytes )
>> 10/06/23 09:39:17 ii : DPD ARE-YOU-THERE sequence 2ba7599c requested

MG> And then times out because it hasn't received a response ...

>> 10/06/23 09:39:18 !! : tunnel DPD timeout for peer 195.162.66.178:4500
>>

MG> I don't see a single DPD message logged in the strongswan logs ...

>> =========
>> pluto[1372]: packet from 195.162.66.179:500: received Vendor ID payload [XAUTH]
>> pluto[1372]: packet from 195.162.66.179:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
>> pluto[1372]: packet from 195.162.66.179:500: ignoring Vendor ID payload [16f6ca16e4a4066d83821a0f0aeaa862]
>> pluto[1372]: packet from 195.162.66.179:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]
>> pluto[1372]: packet from 195.162.66.179:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03]
>> pluto[1372]: packet from 195.162.66.179:500: received Vendor ID payload [RFC 3947]
>> pluto[1372]: packet from 195.162.66.179:500: ignoring Vendor ID payload [FRAGMENTATION 80000000]
>> pluto[1372]: packet from 195.162.66.179:500: received Vendor ID payload [Dead Peer Detection]
>> pluto[1372]: packet from 195.162.66.179:500: ignoring Vendor ID payload [f14b94b7bff1fef02773b8c49feded26]
>> pluto[1372]: packet from 195.162.66.179:500: ignoring Vendor ID payload [166f932d55eb64d8e4df4fd37e2313f0d0fd8451]
>> pluto[1372]: packet from 195.162.66.179:500: ignoring Vendor ID payload [8404adf9cda05760b2ca292e4bff537b]
>> pluto[1372]: packet from 195.162.66.179:500: ignoring Vendor ID payload [Cisco-Unity]
>> pluto[1372]: "rw2"[22] 195.162.66.179 #44: responding to Main Mode from unknown peer 195.162.66.179
>> pluto[1372]: "rw2"[22] 195.162.66.179 #44: NAT-Traversal: Result using RFC 3947: peer is NATed
>> pluto[1372]: "rw2"[22] 195.162.66.179 #44: Peer ID is ID_DER_ASN1_DN: 'C=RU, ST=Tomsk region, O=organ, OU=Central Office, CN=rw2, E=rw2 at openorgan.ru'
>> pluto[1372]: "rw2"[22] 195.162.66.179 #44: crl not found
>> pluto[1372]: "rw2"[22] 195.162.66.179 #44: certificate status unknown
>> pluto[1372]: "rw2"[22] 195.162.66.179 #44: we have a cert and are sending it upon request
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: sent MR3, ISAKMP SA established
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: sending XAUTH request
>> pluto[1372]: packet from 195.162.66.179:4500: Informational Exchange is for an unknown (expired?) SA
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: parsing XAUTH reply
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: extended authentication was successful
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: sending XAUTH status:
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: parsing XAUTH ack
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: received XAUTH ack, established
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: assigning virtual IP source address 192.168.255.2
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: sending ModeCfg reply
>> pluto[1372]: "rw2"[22] 195.162.66.179:4500 #44: sent ModeCfg reply, established
>> =========
>>

MG> Did you enable DPD support for this connection? Can you obtain a higher 
MG> level of debug output from strongswan? Preferably something that says 
MG> why the DPD packets are not being processed.

MG> -Matthew