IPsec debugging

Post by Frank Wille
I would like to know if there are any more options to debug an IPsec
connection. I'm establishing the connection as a client using a CA
certificate and a client certificate and key. This is phase 1
"authentication method" "rsasig", as far as I know?
I have IPSEC_DEBUG in the kernel. I'm using "log debug2" in racoon.conf and

I have 100% absorbed the details of what you are doing. But I have a
few suggestions in addition to what you have done, all to be on both sides:

run "route -n monitor" and save it to a file. Look for failed route
lookups that seem relevant.

run "setkey -x" and save that. This will probably just confirm that
racoon is doing what it said.

run 'tcpdump -s1500 -wFILE', and then go back and look at the 5
seconds very carefully.

run 'setkey -D' and 'setkey -D -P' after negotiation and before the
DPD failure. Check that the SAs match.

The big question in my mind is whether the DPD is wrong or if the probe
packet is actually being dropped because something else is wrong.

Post by Frank Wille
Feb 26 12:16:23 powerbook racoon: ERROR: /etc/racoon/racoon.conf:70: "}" no
compression algorithm at loc='ANONYMOUS', rmt='ANONYMOUS', peer='ANY', id=0
Feb 26 12:16:23 powerbook racoon: ERROR: fatal parse failure (1 errors)

This is fatal, it says. How is racoon starting? Or did you fix it and
not trim the logs?

Post by Frank Wille
Feb 26 12:26:08 powerbook racoon: INFO: ISAKMP-SA established
192.168.1.5[4500]-1.2.3.4[4500] spi:b093a6d4667c8c59:420b8c66dd98416b
Feb 26 12:27:13 powerbook racoon: [1.2.3.4] INFO: DPD: remote (ISAKMP-SA
spi=b093a6d4667c8c59:420b8c66dd98416b) seems to be dead.
Feb 26 12:27:13 powerbook racoon: INFO: purging ISAKMP-SA
spi=b093a6d4667c8c59:420b8c66dd98416b.
Feb 26 12:27:13 powerbook racoon: INFO: purged ISAKMP-SA
spi=b093a6d4667c8c59:420b8c66dd98416b.
Feb 26 12:27:13 powerbook racoon: INFO: ISAKMP-SA deleted
192.168.1.5[4500]-1.2.3.4[4500] spi:b093a6d4667c8c59:420b8c66dd98416b
192.168.1.5[4500]->1.2.3.4[4500]

(Your log lines are wrapped in mail; it would be nice to not munge
them.)

This shows that the ISAKMP SA was created, but no phase 2 SA. So no
real need to look at setkey. But the big question is what the logs on
the other side show and if there is a 4500/4500 probe packet.

Post by Frank Wille
The connection always dies 5 seconds after being established, because DPD
thinks the peer is dead. tcpdump shows that the peer's UDP Port 4500
suddeny became unreachable, although it worked before.

What did tcpdump actually show? (data, not conclusion) Did you run
tcpdump on the remote system? Are you sure your nat stuff in the middle
is working (really, that is rhetorical; you can be sure of nothing, so I
mean did you observe packets in both places....)?

Christos Zoulas

2016-02-29 02:01:55 UTC

Post by Frank Wille
Hi,
I would like to know if there are any more options to debug an IPsec
connection. I'm establishing the connection as a client using a CA
certificate and a client certificate and key. This is phase 1
"authentication method" "rsasig", as far as I know?
I have IPSEC_DEBUG in the kernel. I'm using "log debug2" in racoon.conf and

Have you gotten the same configuration to work with a shared secret?

christos

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

Frank Wille

2016-02-28 13:22:56 UTC

Post by Greg Troxel
I have 100% absorbed the details of what you are doing. But I have a

On both sides is not possible, because the remote side is a Lancom 1781EF
router. I can provide traces from its VPN logs, though.

In case I didn't mention it: I'm trying to set up a so called "road-warrior"
configuration. I have a client which uses IPSEC with NAT-T to connect to
the Lancom router. I also hope to receive my ip-address and gateway via IKE
Config Mode, so I become part of my office's LAN.

Post by Greg Troxel
run "route -n monitor" and save it to a file. Look for failed route
lookups that seem relevant.

This produces an empty file. There is never anything in it.

Post by Greg Troxel
run "setkey -x" and save that. This will probably just confirm that
racoon is doing what it said.

There is not much in it either. But I have seen some more output in previous
test runs. You find it attached.

