Re: [Ipsec-tools-devel] IPsec connection lost when isakmp is deleted by far side

[Laurent B. <bi...@in...>]

Le Wed, 25 Aug 2010 17:14:51 +0200,
VANHULLEBUS Yvan <va...@fr...> a écrit :

> Hi.

Hi,

> > Any idea of what could happend?
> > Is this "delete payload for protocol ESP" expected, shouldn't it
> > delete the IPSEC-sa too?
> 
> Yes, this is what it should do.
> Could you run racoon with "-d -d" (twice) option, so it will also
> output DEBUG2 messages ?
> Please be careful, this verbose mode will produce debbuging for some
> private things (preshared keys, etc....).

Ok, we have updated to the version 0.7.3 (version 0.7.3-6.2 recompiled
from opensuse 11.3) and it seems to work now but one of the two
IPsec-sa (the "local remote" one) is now deleted, the other one
("remote local") shouldn't be deleted too? Or is it on purpose if there
are data encrypted with the old key that keep coming?

The other one is deleted when the timelife reach 0 with:

racoon: 2010-08-25 19:05:34: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 19:05:34: DEBUG: get pfkey EXPIRE message
racoon: 2010-08-25 19:05:34: INFO: IPsec-SA expired: ESP/Tunnel remote[0]->local[0] spi=98969730(0x5e62882)
racoon: 2010-08-25 19:05:34: DEBUG: no such a SA found: ESP/Tunnel remote[0]->local[0] spi=98969730(0x5e62882)

And as racoon doesn't know about it anymore the next time new ISAKMP-sa
and IPsec-sa are renegotiated.

So I guess it's a bug in the version 0.7.1.

Anyway thank you for your help :)

Cheers

Laurent Bigonville

