Re: IPsec debugging

To: Greg Troxel <gdt%ir.bbn.com@localhost>
Subject: Re: IPsec debugging
From: Frank Wille <frank%phoenix.owl.de@localhost>
Date: Tue, 01 Mar 2016 18:32:30 +0100

Greg Troxel wrote:

> Generally I have had to install policies (setkey -P) to require IPsec,
> in order to cause acquire messages to go to racoon.

I still lack a lot of knowledge about IPsec, but when I run a roadwarrior
client with mode-config, I would think that I cannot install any policies
before I got my VPN-internal IP address assigment from the server?

In my special case I have a notebook in my WLAN with 192.168.1.5. The
VPN-LAN to connect into will be 192.168.0.0/24 via the public IP 1.2.3.4.

So I tried running without mode_cfg and using an /etc/ipsec.conf like this
(which is probably wrong):

#!/sbin/setkey -f

flush;
spdflush;

spdadd 192.168.0.77 0.0.0.0 any -P out ipsec
esp/tunnel/192.168.1.5-212.62.95.76/require;
spdadd 0.0.0.0 192.168.0.77 any -P in ipsec
esp/tunnel/212.62.95.76-192.168.1.5/require;

But after that I have got SPD-entries in the database, of course, although
racoon says:
unsupported PF_KEY message X_PROMISC
unsupported PF_KEY message REGISTER

>> But 10 seconds later, at 12:32:22, it prints "time out" and
>> "IFC-R-Connection-timeout-dynamic", without any other reason...
>>
>> This seems to be within phase-2. From now on "phase 2/others I inf[E]"
>> is no longer answered by the Lancom, although it happened twice
>> before.
>
> It does, but the remote side is apparently tearing down the phase1 SA,
> which is why the IKE<>IKE messages on port 4500 started getting
> unreachables.

Indeed, that seems to be the case.

>> Probably not. I verified that both sides have DPD with 20 seconds
>> enabled. I haven't set "natt_keepalive" yet, as I hoped the default
>> value will do...
>
> It is pretty clear that the NAT state is not timing out.  What I don't
> understand is why there is no response to the keepalive.

A test with a working Lancom-VPN-client under Windows showed that there
probably i never a response to the keepalive. I see the same there (see
below).

>> Hmm, but why is the phase1-up script not called?
>
> This feels like a weak clue that phase1 is not really finished.

You are right! I would guess there is a problem with mode-config. The
client doesn't send a mode-config request, so phase1 is not completed
and the phase1-up script not called.

Just DPD seems to be running in the background, which appears as
"phase2/others inf", although phase 2 was not established.

> You should also make sure clocks are synced before doing these tests.
> They seem pretty close but not quite.

Did that now. The Lancom's clock is not very good, so I made it resync with
an
NTP server more often.

> and I wonder if it was failure to
> negotiate a good enough phase 2 that led to the dropping and it's not
> about the DPD at all.

I still don't know what it is, but I think DPD is working. It seems the
Lancom always times out after 30 seconds, no matter what I do.

When I try with "mode_cfg off" I immediately get "connexion established"
from
racoonctl. But the communication doesn't look any different, and the Lancom
still times out after 30 seconds. But the phase1-up script is called now!

According to the Lancom Phase 2 was not completed.

> But you will need to get more information out of
> the server, which I realize may not be doable, or from the client.

The Lancom's vpn-status log is the maximum I can get from there.

I'm still wondering why racoon gives me no debug output. I have seen racoon
logs on the net which include "DEBUG:" lines. I'm only getting "INFO:"
although "log debug2" is set.

I'm compiling the 7.0 release version of racoon now and try to debug it with
gdb and enter traces... :P

> Another idea is that the client isn't trying to negotiate a phase 2.
>  So I wonder if the client thinks the phase1 is not complete.  But the
> message says it is.

Yes. Yes. And yes. :)

With "mode_cfg off" it thinks that phase 1 is complete, but phase 2 is still
incomplete.

> So the two things to run down are:
>
>   why isn't the client trying to negotiate phase2
>
>   why is the server declaring a timeout

Still no idea. But I made a test with a working commercial Lancom Windows
client, using the same certificates and settings (I hope). The tcpdump and
Lancom log is attached for comparison.

It immediately requests an IKE-CFG (config mode), and there is an explicit
Phase 2 done message. All that is missing for the NetBSD client...

-- 
Frank Wille