To be honest, I don't know if I need to run any setkey commands at all, when
doing a completely certificate-based connection set up. In racoon.conf I
have currently a "test.sh" script for phase1-up and -down, which does
nothing besides echoing $LOCAL_ADDR, $REMOTE_ADDR, etc., although I never
see that anywhere.

Post by Greg Troxel
run 'tcpdump -s1500 -wFILE', and then go back and look at the 5
seconds very carefully.

I attached the ASCII version of it, replacing all remote gateway addresses
with 1.2.3.4. Will send you the pcap by private email.

I also entered the Lancom console and logged the VPN status with "trace +
vpn-status". It might provide some useful information (see attached). It
shows that phase-1 looks good. The Lancom sends one keep-alive and receives
an ACK. Then it receives a keep-alive and sends an ACK.

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.

Post by Greg Troxel
run 'setkey -D' and 'setkey -D -P' after negotiation and before the
DPD failure. Check that the SAs match.

I never saw anything else than
No SAD entries.
No SPD entries.
at any point of time.

Post by Greg Troxel
The big question in my mind is whether the DPD is wrong

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

Post by Greg Troxel
or if the probe
packet is actually being dropped because something else is wrong.

Who knows? There is not much information on both sides.

Post by Frank Wille
Feb 26 12:16:23 powerbook racoon: ERROR: fatal parse failure (1 errors)

This is fatal, it says. How is racoon starting? Or did you fix it and
not trim the logs?

Indeed, sorry. There were some lines from previous tests in it. I tried to
remove the "compression algorithm" statement for phase-2, which racoon
didn't like.

Post by Greg Troxel
(Your log lines are wrapped in mail; it would be nice to not munge
them.)

Attached them now. Hope that works.

Post by Greg Troxel
This shows that the ISAKMP SA was created, but no phase 2 SA.

This is also my impression at the moment. Something goes wrong in phase 2?

Hmm, but why is the phase1-up script not called?

Post by Greg Troxel
So no
real need to look at setkey. But the big question is what the logs on
the other side show and if there is a 4500/4500 probe packet.

Refer to the attached Lancom.trace. According to tcpdump 4500/4500
communication seems to happen at least twice, before the Lancom terminates
the connection.

Post by Greg Troxel
What did tcpdump actually show? (data, not conclusion)

The attached tcpdump.txt contains everything which happened.

Post by Greg Troxel
Are you sure your nat stuff in the middle is working

Not really. How can I check that, besides seeing UDP packages exchanged on
port 4500 from both sides?

Thanks for looking into the problem! It would really be nice to get IPSec
with NetBSD going, as my company intends to use NetBSD (rdesktop via VPN)
on all their notebooks!

--
Frank Wille

Greg Troxel

2016-03-01 01:09:08 UTC

Post by Greg Troxel
run "route -n monitor" and save it to a file. Look for failed route
lookups that seem relevant.

This produces an empty file. There is never anything in it.

That means that there are probably no redirect routes added due to
unreachables. That's not surprising, but I always like to check for
trouble that is not expected.

Post by Greg Troxel
run "setkey -x" and save that. This will probably just confirm that
racoon is doing what it said.

There is not much in it either. But I have seen some more output in previous
test runs. You find it attached.

That's probably because the problem is that the phase1 is getting torn
down and phase2 is never really getting set up. phase1 is the SA
between IKE implmeentations, and doesn't show up in the kernel, and
phase2 are the IPsec SAs.

Post by Frank Wille
To be honest, I don't know if I need to run any setkey commands at all, when
doing a completely certificate-based connection set up. In racoon.conf I
have currently a "test.sh" script for phase1-up and -down, which does
nothing besides echoing $LOCAL_ADDR, $REMOTE_ADDR, etc., although I never
see that anywhere.

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

Post by Greg Troxel
run 'tcpdump -s1500 -wFILE', and then go back and look at the 5
seconds very carefully.

I attached the ASCII version of it, replacing all remote gateway addresses
with 1.2.3.4. Will send you the pcap by private email.

Thanks for the pcap; it seems the same. The real point is that the
remote side started sending unreachables, and...

Post by Frank Wille
I also entered the Lancom console and logged the VPN status with "trace +
vpn-status". It might provide some useful information (see attached). It
shows that phase-1 looks good. The Lancom sends one keep-alive and receives
an ACK. Then it receives a keep-alive and sends an ACK.
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.

So we really need to get the lancom side to explain *why* it is deciding
there is a timeout and what it thinks should have happened.

