Re: IPsec debugging

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

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

2016-03-02 17:30:38: [1.2.3.4] DEBUG: CERT validated
2016-03-02 17:30:38: DEBUG: HASH with:
2016-03-02 17:30:38: DEBUG: 
1dd550a5 779db2e2 97537ade 210973f7 02da518e 09869fd1 c4961cc1 de7b2c3d
998a6f1b 99616edd 976664ca 3fdcb434 9643ec77 17ea523b 66b32027 99e97350
4bca688d a4689f65 e0000823 80913fbf e7aa1dcb 67a0895d f4173b57 f7cd62be
889d74a3 c59b4641 661ccaf5 bfe54038 f77caae2 779933d0 50854408 bae619a2
500cf91d 9c003e04 c6e73904 7698f63f 7b618fc2 96aa49c8 db7288cd 091913ff
38143855 45b6e7cd 9ee53913 8a912b23 f8f923b2 0607ec93 e4ccad28 941358cf
0f8fae97 eea4c2ad 04ca5c21 9fb551bf 5d4d0a7a 00de9e2a 80461d3e b4f05851
5b1f86cc 07f58e97 6f5dca7f fc00d335 5f9a6d11 c45c58db c0401ecd 73a86981
2f782ba4 f0adc32a 6d25270c 4f188c54 00000001 00000001 0000002c 01010001
00000024 01010000 800b0001 800c7080 80010007 800e0080 80030003 80020001
80040002 09000000 306b310e 300c0603 55041113 05333230 3532310b 30090603
55040b13 02495431 0c300a06 03550408 13034e52 57311030 0e060355 04071307
48455246 4f524431 0b300906 03550406 13024445 310c300a 06035504 0a130357
50533111 300f0603 55040313 085a454e 5452414c 45
2016-03-02 17:30:38: DEBUG: hmac(hmac_md5)
2016-03-02 17:30:38: DEBUG: HASH (init) computed:
2016-03-02 17:30:38: DEBUG: 
4181e62e 035ec15a cd3a3b91 35bda641
2016-03-02 17:30:38: DEBUG: SIG authenticated
2016-03-02 17:30:38: [1.2.3.4] DEBUG: peer's ID:2016-03-02 17:30:38: DEBUG: 
09000000 306b310e 300c0603 55041113 05333230 3532310b 30090603 55040b13
02495431 0c300a06 03550408 13034e52 57311030 0e060355 04071307 48455246
4f524431 0b300906 03550406 13024445 310c300a 06035504 0a130357 50533111
300f0603 55040313 085a454e 5452414c 45
2016-03-02 17:30:38: DEBUG: ===
2016-03-02 17:30:38: DEBUG: compute IV for phase2
2016-03-02 17:30:38: DEBUG: phase1 last IV:
2016-03-02 17:30:38: DEBUG: 
d743aa08 c36d0d72 a4d24120 d0475633 e6327238
2016-03-02 17:30:38: DEBUG: hash(md5)
2016-03-02 17:30:38: DEBUG: encryption(aes)
2016-03-02 17:30:38: DEBUG: phase2 IV computed:
2016-03-02 17:30:38: DEBUG: 
bae50371 dcebc1af 44963b77 c345edbb
2016-03-02 17:30:38: DEBUG: HASH with:
2016-03-02 17:30:38: DEBUG: 
e6327238 0000001c 00000001 01106002 6d25270c 4f188c54 2f782ba4 f0adc32a
2016-03-02 17:30:38: DEBUG: hmac(hmac_md5)
2016-03-02 17:30:38: DEBUG: HASH computed:
2016-03-02 17:30:38: DEBUG: 
0300b7ab 6120ad69 9d6bd70c f71d5d36
2016-03-02 17:30:38: DEBUG: begin encryption.
2016-03-02 17:30:38: DEBUG: encryption(aes)
2016-03-02 17:30:38: DEBUG: pad length = 16
2016-03-02 17:30:38: DEBUG: 
0b000014 0300b7ab 6120ad69 9d6bd70c f71d5d36 0000001c 00000001 01106002
6d25270c 4f188c54 2f782ba4 f0adc32a a87ffd3a b765c486 16880400 38badf0f
2016-03-02 17:30:38: DEBUG: encryption(aes)
2016-03-02 17:30:38: DEBUG: with key:
2016-03-02 17:30:38: DEBUG: 
9d234eb0 dad64d47 1a9fbe8b 5dbfbccf
2016-03-02 17:30:38: DEBUG: encrypted payload by IV:
2016-03-02 17:30:38: DEBUG: 
bae50371 dcebc1af 44963b77 c345edbb
2016-03-02 17:30:38: DEBUG: save IV for next:
2016-03-02 17:30:38: DEBUG: 
660b403f 01b9ceb7 968b9b46 1b326f13
2016-03-02 17:30:38: DEBUG: encrypted.
2016-03-02 17:30:38: DEBUG: Adding NON-ESP marker
2016-03-02 17:30:38: DEBUG: 96 bytes from 192.168.1.5[4500] to 1.2.3.4[4500]
2016-03-02 17:30:38: DEBUG: sockname 192.168.1.5[4500]
2016-03-02 17:30:38: DEBUG: send packet from 192.168.1.5[4500]
2016-03-02 17:30:38: DEBUG: send packet to 1.2.3.4[4500]
2016-03-02 17:30:38: DEBUG: 1 times of 96 bytes message will be sent to 1.2.3.4[4500]
2016-03-02 17:30:38: DEBUG: 
00000000 6d25270c 4f188c54 2f782ba4 f0adc32a 08100501 e6327238 0000005c
7965e7d0 9c409799 1638f903 5bf9f2b1 4f217619 d3d6d4bc 2fc49c0d 32f0324e
9d9edea4 05aea0ec 26610b9a 19b70296 660b403f 01b9ceb7 968b9b46 1b326f13
2016-03-02 17:30:38: DEBUG: sendto Information notify.
2016-03-02 17:30:38: DEBUG: IV freed
2016-03-02 17:30:38: [1.2.3.4] INFO: received INITIAL-CONTACT
2016-03-02 17:30:38: DEBUG: call pfkey_send_dump
2016-03-02 17:30:38: DEBUG: pk_recv: retry[0] recv() 
2016-03-02 17:30:38: INFO: ISAKMP-SA established 192.168.1.5[4500]-1.2.3.4[4500] spi:6d25270c4f188c54:2f782ba4f0adc32a
2016-03-02 17:30:38: DEBUG: ===
2016-03-02 17:30:55: DEBUG: ===
2016-03-02 17:30:55: DEBUG: 92 bytes message received from 1.2.3.4[4500] to 192.168.1.5[4500]
2016-03-02 17:30:55: DEBUG: 
6d25270c 4f188c54 2f782ba4 f0adc32a 08100501 fc5e6961 0000005c 85b4c2fe
ea7a1325 f01e0e98 4fb0a7a0 67d2497f 2d53d197 26a0494c 0ea494f9 673f0c61
f7d0be4e 9e55e5bd 531726e9 cd78edff 9d3cd5a0 b83b26cc 9f750374
2016-03-02 17:30:55: DEBUG: receive Information.
2016-03-02 17:30:55: DEBUG: compute IV for phase2
2016-03-02 17:30:55: DEBUG: phase1 last IV:
2016-03-02 17:30:55: DEBUG: 
d743aa08 c36d0d72 a4d24120 d0475633 fc5e6961
2016-03-02 17:30:55: DEBUG: hash(md5)
2016-03-02 17:30:55: DEBUG: encryption(aes)
2016-03-02 17:30:55: DEBUG: phase2 IV computed:
2016-03-02 17:30:55: DEBUG: 
c3007892 3f11b0b7 0a1b5722 52dddb82
2016-03-02 17:30:56: DEBUG: begin decryption.
2016-03-02 17:30:56: DEBUG: encryption(aes)
2016-03-02 17:30:56: DEBUG: IV was saved for next processing:
2016-03-02 17:30:56: DEBUG: 
cd78edff 9d3cd5a0 b83b26cc 9f750374
2016-03-02 17:30:56: DEBUG: encryption(aes)
2016-03-02 17:30:56: DEBUG: with key:
2016-03-02 17:30:56: DEBUG: 
9d234eb0 dad64d47 1a9fbe8b 5dbfbccf
2016-03-02 17:30:56: DEBUG: decrypted payload by IV:
2016-03-02 17:30:56: DEBUG: 
c3007892 3f11b0b7 0a1b5722 52dddb82
2016-03-02 17:30:56: DEBUG: decrypted payload, but not trimed.
2016-03-02 17:30:56: DEBUG: 
0b000014 466ec8b4 bb871f1c 5bb66f8c 4dc2fb3b 00000020 00000001 01108d28
6d25270c 4f188c54 2f782ba4 f0adc32a 38a4c66f 00000000 00000000 00000000
2016-03-02 17:30:56: DEBUG: padding len=1
2016-03-02 17:30:56: DEBUG: skip to trim padding.
2016-03-02 17:30:56: DEBUG: decrypted.
2016-03-02 17:30:56: DEBUG: 
6d25270c 4f188c54 2f782ba4 f0adc32a 08100501 fc5e6961 0000005c 0b000014
466ec8b4 bb871f1c 5bb66f8c 4dc2fb3b 00000020 00000001 01108d28 6d25270c
4f188c54 2f782ba4 f0adc32a 38a4c66f 00000000 00000000 00000000
2016-03-02 17:30:56: DEBUG: IV freed
2016-03-02 17:30:56: DEBUG: HASH with:
2016-03-02 17:30:56: DEBUG: 
fc5e6961 00000020 00000001 01108d28 6d25270c 4f188c54 2f782ba4 f0adc32a
38a4c66f
2016-03-02 17:30:56: DEBUG: hmac(hmac_md5)
2016-03-02 17:30:56: DEBUG: HASH computed:
2016-03-02 17:30:56: DEBUG: 
466ec8b4 bb871f1c 5bb66f8c 4dc2fb3b
2016-03-02 17:30:56: DEBUG: hash validated.
2016-03-02 17:30:56: DEBUG: begin.
2016-03-02 17:30:56: DEBUG: seen nptype=8(hash)
2016-03-02 17:30:56: DEBUG: seen nptype=11(notify)
2016-03-02 17:30:56: DEBUG: succeed.
2016-03-02 17:30:56: [1.2.3.4] DEBUG: DPD R-U-There received
2016-03-02 17:30:56: DEBUG: compute IV for phase2
2016-03-02 17:30:56: DEBUG: phase1 last IV:
2016-03-02 17:30:56: DEBUG: 
d743aa08 c36d0d72 a4d24120 d0475633 db7f7bca
2016-03-02 17:30:56: DEBUG: hash(md5)
2016-03-02 17:30:56: DEBUG: encryption(aes)
2016-03-02 17:30:56: DEBUG: phase2 IV computed:
2016-03-02 17:30:56: DEBUG: 
55c87cb1 ef8d219f 9b94cfc1 36f45ef5
2016-03-02 17:30:56: DEBUG: HASH with:
2016-03-02 17:30:56: DEBUG: 
db7f7bca 00000020 00000001 01108d29 6d25270c 4f188c54 2f782ba4 f0adc32a
38a4c66f
2016-03-02 17:30:56: DEBUG: hmac(hmac_md5)
2016-03-02 17:30:56: DEBUG: HASH computed:
2016-03-02 17:30:56: DEBUG: 
7696c1b2 fea5f7e3 4630557c 9257a8f0
2016-03-02 17:30:56: DEBUG: begin encryption.
2016-03-02 17:30:56: DEBUG: encryption(aes)
2016-03-02 17:30:56: DEBUG: pad length = 12
2016-03-02 17:30:56: DEBUG: 
0b000014 7696c1b2 fea5f7e3 4630557c 9257a8f0 00000020 00000001 01108d29
6d25270c 4f188c54 2f782ba4 f0adc32a 38a4c66f cadac8b3 536cb0f1 da7ce80b
2016-03-02 17:30:56: DEBUG: encryption(aes)
2016-03-02 17:30:56: DEBUG: with key:
2016-03-02 17:30:56: DEBUG: 
9d234eb0 dad64d47 1a9fbe8b 5dbfbccf
2016-03-02 17:30:56: DEBUG: encrypted payload by IV:
2016-03-02 17:30:56: DEBUG: 
55c87cb1 ef8d219f 9b94cfc1 36f45ef5
2016-03-02 17:30:56: DEBUG: save IV for next:
2016-03-02 17:30:56: DEBUG: 
2e5b351c 3d1bc52c 73e0d0aa 4cf23a20
2016-03-02 17:30:56: DEBUG: encrypted.
2016-03-02 17:30:56: DEBUG: Adding NON-ESP marker
2016-03-02 17:30:56: DEBUG: 96 bytes from 192.168.1.5[4500] to 1.2.3.4[4500]
2016-03-02 17:30:56: DEBUG: sockname 192.168.1.5[4500]
2016-03-02 17:30:56: DEBUG: send packet from 192.168.1.5[4500]
2016-03-02 17:30:56: DEBUG: send packet to 1.2.3.4[4500]
2016-03-02 17:30:56: DEBUG: 1 times of 96 bytes message will be sent to 1.2.3.4[4500]
2016-03-02 17:30:56: DEBUG: 
00000000 6d25270c 4f188c54 2f782ba4 f0adc32a 08100501 db7f7bca 0000005c
99820149 fb9ed77a b1af7443 fdb380b2 6d588e8d a4e33784 260d7e9e cf5a8c5e
d5f6d7a7 f01cf2bb 1f492c21 56eeb427 2e5b351c 3d1bc52c 73e0d0aa 4cf23a20
2016-03-02 17:30:56: DEBUG: sendto Information notify.
2016-03-02 17:30:56: DEBUG: IV freed
2016-03-02 17:30:56: DEBUG: received a valid R-U-THERE, ACK sent
2016-03-02 17:30:56: DEBUG: KA: 192.168.1.5[4500]->1.2.3.4[4500]
2016-03-02 17:30:56: DEBUG: sockname 192.168.1.5[4500]
2016-03-02 17:30:56: DEBUG: send packet from 192.168.1.5[4500]
2016-03-02 17:30:56: DEBUG: send packet to 1.2.3.4[4500]
2016-03-02 17:30:56: DEBUG: 1 times of 1 bytes message will be sent to 1.2.3.4[4500]
2016-03-02 17:30:56: DEBUG: 
ff

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: racoon with rsasig and mode_cfg
Next by Date: Re: passive references
Previous by Thread: Re: IPsec debugging
Next by Thread: Re: IPsec debugging
Indexes:

Home | Main Index | Thread Index | Old Index