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 500Finally, 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=1If 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.