racoon: 2010-08-25 18:48:00: DEBUG: ===
racoon: 2010-08-25 18:48:00: DEBUG: 76 bytes message received from remote[500] to local[500]
racoon: 2010-08-25 18:48:00: DEBUG:  505588dd 5dfb03c6 03845834 90e950d8 08100501 74bd3986 0000004c 0b3553c5 abe44c3c 0e138129 a3cfe6b1 f0a3b578 de567779 87e83b53 6fd39eb0 b54466aa d7d14a9e 42dfe0fa 50cac692
racoon: 2010-08-25 18:48:00: DEBUG: receive Information.
racoon: 2010-08-25 18:48:00: DEBUG: compute IV for phase2
racoon: 2010-08-25 18:48:00: DEBUG: phase1 last IV:
racoon: 2010-08-25 18:48:00: DEBUG:  f632a785 eef0170a 077c6300 af0d4a09 74bd3986
racoon: 2010-08-25 18:48:00: DEBUG: hash(sha1)
racoon: 2010-08-25 18:48:00: DEBUG: encryption(aes)
racoon: 2010-08-25 18:48:00: DEBUG: phase2 IV computed:
racoon: 2010-08-25 18:48:00: DEBUG:  0e669fe6 da2184d8 b4f2649f 74a9e1e5
racoon: 2010-08-25 18:48:00: DEBUG: begin decryption.
racoon: 2010-08-25 18:48:00: DEBUG: encryption(aes)
racoon: 2010-08-25 18:48:00: DEBUG: IV was saved for next processing:
racoon: 2010-08-25 18:48:00: DEBUG:  b54466aa d7d14a9e 42dfe0fa 50cac692
racoon: 2010-08-25 18:48:00: DEBUG: encryption(aes)
racoon: alg_oakley_encdef_decrypt(aes klen=256 size=48): 0.000008
racoon: 2010-08-25 18:48:00: DEBUG: with key:
racoon: 2010-08-25 18:48:00: DEBUG:  f1be8af9 d4e910ba 25b4e5c0 950a15fb 4a043dd8 83d78c00 348cbb97 663f5933
racoon: 2010-08-25 18:48:00: DEBUG: decrypted payload by IV:
racoon: 2010-08-25 18:48:00: DEBUG:  0e669fe6 da2184d8 b4f2649f 74a9e1e5
racoon: 2010-08-25 18:48:00: DEBUG: decrypted payload, but not trimed.
racoon: 2010-08-25 18:48:00: DEBUG:  0c000018 fdc9fd30 572cf444 77e8573e 3bb6ae39 26b04af7 00000010 00000001 03040001 d25e12d5 00000000 00000000
racoon: 2010-08-25 18:48:00: DEBUG: padding len=0
racoon: 2010-08-25 18:48:00: DEBUG: skip to trim padding.
racoon: 2010-08-25 18:48:00: DEBUG: decrypted.
racoon: 2010-08-25 18:48:00: DEBUG:  505588dd 5dfb03c6 03845834 90e950d8 08100501 74bd3986 0000004c 0c000018 fdc9fd30 572cf444 77e8573e 3bb6ae39 26b04af7 00000010 00000001 03040001 d25e12d5 00000000 00000000
racoon: 2010-08-25 18:48:00: DEBUG: IV freed
racoon: 2010-08-25 18:48:00: DEBUG: HASH with:
racoon: 2010-08-25 18:48:00: DEBUG:  74bd3986 00000010 00000001 03040001 d25e12d5
racoon: 2010-08-25 18:48:00: DEBUG: hmac(hmac_sha1)
racoon: alg_oakley_hmacdef_one(hmac_sha1 size=20): 0.000006
racoon: 2010-08-25 18:48:00: DEBUG: HASH computed:
racoon: 2010-08-25 18:48:00: DEBUG:  fdc9fd30 572cf444 77e8573e 3bb6ae39 26b04af7
racoon: 2010-08-25 18:48:00: DEBUG: hash validated.
racoon: 2010-08-25 18:48:00: DEBUG: begin.
racoon: 2010-08-25 18:48:00: DEBUG: seen nptype=8(hash)
racoon: 2010-08-25 18:48:00: DEBUG: seen nptype=12(delete)
racoon: 2010-08-25 18:48:00: DEBUG: succeed.
racoon: 2010-08-25 18:48:00: DEBUG: delete payload for protocol ESP
racoon: 2010-08-25 18:48:00: DEBUG: call pfkey_send_dump
racoon: 2010-08-25 18:48:00: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:00: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:00: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:00: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:00: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:00: DEBUG: check spi(packet)=3529380565 spi(db)=3529380565.
racoon: 2010-08-25 18:48:00: DEBUG: an undead schedule has been deleted.
racoon: 2010-08-25 18:48:00: DEBUG: IV freed
racoon: 2010-08-25 18:48:00: INFO: purged IPsec-SA proto_id=ESP spi=3529380565.
racoon: 2010-08-25 18:48:00: DEBUG: purged SAs.
racoon: 2010-08-25 18:48:00: DEBUG: ===
racoon: 2010-08-25 18:48:00: DEBUG: 92 bytes message received from remote[500] to local[500]
racoon: 2010-08-25 18:48:00: DEBUG:  505588dd 5dfb03c6 03845834 90e950d8 08100501 b160ed20 0000005c d0c9e5e4 c7695b16 e0638fbe 02d06ba8 22807696 3230445e aaa7ecd9 3230e199 2fcf1206 79821442 e13ff49b 9133ce5f 5ea7f357 95368642 36a2993f cd1d208b
racoon: 2010-08-25 18:48:00: DEBUG: receive Information.
racoon: 2010-08-25 18:48:00: DEBUG: compute IV for phase2
racoon: 2010-08-25 18:48:00: DEBUG: phase1 last IV:
racoon: 2010-08-25 18:48:00: DEBUG:  f632a785 eef0170a 077c6300 af0d4a09 b160ed20
racoon: 2010-08-25 18:48:00: DEBUG: hash(sha1)
racoon: 2010-08-25 18:48:00: DEBUG: encryption(aes)
racoon: 2010-08-25 18:48:00: DEBUG: phase2 IV computed:
racoon: 2010-08-25 18:48:00: DEBUG:  718ce699 a72fdd7f ee6b4363 e04febe8
racoon: 2010-08-25 18:48:00: DEBUG: begin decryption.
racoon: 2010-08-25 18:48:00: DEBUG: encryption(aes)
racoon: 2010-08-25 18:48:00: DEBUG: IV was saved for next processing:
racoon: 2010-08-25 18:48:00: DEBUG:  5ea7f357 95368642 36a2993f cd1d208b
racoon: 2010-08-25 18:48:00: DEBUG: encryption(aes)
racoon: alg_oakley_encdef_decrypt(aes klen=256 size=64): 0.000004
racoon: 2010-08-25 18:48:00: DEBUG: with key:
racoon: 2010-08-25 18:48:00: DEBUG:  f1be8af9 d4e910ba 25b4e5c0 950a15fb 4a043dd8 83d78c00 348cbb97 663f5933
racoon: 2010-08-25 18:48:00: DEBUG: decrypted payload by IV:
racoon: 2010-08-25 18:48:00: DEBUG:  718ce699 a72fdd7f ee6b4363 e04febe8
racoon: 2010-08-25 18:48:00: DEBUG: decrypted payload, but not trimed.
racoon: 2010-08-25 18:48:00: DEBUG:  0c000018 21683258 45786765 813f2904 e5b8cea3 069f24f1 0000001c 00000001 01100001 505588dd 5dfb03c6 03845834 90e950d8 00000000 00000000 00000000
racoon: 2010-08-25 18:48:00: DEBUG: padding len=0
racoon: 2010-08-25 18:48:00: DEBUG: skip to trim padding.
racoon: 2010-08-25 18:48:00: DEBUG: decrypted.
racoon: 2010-08-25 18:48:00: DEBUG:  505588dd 5dfb03c6 03845834 90e950d8 08100501 b160ed20 0000005c 0c000018 21683258 45786765 813f2904 e5b8cea3 069f24f1 0000001c 00000001 01100001 505588dd 5dfb03c6 03845834 90e950d8 00000000 00000000 00000000
racoon: 2010-08-25 18:48:00: DEBUG: IV freed
racoon: 2010-08-25 18:48:00: DEBUG: HASH with:
racoon: 2010-08-25 18:48:00: DEBUG:  b160ed20 0000001c 00000001 01100001 505588dd 5dfb03c6 03845834 90e950d8
racoon: 2010-08-25 18:48:00: DEBUG: hmac(hmac_sha1)
racoon: alg_oakley_hmacdef_one(hmac_sha1 size=32): 0.000005
racoon: 2010-08-25 18:48:00: DEBUG: HASH computed:
racoon: 2010-08-25 18:48:00: DEBUG:  21683258 45786765 813f2904 e5b8cea3 069f24f1
racoon: 2010-08-25 18:48:00: DEBUG: hash validated.
racoon: 2010-08-25 18:48:00: DEBUG: begin.
racoon: 2010-08-25 18:48:00: DEBUG: seen nptype=8(hash)
racoon: 2010-08-25 18:48:00: DEBUG: seen nptype=12(delete)
racoon: 2010-08-25 18:48:00: DEBUG: succeed.
racoon: 2010-08-25 18:48:00: DEBUG: delete payload for protocol ISAKMP
racoon: 2010-08-25 18:48:00: INFO: ISAKMP-SA expired local[500]-remote[500] spi:505588dd5dfb03c6:0384583490e950d8
racoon: 2010-08-25 18:48:00: DEBUG: purged SAs.
racoon: 2010-08-25 18:48:00: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:00: DEBUG: get pfkey DELETE message
racoon: 2010-08-25 18:48:00: DEBUG: DELETE message is not interesting because the message was originated by me.
racoon: 2010-08-25 18:48:01: INFO: ISAKMP-SA deleted local[500]-remote[500] spi:505588dd5dfb03c6:0384583490e950d8
racoon: 2010-08-25 18:48:01: DEBUG: IV freed
racoon: 2010-08-25 18:48:49: DEBUG: call pfkey_send_dump
racoon: 2010-08-25 18:48:49: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:49: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:49: DEBUG: pk_recv: retry[0] recv()
racoon: 2010-08-25 18:48:49: DEBUG: pk_recv: retry[0] recv()