14:17:36.260114 IP 192.168.0.20.10952 > 1.2.3.4.500: isakmp: phase 1 I ident
14:17:36.306843 IP 1.2.3.4.500 > 192.168.0.20.10952: isakmp: phase 1 R ident
14:17:36.314908 IP 192.168.0.20.10952 > 1.2.3.4.500: isakmp: phase 1 I ident
14:17:36.358582 IP 1.2.3.4.500 > 192.168.0.20.10952: isakmp: phase 1 R ident
14:17:36.555390 IP 192.168.0.20.10954 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 1 I ident[E]
14:17:36.998288 IP 1.2.3.4.4500 > 192.168.0.20.10954: NONESP-encap: isakmp: phase 1 R ident[E]
14:17:37.008849 IP 192.168.0.20.10954 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I #6[E]
14:17:37.055536 IP 1.2.3.4.4500 > 192.168.0.20.10954: NONESP-encap: isakmp: phase 2/others R #6[E]
14:17:37.068085 IP 192.168.0.20.10954 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I oakley-quick[E]
14:17:37.126749 IP 1.2.3.4.4500 > 192.168.0.20.10954: NONESP-encap: isakmp: phase 2/others R oakley-quick[E]
14:17:37.127812 IP 192.168.0.20.10954 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I oakley-quick[E]
14:17:51.868196 IP 192.168.0.20.10954 > 1.2.3.4.4500: isakmp-nat-keep-alive
14:17:56.869256 IP 192.168.0.20.10954 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I inf[E]
14:17:56.912694 IP 1.2.3.4.4500 > 192.168.0.20.10954: NONESP-encap: isakmp: phase 2/others R inf[E]
14:18:06.867197 IP 192.168.0.20.10954 > 1.2.3.4.4500: isakmp-nat-keep-alive

[VPN-Status] 2016/03/01 14:17:38,446
IKE info: The remote server 91.56.237.127:6180 (UDP) peer def-main-peer id <no_id> supports draft-ietf-ipsec-isakmp-xauth
IKE info: The remote peer def-main-peer supports NAT-T in draft mode
IKE info: The remote peer def-main-peer supports NAT-T in draft mode
IKE info: The remote peer def-main-peer supports NAT-T in RFC mode
IKE info: The remote server 91.56.237.127:6180 (UDP) peer def-main-peer id <no_id> negotiated rfc-3706-dead-peer-detection
IKE info: The remote client 91.56.237.127:6180 (UDP) peer def-main-peer id <no_id> is NCP LANCOM Serial Number Protocol 1.0 with serial number 0


[VPN-Status] 2016/03/01 14:17:38,447
IKE info: Phase-1 remote proposal 1 for peer def-main-peer matched with local proposal 1


[VPN-Status] 2016/03/01 14:17:38,760
IKE log: 141738.760114 Default conf_get_list: empty field, ignoring...


[VPN-Status] 2016/03/01 14:17:38,769
IKE info: Phase-1 [responder] got INITIAL-CONTACT from peer VPNCLIENT15EF90 (91.56.237.127)


[VPN-Status] 2016/03/01 14:17:39,115
VPN: WAN state changed to WanSetup for  (0.0.0.0), called by: 009c5f50

[VPN-Status] 2016/03/01 14:17:39,115
VPN: WAN state changed to WanCalled for VPNCLIENT15EF90 (0.0.0.0), called by: 009c5cb8

[VPN-Status] 2016/03/01 14:17:39,115
vpn-maps[36], remote: VPNCLIENT15EF90, nego, connected-by-name

[VPN-Status] 2016/03/01 14:17:39,115
IKE info: exchange_finalize: assuming identified for road-warrior with cert, id=VPNCLIENT15EF90, RemoteGW=91.56.237.127


[VPN-Status] 2016/03/01 14:17:39,134
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: 0xb735c33ed1be41d2, responder cookie: 0xc4e9e33a864fd6c3
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


[VPN-Status] 2016/03/01 14:17:39,136
IKE info: Phase-1 SA Timeout (Hard-Event) for peer VPNCLIENT15EF90 set to 28800 seconds (Responder)


[VPN-Status] 2016/03/01 14:17:39,192
IKE info: IKE-CFG: Received REQUEST message with id 0 from peer VPNCLIENT15EF90
IKE info: IKE-CFG:   Attribute INTERNAL_IP4_ADDRESS     len 0 value (none) received
IKE info: IKE-CFG:   Attribute INTERNAL_IP4_DNS         len 0 value (none) received
IKE info: IKE-CFG:   Attribute INTERNAL_IP4_NBNS        len 0 value (none) received
IKE info: IKE-CFG:   Attribute APPLICATION_VERSION      len 42 value Cisco Systems VPN Client 5.0.03.0560:WinNT received
IKE info: IKE-CFG:   Attribute <Unknown 20002>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28672>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28673>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28674>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28675>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28676>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28678>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28679>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28680>          len 12 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28681>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 20003>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 20004>          len 0 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 28682>          len 5 is private -> ignore
IKE info: IKE-CFG:   Attribute <Unknown 20005>          len 5 is private -> ignore


