Re: Simple IPSEC client with certificate - phase 1 time out

[Brett Lymn <blymn%internode.on.net@localhost>]

On Tue, Mar 01, 2016 at 01:11:08PM +0100, Frank Wille wrote:
> Brett Lymn wrote:
> 
> > OK, does phase 2 actually complete?
> 
> I doubt that. Currently I'm not even sure whether phase 1 completes, because
> the phase1-up script is never called. On the other hand the phase1-down
> script is called, as soon as the connection is terminated.
> 

Well, it does seem to get close.... see below.

> 
> > What does a "setkey -aD" output?
> 
> No SAD entries. And no SPD entries either.
> I guess they would be added by the phase1-up script...?
> 

In the logs you can see the SAD entries get created but they get removed
when the connection gets torn down.

> 
> > Have you tried a tcpdump to see what is going on at the network level?
> 
> Yes, always. I have attached the tcpdump from my client and the vpn-status
> log of the Lancom-router (the VPN "server").
> 

That's helpful.  I normally use -s 0 -x with my tcpdump so I can see
what is in the packets but it may not be very useful here.

> 
> > You should expect encrypted packets, if you are seeing stuff in the
> > clear then check your routing and ensure the packets are properly
> > routed to the vpn tunnel end point.
> 
> This is something to worry about as soon as both phases have been completed,
> which definitely is not the case. ;)
> 

Well, there is a chance that the negotiation was failing due to packets
not going where you expect.  That doesn't appear to be happening but
checking the simple things can't hurt and can save a lot of grief :)

> 
> > It has been a long while since I played with this but I seem to recall
> > that you do get a log of what is being proposed by both sides.
> 
> The proposal is accepted (refer to the Lancom VPN log).
> 

Yes and by NetBSD too, you can actually see the phase 1 has completed in
the racoon logs but then the SA gets removed.

> Looking at the tcpdump I wonder why the NetBSD client says it is exchanging
> "isakmp: phase 2" packets, while the Lancom still calls these isakmp
> notifies "Phase-1 SA"?
> 

As Greg said, this is probably just terminology, I wouldn't get hung up
on that too much.


OK, lets have a bit of a look at the logs and see what is going on...

> Mar  1 11:52:07 powerbook racoon: [1.2.3.4] INFO: received INITIAL-CONTACT 
> Mar  1 11:52:07 powerbook racoon: INFO: ISAKMP-SA established 192.168.1.5[4500]-1.2.3.4[4500] spi:4da2f5f910bbdf44:444ae08dd7de45a5 

This is good - we have a security association here, note the SPI numbers
here, they will be useful later.

> Mar  1 11:53:12 powerbook racoon: [1.2.3.4] INFO: DPD: remote (ISAKMP-SA spi=4da2f5f910bbdf44:444ae08dd7de45a5) seems to be dead. 
> Mar  1 11:53:12 powerbook racoon: INFO: purging ISAKMP-SA spi=4da2f5f910bbdf44:444ae08dd7de45a5. 
> Mar  1 11:53:12 powerbook racoon: INFO: purged ISAKMP-SA spi=4da2f5f910bbdf44:444ae08dd7de45a5. 
> Mar  1 11:53:12 powerbook racoon: INFO: ISAKMP-SA deleted 192.168.1.5[4500]-1.2.3.4[4500] spi:4da2f5f910bbdf44:444ae08dd7de45a5 
> Mar  1 11:53:12 powerbook racoon: INFO: KA remove: 192.168.1.5[4500]->1.2.3.4[4500] 

Then the SA gets torn down.

> 11:52:06.441891 IP 192.168.1.5.500 > 1.2.3.4.500: isakmp: phase 1 I ident

Nothing really out of place in the tcpdump...

the log from the other side is interesting:

> 
> [VPN-Status] 2016/03/01 11:52:07,096
> IKE info: exchange_finalize: assuming identified for road-warrior with cert, id=VPNCLIENT15EF90, RemoteGW=91.56.237.127
> 
> 
> [VPN-Status] 2016/03/01 11:52:07,121
> IKE info: Phase-1 [responder] for peer VPNCLIENT15EF90 initiator id CN=VPNCLIENT15,O=WPS,C=DE,L=HERFORD,ST=NRW,OU=IT,postalCode=32052, responder id CN=ZENTRALE,O=WPS,C=DE,L=HERFORD,ST=NRW,OU=IT,postalCode=32052
> IKE info: initiator cookie: 0x4da2f5f910bbdf44, responder cookie: 0x444ae08dd7de45a5
> IKE info: NAT-T enabled in mode rfc, we are not behind a nat, the remote side is  behind a nat
> IKE info: SA ISAKMP for peer VPNCLIENT15EF90 encryption aes-cbc authentication MD5
> IKE info: life time ( 28800 sec/ 0 kb) DPD 0 sec
> 

This is good - we have a phase 1 done here, note the initiator and
responder cookies match the SPI numbers from the NetBSD side.  Looking
good at this point.

