[Openswan Users] Problem: interroperability between Linux and Windows Server 2003
Denis Roy
droy at lb3.ca
Fri Dec 8 19:37:19 EST 2006
Hello,
I use Openswan 2.4.7 with kernel 2.6.18-gentoo-r3. The setup is very
simple and consist of a bidirectional ipsec encryption in mode=transport
between two hosts on the same subnet. When I first launch OpenSwan,
everything is alright but it stops working one hour or so later. The
strange thing is that it asks to delete an old SA (ISAKMP State#1),
while it was using the eighth and deleted the seventh already. Shortly
after that, I get an error "Informational Exchange is for an unknown
(expired?) SA" and then, I cannot successfully ping the host until I
restart OpenSwan. During that time, I can see that my outgoing traffic
is still encrypted but the Windows Server does not reply. Here is a part
of the logs I get from pluto in debug mode, and the corresponding part
of oakley.log So you can get what's happening on both sides.
-----pluto log-----
Dec 8 18:55:08 [pluto] | *received 84 bytes from 192.168.16.2:500 on
br0 (port=500)
Dec 8 18:55:08 [pluto] | processing packet with exchange
type=ISAKMP_XCHG_INFO (5)
Dec 8 18:55:08 [pluto] | ICOOKIE: ba 14 6a e5 da cc 74 42
Dec 8 18:55:08 [pluto] | RCOOKIE: a9 57 36 28 d3 48 d7 64
Dec 8 18:55:08 [pluto] | peer: c0 a8 10 02
Dec 8 18:55:08 [pluto] | state hash entry 25
Dec 8 18:55:08 [pluto] | peer and cookies match on #8, provided msgid
00000000 vs 74b0c818/00000000
Dec 8 18:55:08 [pluto] | peer and cookies match on #1, provided msgid
00000000 vs 00000000/00000000
Dec 8 18:55:08 [pluto] | p15 state object #1 found, in STATE_MAIN_I4
Dec 8 18:55:08 [pluto] | processing connection windows-security
Dec 8 18:55:08 [pluto] | last Phase 1 IV: 92 0a 7a 7a 70 9a 13 0c
Dec 8 18:55:08 [pluto] | current Phase 1 IV: 92 0a 7a 7a 70 9a 13 0c
Dec 8 18:55:08 [pluto] | computed Phase 2 IV:
Dec 8 18:55:08 [pluto] | 88 ed cc 6f 87 48 8a be 69 d6 ca 48 c3 f7
b4 74
Dec 8 18:55:08 [pluto] | 74 58 8e d7
Dec 8 18:55:08 [pluto] | received encrypted packet from
192.168.16.2:500
Dec 8 18:55:08 [pluto] | decrypting 56 bytes using algorithm
OAKLEY_3DES_CBC
Dec 8 18:55:08 [pluto] | decrypted:
Dec 8 18:55:08 [pluto] | 0c 00 00 18 0e e2 6b 04 b4 e3 79 79 38 72
ed cc
Dec 8 18:55:08 [pluto] | b2 6f 1e 30 08 ec b1 f9 00 00 00 1c 00 00
00 01
Dec 8 18:55:08 [pluto] | 01 10 00 01 ba 14 6a e5 da cc 74 42 a9 57
36 28
Dec 8 18:55:08 [pluto] | d3 48 d7 64 00 00 00 00
Dec 8 18:55:08 [pluto] | next IV: f5 2a d4 4e 90 c0 54 cb
Dec 8 18:55:08 [pluto] | ICOOKIE: ba 14 6a e5 da cc 74 42
Dec 8 18:55:08 [pluto] | RCOOKIE: a9 57 36 28 d3 48 d7 64
Dec 8 18:55:08 [pluto] | peer: c0 a8 10 02
Dec 8 18:55:08 [pluto] | state hash entry 25
Dec 8 18:55:08 [pluto] | peer and cookies match on #8, provided msgid
00000000 vs 74b0c818
Dec 8 18:55:08 [pluto] | peer and cookies match on #1, provided msgid
00000000 vs 00000000
Dec 8 18:55:08 [pluto] | state object #1 found, in STATE_MAIN_I4
Dec 8 18:55:08 [pluto] | processing connection windows-security
Dec 8 18:55:08 [pluto] "windows-security" #1: received Delete SA
payload: deleting ISAKMP State #1
Dec 8 18:55:08 [pluto] | deleting state #1
Dec 8 18:55:08 [pluto] | processing connection windows-security
Dec 8 18:55:08 [pluto] | **emit ISAKMP Message:
Dec 8 18:55:08 [pluto] | initiator cookie:
Dec 8 18:55:08 [pluto] | ba 14 6a e5 da cc 74 42
Dec 8 18:55:08 [pluto] | responder cookie:
Dec 8 18:55:08 [pluto] | a9 57 36 28 d3 48 d7 64
Dec 8 18:55:08 [pluto] | next payload type: ISAKMP_NEXT_HASH
Dec 8 18:55:08 [pluto] | ISAKMP version: ISAKMP Version 1.0
Dec 8 18:55:08 [pluto] | exchange type: ISAKMP_XCHG_INFO
Dec 8 18:55:08 [pluto] | flags: ISAKMP_FLAG_ENCRYPTION
Dec 8 18:55:08 [pluto] | message ID: e3 57 03 4c
Dec 8 18:55:08 [pluto] | ***emit ISAKMP Hash Payload:
Dec 8 18:55:08 [pluto] | next payload type: ISAKMP_NEXT_D
Dec 8 18:55:08 [pluto] | emitting 20 zero bytes of HASH(1) into ISAKMP
Hash Payload
Dec 8 18:55:08 [pluto] | emitting length of ISAKMP Hash Payload: 24
Dec 8 18:55:08 [pluto] | ***emit ISAKMP Delete Payload:
Dec 8 18:55:08 [pluto] | next payload type: ISAKMP_NEXT_NONE
Dec 8 18:55:08 [pluto] | DOI: ISAKMP_DOI_IPSEC
Dec 8 18:55:08 [pluto] | protocol ID: 1
Dec 8 18:55:08 [pluto] | SPI size: 16
Dec 8 18:55:08 [pluto] | number of SPIs: 1
Dec 8 18:55:08 [pluto] | emitting 16 raw bytes of delete payload into
ISAKMP Delete Payload
Dec 8 18:55:08 [pluto] | delete payload ba 14 6a e5 da cc 74 42 a9
57 36 28 d3 48 d7 64
Dec 8 18:55:08 [pluto] | emitting length of ISAKMP Delete Payload: 28
Dec 8 18:55:08 [pluto] | HASH(1) computed:
Dec 8 18:55:08 [pluto] | 44 86 68 a5 2c a0 a5 f8 77 0e db a1 43 bc
05 f1
Dec 8 18:55:08 [pluto] | 6b ea ae cb
Dec 8 18:55:08 [pluto] | last Phase 1 IV: 92 0a 7a 7a 70 9a 13 0c
Dec 8 18:55:08 [pluto] | current Phase 1 IV: 92 0a 7a 7a 70 9a 13 0c
Dec 8 18:55:08 [pluto] | computed Phase 2 IV:
Dec 8 18:55:08 [pluto] | 63 1a ab a2 5f 22 41 dc ce bd 25 7e 87 04
e1 a2
Dec 8 18:55:08 [pluto] | ad df f8 55
Dec 8 18:55:08 [pluto] | encrypting:
Dec 8 18:55:08 [pluto] | 0c 00 00 18 44 86 68 a5 2c a0 a5 f8 77 0e
db a1
Dec 8 18:55:08 [pluto] | 43 bc 05 f1 6b ea ae cb 00 00 00 1c 00 00
00 01
Dec 8 18:55:08 [pluto] | 01 10 00 01 ba 14 6a e5 da cc 74 42 a9 57
36 28
Dec 8 18:55:08 [pluto] | d3 48 d7 64
Dec 8 18:55:08 [pluto] | IV:
Dec 8 18:55:08 [pluto] | 63 1a ab a2 5f 22 41 dc ce bd 25 7e 87 04
e1 a2
Dec 8 18:55:08 [pluto] | ad df f8 55
Dec 8 18:55:08 [pluto] | emitting 4 zero bytes of encryption padding
into ISAKMP Message
Dec 8 18:55:08 [pluto] | encrypting using OAKLEY_3DES_CBC
Dec 8 18:55:08 [pluto] | next IV: d4 87 43 b8 8c 84 ef ee
Dec 8 18:55:08 [pluto] | emitting length of ISAKMP Message: 84
Dec 8 18:55:08 [pluto] | sending 84 bytes for delete notify through
br0:500 to 192.168.16.2:500:
Dec 8 18:55:08 [pluto] | no suspended cryptographic state for 1
Dec 8 18:55:08 [pluto] packet from 192.168.16.2:500: received and
ignored informational message
Dec 8 18:55:08 [pluto] | complete state transition with STF_IGNORE
Dec 8 18:55:08 [pluto] | next event EVENT_PENDING_PHASE2 in 119 seconds
Dec 8 18:57:07 [pluto] |
Dec 8 18:57:07 [pluto] | *time to handle event
Dec 8 18:57:07 [pluto] | handling event EVENT_PENDING_PHASE2
Dec 8 18:57:07 [pluto] | event after this is EVENT_REINIT_SECRET in 240
seconds
Dec 8 18:57:07 [pluto] | inserting event EVENT_PENDING_PHASE2, timeout
in 120 seconds
Dec 8 18:57:07 [pluto] | pending review: connection "windows-security"
checked
Dec 8 18:57:07 [pluto] | next event EVENT_PENDING_PHASE2 in 120 seconds
Dec 8 18:58:09 [pluto] |
Dec 8 18:58:09 [pluto] | *received 68 bytes from 192.168.16.2:500 on
br0 (port=500)
Dec 8 18:58:09 [pluto] | processing packet with exchange
type=ISAKMP_XCHG_INFO (5)
Dec 8 18:58:09 [pluto] | ICOOKIE: ba 14 6a e5 da cc 74 42
Dec 8 18:58:09 [pluto] | RCOOKIE: a9 57 36 28 d3 48 d7 64
Dec 8 18:58:09 [pluto] | peer: c0 a8 10 02
Dec 8 18:58:09 [pluto] | state hash entry 25
Dec 8 18:58:09 [pluto] | peer and cookies match on #8, provided msgid
00000000 vs 74b0c818/00000000
Dec 8 18:58:09 [pluto] | p15 state object not found
Dec 8 18:58:09 [pluto] packet from 192.168.16.2:500: Informational
Exchange is for an unknown (expired?) SA
Dec 8 18:58:09 [pluto] | next event EVENT_PENDING_PHASE2 in 58 seconds
Dec 8 18:59:07 [pluto] |
Dec 8 18:59:07 [pluto] | *time to handle event
Dec 8 18:59:07 [pluto] | handling event EVENT_PENDING_PHASE2
Dec 8 18:59:07 [pluto] | event after this is EVENT_REINIT_SECRET in 120
seconds
Dec 8 18:59:07 [pluto] | inserting event EVENT_PENDING_PHASE2, timeout
in 120 seconds
Dec 8 18:59:07 [pluto] | pending review: connection "windows-security"
checked
Dec 8 18:59:07 [pluto] | next event EVENT_PENDING_PHASE2 in 120 seconds
-----oakley.log-----
12-08: 18:52:36:406:162c Receive: (get) SA = 0x064f7908 from
192.168.16.1.500
12-08: 18:52:36:406:162c ISAKMP Header: (V1.0), len = 68
12-08: 18:52:36:406:162c I-COOKIE ba146ae5dacc7442
12-08: 18:52:36:406:162c R-COOKIE a9573628d348d764
12-08: 18:52:36:406:162c exchange: ISAKMP Informational Exchange
12-08: 18:52:36:406:162c flags: 1 ( encrypted )
12-08: 18:52:36:406:162c next payload: HASH
12-08: 18:52:36:406:162c message ID: 39f6af8f
12-08: 18:52:36:406:162c processing HASH (Notify/Delete)
12-08: 18:52:36:406:162c processing payload DELETE
12-08: 18:52:36:406:162c Asked to delete phase2 SPI we don't own:
3935321817 proto=3
12-08: 18:53:49:500:162c CE Dead. sa:064F7908 ce:05E67E50 status:35f0
12-08: 18:55:15:625:162c Expire_sa SA=64f7908
12-08: 18:55:15:625:162c SA Dead. sa:064F7908 status:35ef
12-08: 18:55:15:625:162c isadb_set_status sa:064F7908 centry:00000000
status 35ef
12-08: 18:55:15:625:162c constructing ISAKMP Header
12-08: 18:55:15:625:162c constructing HASH (null)
12-08: 18:55:15:625:162c constructing DELETE. MM 064F7908
12-08: 18:55:15:625:162c constructing HASH (Notify/Delete)
12-08: 18:55:15:625:162c Not setting retransmit to downlevel client. SA
064F7908 Centry 00000000
12-08: 18:55:15:625:162c
12-08: 18:55:15:625:162c Sending: SA = 0x064F7908 to 192.168.16.1:Type
1.500
12-08: 18:55:15:625:162c ISAKMP Header: (V1.0), len = 84
12-08: 18:55:15:625:162c I-COOKIE ba146ae5dacc7442
12-08: 18:55:15:625:162c R-COOKIE a9573628d348d764
12-08: 18:55:15:625:162c exchange: ISAKMP Informational Exchange
12-08: 18:55:15:625:162c flags: 1 ( encrypted )
12-08: 18:55:15:625:162c next payload: HASH
12-08: 18:55:15:625:162c message ID: bd36c271
12-08: 18:55:15:625:162c Ports S:f401 D:f401
12-08: 18:55:15:625:162c
12-08: 18:55:15:625:162c Receive: (get) SA = 0x064f7908 from
192.168.16.1.500
12-08: 18:55:15:625:162c ISAKMP Header: (V1.0), len = 84
12-08: 18:55:15:625:162c I-COOKIE ba146ae5dacc7442
12-08: 18:55:15:625:162c R-COOKIE a9573628d348d764
12-08: 18:55:15:625:162c exchange: ISAKMP Informational Exchange
12-08: 18:55:15:625:162c flags: 1 ( encrypted )
12-08: 18:55:15:625:162c next payload: HASH
12-08: 18:55:15:625:162c message ID: e357034c
12-08: 18:55:15:625:162c processing HASH (Notify/Delete)
12-08: 18:55:15:625:162c processing payload DELETE
12-08: 18:58:16:297:162c QM Deleted. Notify from driver: Src
192.168.16.2 Dest 192.168.16.1 InSPI 1693508629 OutSpi 4249402879
Tunnel 0 TunnelFilter 0
12-08: 18:58:16:297:162c srcEncapPort=62465, dstEncapPort=62465
12-08: 18:58:16:297:162c Could not find the peer list entry
12-08: 18:58:16:297:162c constructing ISAKMP Header
12-08: 18:58:16:297:162c constructing HASH (null)
12-08: 18:58:16:297:162c Construct QM Delete Spi 1693508629
12-08: 18:58:16:297:162c constructing HASH (Notify/Delete)
12-08: 18:58:16:297:162c Not setting retransmit to downlevel client. SA
064F7908 Centry 00000000
12-08: 18:58:16:297:162c
12-08: 18:58:16:297:162c Sending: SA = 0x064F7908 to 192.168.16.1:Type
1.500
12-08: 18:58:16:297:162c ISAKMP Header: (V1.0), len = 68
12-08: 18:58:16:297:162c I-COOKIE ba146ae5dacc7442
12-08: 18:58:16:297:162c R-COOKIE a9573628d348d764
12-08: 18:58:16:297:162c exchange: ISAKMP Informational Exchange
12-08: 18:58:16:297:162c flags: 1 ( encrypted )
12-08: 18:58:16:297:162c next payload: HASH
12-08: 18:58:16:297:162c message ID: a92f0543
12-08: 18:58:16:297:162c Ports S:f401 D:f401
12-08: 18:58:16:297:162c PrivatePeerAddr 0
12-08: 18:58:19:515:162c ClearFragList
Anyone has an idea of what is happening there? Any help would be
appreciated... Maybe just explaining the "p15 state object not found" on
pluto's side could be a good start.
Thank you very much in advance,
Denis.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.openswan.org/pipermail/users/attachments/20061208/b0f2dffc/attachment-0001.html
More information about the Users
mailing list