Cryptosystems: Debugging IPSec
Pages: 1, 2, 3

Testing the Tunnel

Whenever I negotiate a tunnel for the first time, I run several tests and either take full advantage of my virtual terminals, or I use /usr/ports/misc/screen if I'm restricted to one terminal. First, I clear a terminal so I can watch the racoon log:

$ clear
$ tail -f /var/log/racoon.log

If you don't get anything back when you run that tail command, racoon is not logging. Even though you haven't used racoon yet, a log should have been created for you and entries made indicating that racoon started. You do want a log when you're testing a tunnel, so kill racoon, restart it with the logging switch and try again:

$ killall racoon
$ racoon -f /usr/local/etc/racoon/racoon.conf -l /var/log/racoon.log

I then open a second terminal and start a tcpdump session that will just display the packets used in the IKE negotiations:

$ tcpdump port 500

Finally, I open a third terminal where I'll try to negotiate the tunnel. If your firewall rules allow you to ping, pinging the inside interface of the peer is a very good tunnel test.

If all goes well, your ping will hang for a moment while the tunnel is negotiated, then you'll see your ping responses displayed to your terminal. On your other terminals, you should see something like this:

$ tail -f /var/log/racoon.log

2002-12-29 13:03:09: INFO: main.c:172:main(): @(#)package version 
freebsd-20021120a
2002-12-29 13:03:09: INFO: main.c:174:main(): @(#)internal version 20001216 
sakane@kame.net
2002-12-29 13:03:09: INFO: main.c:175:main(): @(#)This product linked 
OpenSSL 0.9.6g 9 Aug 2002 (http://www.openssl.org/)
2002-12-29 13:03:09: INFO: isakmp.c:1358:isakmp_open(): 24.226.40.106[500] 
used as isakmp port (fd=5)
2002-12-29 13:04:31: INFO: isakmp.c:1684:isakmp_post_acquire(): IPsec-SA 
request for 24.226.16.88 queued due to no phase1 found.
2002-12-29 13:04:31: INFO: isakmp.c:798:isakmp_ph1begin_i(): initiate new 
phase 1 negotiation: A.A.A.A[500]<=>B.B.B.B[500]
2002-12-29 13:04:31: INFO: isakmp.c:803:isakmp_ph1begin_i(): begin 
Aggressive mode.
2002-12-29 13:04:31: INFO: vendorid.c:128:check_vendorid(): received Vendor 
ID: KAME/racoon
2002-12-29 13:07:21: INFO: isakmp.c:2412:log_ph1established(): ISAKMP-SA 
established A.A.A.A[500]-B.B.B.B[500] spi:2b7869ab380e7cc1:a3e29f4ac161cb25
2002-12-29 13:07:21: INFO: isakmp.c:942:isakmp_ph2begin_i(): initiate new 
phase 2 negotiation: A.A.A.A[0]<=>B.B.B.B[0]
2002-12-29 13:07:21: INFO: pfkey.c:1110:pk_recvupdate(): IPsec-SA 
established: ESP/Tunnel B.B.B.B->A.A.A.A spi=82702499(0x4edf0a3)
2002-12-29 13:07:21: INFO: pfkey.c:1322:pk_recvadd(): IPsec-SA established: 
ESP/Tunnel A.A.A.A->B.B.B.B spi=63238165(0x3c4f015)

Note that first the Phase 1, or ISAKMP, SA is established with a unique spi. Then two Phase 2, or IPsec, SAs are established, one in each direction, and each with a unique spi.

$ tcpdump port 500
tcpdump: listening on ed0 
13:04:31.067156 A.A.A.A.isakmp > B.B.B.B.isakmp: isakmp: phase 1 I agg:
[|sa]
13:04:31.067682 B.B.B.B.isakmp > A.A.A.A.isakmp: isakmp: phase 1 R agg: 
[|sa]
13:04:31.680474 A.A.A.A.isakmp > B.B.B.B.isakmp: isakmp: phase 1 I agg: 
(hash: len=20)
13:04:31.681046 A.A.A.A.isakmp > B.B.B.B.isakmp: isakmp: phase 2/others I 
inf[E]: [encrypted hash]
13:04:31.697564 A.A.A.A.isakmp > B.B.B.B.isakmp: isakmp: phase 2/others I 
oakley-quick[E]: [encrypted hash]
13:04:31.703306 B.B.B.B.isakmp > A.A.A.A.isakmp: isakmp: phase 2/others R 
inf[E]: [encrypted hash]
13:04:31.770199 B.B.B.B.isakmp > A.A.A.A.isakmp: isakmp: phase 2/others R 
oakley-quick[E]: [encrypted hash]

You may remember from VPNs and IPSec Demystified that Phase One aggressive mode uses 3 packets, which you can see from this tcpdump. This is followed by Phase Two. Note that all Phase Two packets are encrypted.

Finally, you know your tunnel is fully established when your SAD contains the SAs. You can confirm that with:

$ setkey -D

A.A.A.A B.B.B.B
	esp mode=tunnel spi=63238165(0x03c4f015) reqid=0(0x00000000)
	E: blowfish-cbc  a24ac0e7 36f7e153 26f81300 43d0d333
	A: hmac-sha1  6bb84116 e90d2b1b 2ac95285 0dd394fb afa0c3d8
	seq=0x00000004 replay=4 flags=0x00000000 state=mature 
	created: Dec 29 13:07:21 2002	current: Dec 29 13:15:32 2002
	diff: 491(s)	hard: 86400(s)	soft: 69120(s)
	last: Dec 29 13:07:35 2002	hard: 0(s)	soft: 0(s)
	current: 544(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 4	hard: 0	soft: 0
	sadb_seq=1 pid=50830 refcnt=2
B.B.B.B A.A.A.A
	esp mode=tunnel spi=82702499(0x04edf0a3) reqid=0(0x00000000)
	E: blowfish-cbc  ece45b91 af659b1f 1031b8eb e6268c60
	A: hmac-sha1  eb46c7b6 12051da0 567ca3a6 1c889e72 3faa5553
	seq=0x00000004 replay=4 flags=0x00000000 state=mature 
	created: Dec 29 13:07:21 2002	current: Dec 29 13:15:32 2002
	diff: 491(s)	hard: 86400(s)	soft: 69120(s)
	last: Dec 29 13:07:35 2002	hard: 0(s)	soft: 0(s)
	current: 336(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 4	hard: 0	soft: 0
	sadb_seq=0 pid=50830 refcnt=1

If your tunnel successfully negotiates, give yourself a pat on the back, and do the happy dance. If it doesn't, take heart and follow along as I demonstrate some common errors.

Pages: 1, 2, 3

Next Page