> 
> [VPN-Status] 2016/03/01 11:52:23,541
> IKE info: ISAKMP_NOTIFY_DPD_R_U_THERE sent for Phase-1 SA to peer VPNCLIENT15EF90, sequence nr 0x7a8b3f4b
> 
> 
> [VPN-Status] 2016/03/01 11:52:23,614
> IKE info: NOTIFY received of type ISAKMP_NOTIFY_DPD_R_U_THERE_ACK for peer VPNCLIENT15EF90 Seq-Nr 0x7a8b3f4b, expected 0x7a8b3f4b
> 

This is good, we see a query and response

> 
> [VPN-Status] 2016/03/01 11:52:27,223
> IKE info: NOTIFY received of type ISAKMP_NOTIFY_DPD_R_U_THERE for peer VPNCLIENT15EF90 Seq-Nr 0xe8, expected 0xe8
> 
> 
> [VPN-Status] 2016/03/01 11:52:27,224
> IKE info: ISAKMP_NOTIFY_DPD_R_U_THERE_ACK sent for Phase-1 SA to peer VPNCLIENT15EF90, sequence nr 0xe8
> 

OK and here is where things fall apart.  The client sends an "are you
there" request and vpn server sends a reply but it seems like the packet
did not get through and then things go bad from there...

> 
> [VPN-Status] 2016/03/01 11:52:37,096
> VPN: connection for VPNCLIENT15EF90 (91.56.237.127) timed out: no response
> 
> [VPN-Status] 2016/03/01 11:52:37,096
> VPN: Error: IFC-R-Connection-timeout-dynamic (0x1205) for VPNCLIENT15EF90 (91.56.237.127)
> 
> [VPN-Status] 2016/03/01 11:52:37,096
> vpn-maps[38], remote: VPNCLIENT15EF90
> 
> [VPN-Status] 2016/03/01 11:52:37,096
> VPN: installing ruleset for VPNCLIENT15EF90 (91.56.237.127)
> 
> [VPN-Status] 2016/03/01 11:52:37,096
> VPN: WAN state changed to WanDisconnect for VPNCLIENT15EF90 (91.56.237.127), called by: 009c5cb8
> 
> [VPN-Status] 2016/03/01 11:52:37,097
> IKE info: Phase-1 SA removed: peer VPNCLIENT15EF90 rule VPNCLIENT15EF90 removed
> 
> 
> [VPN-Status] 2016/03/01 11:52:37,102
> VPN: WAN state changed to WanIdle for VPNCLIENT15EF90 (91.56.237.127), called by: 009c5cb8
> 
> [VPN-Status] 2016/03/01 11:52:37,103
> removeAllDeletedRoutes, called by: 009bdd24
> 
> [VPN-Status] 2016/03/01 11:52:37,108
> VPN: VPNCLIENT15EF90 (91.56.237.127)  disconnected
> 

So the SA is torn down here on the vpn server side because there was no
response, probably because the NetBSD client is still waiting for an ack
to the are you there.

> 
> [VPN-Status] 2016/03/01 11:52:47,318
> IKE log: 115247.318276 Default message_drop_invalid_cookies: invalid cookie(s) 4da2f5f910bbdf44 444ae08dd7de45a5
> 
> 
> [VPN-Status] 2016/03/01 11:52:47,318
> IKE log: 115247.318468 Default dropped message from 91.56.237.127 port 2500 due to notification type INVALID_COOKIE
> 
> 
> [VPN-Status] 2016/03/01 11:52:47,318
> IKE info: Informational messages are unidirectional and therefore are not answered! (cookies 4D A2 F5 F9 10 BB DF 44 44 4A E0 8D D7 DE 45 A5)
> 

The rest of this is the NetBSD client still trying to talk at the vpn
server after the SA has been torn down.  Note the match of the cookie
and the SPI, this is how we can tell what is happening.


OK so what we can see here is that there seems to be some packet loss
that is causing the NetBSD client to wait for an answer but during that
time the vpn server decides nothing is happening and tears the
connection down.  So, some things to consider:

0) How reliable is the internet connection on the client side?  It seems
these days there is an assumption the connection is fast.  I have had an
instance where I tried to test a vpn connection using a dial up modem,
it failed miserably, timing out - the very same configuration worked
perfectly from a public wireless network.

1) Since one side is doing NAT-T, do you have port forwarding on the
router so that the IKE packets (udp 500 and 4500) are forwarded back to
the vpn client?  Though it seems you must already have this right to get
the phase 1 done...

2) any firewall rules blocking the incoming traffic?  Again, just check
though it doesn't make much sense give you have managed to get so far
along.

3) some firewalls/routers don't like large udp packets, there are some
racoon settings for fragmenting packets - perhaps you need those.
Though my experience with this is that the tunnel comes up and a ping
will work but trying something heavier like a remote display or login
will mysteriously fail.

-- 
Brett Lymn
Let go, or be dragged - Zen proverb.