Post by Greg Troxel
run 'setkey -D' and 'setkey -D -P' after negotiation and before the
DPD failure. Check that the SAs match.

I never saw anything else than
No SAD entries.
No SPD entries.
at any point of time.

So I really wonder how the traffic will get forced into the tunnel once
set up. Perhaps the default is "use" these days. I have always set up
SPD entries.

Post by Greg Troxel
The big question in my mind is whether the DPD is wrong

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. I would hook up
a hub to near the lancom and run tcpdump on that to see if the
keepalives are arriving and if there are responses. And read the
protocol specs to see how this is supposed to work.

Post by Greg Troxel
This shows that the ISAKMP SA was created, but no phase 2 SA.

This is also my impression at the moment. Something goes wrong in phase 2?
Hmm, but why is the phase1-up script not called?

This feels like a weak clue that phase1 is not really finished.

Post by Frank Wille
Not really. How can I check that, besides seeing UDP packages exchanged on
port 4500 from both sides?

You run tcpdump on both sides and see if the traffic is consistent.

Post by Frank Wille
Thanks for looking into the problem! It would really be nice to get IPSec
with NetBSD going, as my company intends to use NetBSD (rdesktop via VPN)
on all their notebooks!

Wow!

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

I think the biggest clue comes from interleaving the packets and messages:

Feb 29 12:31:52 powerbook racoon: INFO: ISAKMP-SA established 192.168.1.5[4500]-1.2.3.4[4500] spi:4f5e1f08e12bd21c:2e8dc875b4e07c26

[VPN-Status] 2016/02/29 12:31:52,431
IKE info: NOTIFY received of type INITIAL_CONTACT for peer VPNCLIENT15EF90
12:31:52.467385 IP powerbook-wlan.owl.de.ipsec-nat-t > 1.2.3.4.ipsec-nat-t: NONESP-encap: isakmp: phase 2/others I inf[E]

[VPN-Status] 2016/02/29 12:31:52,441
IKE info: ISAKMP_NOTIFY_DPD_R_U_THERE sent for Phase-1 SA to peer VPNCLIENT15EF90, sequence nr 0x56e60865
12:31:52.539912 IP 1.2.3.4.ipsec-nat-t > powerbook-wlan.owl.de.ipsec-nat-t: NONESP-encap: isakmp: phase 2/others R inf[E]

[VPN-Status] 2016/02/29 12:31:52,530
IKE info: NOTIFY received of type ISAKMP_NOTIFY_DPD_R_U_THERE_ACK for peer VPNCLIENT15EF90 Seq-Nr 0x56e60865, expected 0x56e60865
12:31:52.570866 IP powerbook-wlan.owl.de.ipsec-nat-t > 1.2.3.4.ipsec-nat-t: NONESP-encap: isakmp: phase 2/others I inf[E]

[VPN-Status] 2016/02/29 12:32:12,430
IKE info: NOTIFY received of type ISAKMP_NOTIFY_DPD_R_U_THERE for peer VPNCLIENT15EF90 Seq-Nr 0xea7, expected 0xea7
12:32:12.486257 IP powerbook-wlan.owl.de.ipsec-nat-t > 1.2.3.4.ipsec-nat-t: NONESP-encap: isakmp: phase 2/others I inf[E]

[VPN-Status] 2016/02/29 12:32:12,433
IKE info: ISAKMP_NOTIFY_DPD_R_U_THERE_ACK sent for Phase-1 SA to peer VPNCLIENT15EF90, sequence nr 0xea7
12:32:12.533086 IP 1.2.3.4.ipsec-nat-t > powerbook-wlan.owl.de.ipsec-nat-t: NONESP-encap: isakmp: phase 2/others R inf[E]

[these seem to result in no log entries]
12:32:27.793879 IP powerbook-wlan.owl.de.ipsec-nat-t > 1.2.3.4.ipsec-nat-t: isakmp-nat-keep-alive

[VPN-Status] 2016/02/29 12:32:22,284
VPN: connection for VPNCLIENT15EF90 (91.56.236.148) timed out: no response

Feb 29 12:32:57 powerbook racoon: [1.2.3.4] INFO: DPD: remote (ISAKMP-SA spi=4f5e1f08e12bd21c:2e8dc875b4e07c26) seems to be dead.
Feb 29 12:32:57 powerbook racoon: INFO: purging ISAKMP-SA spi=4f5e1f08e12bd21c:2e8dc875b4e07c26.
Feb 29 12:32:57 powerbook racoon: INFO: purged ISAKMP-SA spi=4f5e1f08e12bd21c:2e8dc875b4e07c26.
Feb 29 12:32:57 powerbook racoon: INFO: ISAKMP-SA deleted 192.168.1.5[4500]-1.2.3.4[4500] spi:4f5e1f08e12bd21c:2e8dc875b4e07c26
Feb 29 12:32:57 powerbook racoon: INFO: KA remove: 192.168.1.5[4500]->1.2.3.4[4500]

