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

Wed Jun 23 10:57:09 CDT 2010

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.
>

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

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

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
>

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
> =========
>

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

-Matthew