[VPN-Status] 2016/03/01 14:17:39,193
VPN: set local server addresses for VPNCLIENT15EF90 (91.56.237.127)
   DNS:  192.168.0.251, 0.0.0.0
   NBNS: 0.0.0.0, 0.0.0.0

[VPN-Status] 2016/03/01 14:17:39,193
IKE info: IKE-CFG: Creating REPLY message with id 0 for peer VPNCLIENT15EF90
IKE info: IKE-CFG:   Attribute APPLICATION_VERSION      len 0 skipped
IKE info: IKE-CFG:   Attribute INTERNAL_IP4_NBNS        len 0 skipped
IKE info: IKE-CFG:   Attribute INTERNAL_IP4_DNS         len 4 value 192.168.0.251 added
IKE info: IKE-CFG:   Attribute INTERNAL_IP4_ADDRESS     len 4 value 192.168.0.217 added
IKE info: IKE-CFG: Sending message


[VPN-Status] 2016/03/01 14:17:39,267
IKE info: Phase-2 proposal failed: remote No 1, esp algorithm keylen 128 <-> local No 1, esp algorithm keylen 256,256:256
IKE info: Phase-2 remote proposal 1 for peer VPNCLIENT15EF90 matched with local proposal 2


[VPN-Status] 2016/03/01 14:17:39,312
IKE info: Phase-2 SA Rekeying Timeout (Soft-Event) for peer VPNCLIENT15EF90 set to 25920 seconds (Responder)


[VPN-Status] 2016/03/01 14:17:39,312
IKE info: Phase-2 SA Timeout (Hard-Event) for peer VPNCLIENT15EF90 set to 28800 seconds (Responder)


[VPN-Status] 2016/03/01 14:17:39,312
IKE info: Phase-2 [responder] done with 2 SAS for peer VPNCLIENT15EF90 rule ipsec-DEF-VPN-PEER
IKE info: rule:' ipsec 192.168.0.0/255.255.255.0 <-> 192.168.0.217/255.255.255.255 '
IKE info: SA ESP [0x20afa2d2]  alg AES_CBC keylength 128 +hmac HMAC_MD5 outgoing
IKE info: SA ESP [0x27e63405]  alg AES_CBC keylength 128 +hmac HMAC_MD5 incoming
IKE info: life soft( 25920 sec/0 kb) hard (28800 sec/0 kb)
IKE info: tunnel between src: 212.62.95.76 dst: 91.56.237.127  


[VPN-Status] 2016/03/01 14:17:39,314
VPN: wait for IKE negotiation from VPNCLIENT15EF90 (91.56.237.127)

[VPN-Status] 2016/03/01 14:17:39,314
VPN: WAN state changed to WanProtocol for VPNCLIENT15EF90 (91.56.237.127), called by: 009c5cb8

[VPN-Status] 2016/03/01 14:17:40,314
VPN: VPNCLIENT15EF90 connected

[VPN-Status] 2016/03/01 14:17:40,315
VPN: WAN state changed to WanConnect for VPNCLIENT15EF90 (91.56.237.127), called by: 009c5cb8

[VPN-Status] 2016/03/01 14:17:40,315
vpn-maps[36], remote: VPNCLIENT15EF90, connected, connected-by-name


[VPN-Status] 2016/03/01 14:17:59,054
IKE info: NOTIFY received of type ISAKMP_NOTIFY_DPD_R_U_THERE for peer VPNCLIENT15EF90 Seq-Nr 0x28f7364f, expected 0x28f7364f


[VPN-Status] 2016/03/01 14:17:59,055
IKE info: ISAKMP_NOTIFY_DPD_R_U_THERE_ACK sent for Phase-1 SA to peer VPNCLIENT15EF90, sequence nr 0x28f7364f

References:
- IPsec debugging
  - From: Frank Wille
- Re: IPsec debugging
  - From: Greg Troxel
- Re: IPsec debugging
  - From: Frank Wille
- Re: IPsec debugging
  - From: Greg Troxel

Prev by Date: Re: IPsec debugging
Next by Date: racoon with rsasig and mode_cfg
Previous by Thread: Re: IPsec debugging
Next by Thread: Re: IPsec debugging
Indexes:

Home | Main Index | Thread Index | Old Index