Note that the ISAKMP_NOTIFY_DPD_R_U_THERE was sent and rceeived. Then
it was received and send, and the timeout is 10s following the received.
I don't follow this; it seems like there was no non-response to the DPD
messages at the server, 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. But you will need to get more information out of the server,
which I realize may not be doable, or from the client.

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.

So the two things to run down are:

why isn't the client trying to negotiate phase2

why is the server declaring a timeout

Frank Wille

2016-03-01 17:32:30 UTC

Post by Greg Troxel
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

Post by Frank Wille
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.

Post by Frank Wille
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).

Post by Frank Wille
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.

Post by Greg Troxel
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.

Post by Greg Troxel
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.

Post by Greg Troxel
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

Post by Greg Troxel
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.

Post by Greg Troxel
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

Frank Wille

2016-03-02 17:22:55 UTC

Hi,

I found out how to enable debugging in racoon. It doesn't work when racoon
is doing its output into syslog (for what reason ever)!

When I start racoon manually and use the "-l logfile" option I get (a lot
of) "DEBUG:" lines in it.

So I repeated the test with the Lancom router, which shows that racoon does
not care at all about mode_cfg. It isn't mentioned anywhere in the logs. No
error, no warning. Nothing. It's completely ignored.

I hesitate to post the full debug log here, because it contains hex dumps
and clear text of certificates. Attached it the part when phase 1 is
complete (at least for racoon - mode_cfg is missing).

Nothing happens after printing "ISAKMP-SA established" for 17 seconds. Then
server and client start playing DPD ping-pong until the Lancom terminates
the connection after another 13 seconds (always 30 seconds total).

No IKE mode config. No Phase 2 negotiation. And no hint why. *Sigh*

The same happens when connecting to a NetBSD racoon server (see other
thread). Either there is a bug with "rsasig" / "mode_cfg" or I'm missing
something - which is quite likely as I still don't understand a lot from
IPSec. Do I need to set up some policies or setkeys or whatever beforehand?

Thanks in advance. :)

--
Frank Wille

Frank Wille

2016-02-28 13:46:02 UTC

Post by Christos Zoulas
Have you gotten the same configuration to work with a shared secret?

Unfortunately I cannot change the configuration of the Lancom router in my
office, as the VPN works fine and is needed for a dozen of Windows
notebooks.

--
Frank Wille

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

Thor Lancelot Simon

2016-02-29 23:51:53 UTC

Post by Christos Zoulas
Have you gotten the same configuration to work with a shared secret?

Unfortunately I cannot change the configuration of the Lancom router in my
office, as the VPN works fine and is needed for a dozen of Windows
notebooks.

Windows notebooks you say. Are you *sure* it is not expecting a proposal
for transport mode IPsec with L2TP inside, rather than tunnel mode IPsec?

That would explain why there were no matching Phase 2 proposals, and I wouldn't
be terribly surprised, in that case, if your Phase 1 up script weren't called.

Thor

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

Christos Zoulas

2016-02-29 23:56:32 UTC

On Feb 29, 6:51pm, ***@panix.com (Thor Lancelot Simon) wrote:
-- Subject: Re: IPsec debugging

| On Sun, Feb 28, 2016 at 02:46:02PM +0100, Frank Wille wrote:
| > Christos Zoulas wrote:
| >
| > > Have you gotten the same configuration to work with a shared secret?
| >
| > Unfortunately I cannot change the configuration of the Lancom router in my
| > office, as the VPN works fine and is needed for a dozen of Windows
| > notebooks.
|
| Windows notebooks you say. Are you *sure* it is not expecting a proposal
| for transport mode IPsec with L2TP inside, rather than tunnel mode IPsec?
|
| That would explain why there were no matching Phase 2 proposals, and I wouldn't
| be terribly surprised, in that case, if your Phase 1 up script weren't called.

If it is L2TP just follow this:

https://wiki.netbsd.org/tutorials/how_to_create_an_l2tp_ipsec_tunnel_between_an_android_or_iphone_or_ios_device_to_netbsd/

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

Frank Wille

2016-03-01 16:40:55 UTC