[Swan] Aggressive mode not possible with Juniper Netscreen

Philippe Vouters philippe.vouters at laposte.net
Mon Jan 21 10:35:21 EET 2013


Dear Elison,

So that I could have had correctly understood your situation, it would 
have indeed helped provided I had the Netscreen AND Libreswan log 
traces, both logging at the same time or at a known time shift. From 
your Libreswan trace with plutodebug=control, I cannot see where 
Libreswan would be eventually failing.

Libreswan shows this trace:
Jan 21 09:53:47 elisonniven pluto[4299]: | phase 1 is done, looking for 
phase 2 to unpend
shortly after:
Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: packet rejected: 
should have been encrypted
Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: sending notification 
INVALID_FLAGS to 10.103.2.75:500

The two last events above do not now seem unexpected to me if they 
translate a real cause coming from the Netscreen side.

Philippe Vouters (Fontainebleau/France)
URL: http://vouters.dyndns.org/
SIP: sip:Vouters at sip.linphone.org

Le 21/01/2013 05:25, Elison Niven a écrit :
> Hi,
>
> On Sunday 20 January 2013 04:54:43 AM IST, Paul Wouters wrote:
>> On Fri, 18 Jan 2013, Philippe Vouters wrote:
>>
>>> In summary, it looks to me there are two issues here :
>>>
>>> 1/ Libreswan could be wrongly issuing the packet rejected message
>>> meanwhile taking the corresponding action.
>>> 2/ Another problem you seem to face is on your Netscreen side (your
>>> traces). At the time of the Libreswan packet rejected message,
>>> Netscreen would wrongly assume it is already phase 2 while Libreswan
>>> is still keeping in phase 1.
>>
>> I'm pretty sure this is 2)
>>
>> There is a mismatch in configuration.
>>
> I do not see how this is a mismatch in the configuration as when 
> Libreswan initiates the connection, it is working fine!
>
> Here are the logs on libreswan with plutodebug=control :
> Jan 21 09:53:47 elisonniven pluto[4299]: |
> Jan 21 09:53:47 elisonniven pluto[4299]: | *received 324 bytes from 
> 10.103.2.75:500 on p18p1 (port=500)
> Jan 21 09:53:47 elisonniven pluto[4299]: |  processing version=1.0 
> packet with exchange type=ISAKMP_XCHG_AGGR (4)
> Jan 21 09:53:47 elisonniven pluto[4299]: packet from 10.103.2.75:500: 
> ignoring unknown Vendor ID payload 
> [4a4340b543e02b84c88a8b96a8af9ebe77d9accc0000000b00000500]
> Jan 21 09:53:47 elisonniven pluto[4299]: packet from 10.103.2.75:500: 
> received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
> Jan 21 09:53:47 elisonniven pluto[4299]: packet from 10.103.2.75:500: 
> ignoring Vendor ID payload [HeartBeat Notify 386b0100]
> Jan 21 09:53:47 elisonniven pluto[4299]: | creating state object #1 at 
> 0x988ffc8
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: Aggressive mode 
> peer ID is ID_IPV4_ADDR: '10.103.2.75'
> Jan 21 09:53:47 elisonniven pluto[4299]: | started looking for secret 
> for 10.103.6.114->10.103.2.75 of kind PPK_PSK
> Jan 21 09:53:47 elisonniven pluto[4299]: | actually looking for secret 
> for 10.103.6.114->10.103.2.75 of kind PPK_PSK
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 10.103.2.75 
> to 10.103.6.114 / 10.103.2.75 -> 4
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 12
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 4: match=12
> Jan 21 09:53:47 elisonniven pluto[4299]: | best_match 0>12 
> best=0x988cbb0 (line=4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key %any to 
> 10.103.6.114 / 10.103.2.75 -> 2
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 10
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 3: match=10
> Jan 21 09:53:47 elisonniven pluto[4299]: | match(10) was not 
> best_match(12)
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 10.103.7.41 
> to 10.103.6.114 / 10.103.2.75 -> 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 8
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 2: match=8
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 
> 10.103.7.155 to 10.103.6.114 / 10.103.2.75 -> 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 8
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 1: match=8
> Jan 21 09:53:47 elisonniven pluto[4299]: | concluding with 
> best_match=12 best=0x988cbb0 (lineno=4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | offered CA: '%none'
> Jan 21 09:53:47 elisonniven pluto[4299]: | processing connection jun
> Jan 21 09:53:47 elisonniven pluto[4299]: | ICOOKIE:  6c 23 d9 65 fa 87 
> ba 23
> Jan 21 09:53:47 elisonniven pluto[4299]: | RCOOKIE:  94 46 8a 37 2d 46 
> ff 8d
> Jan 21 09:53:47 elisonniven pluto[4299]: | state hash entry 23
> Jan 21 09:53:47 elisonniven pluto[4299]: | inserting state object #1
> Jan 21 09:53:47 elisonniven pluto[4299]: | inserting event 
> EVENT_SO_DISCARD, timeout in 0 seconds for #1
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: responding to 
> Aggressive Mode, state #1, connection "jun" from 10.103.2.75
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: enabling possible 
> NAT-traversal with method draft-ietf-ipsec-nat-t-ike-00/01
> Jan 21 09:53:47 elisonniven pluto[4299]: | started looking for secret 
> for 10.103.6.114->10.103.2.75 of kind PPK_PSK
> Jan 21 09:53:47 elisonniven pluto[4299]: | actually looking for secret 
> for 10.103.6.114->10.103.2.75 of kind PPK_PSK
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 10.103.2.75 
> to 10.103.6.114 / 10.103.2.75 -> 4
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 12
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 4: match=12
> Jan 21 09:53:47 elisonniven pluto[4299]: | best_match 0>12 
> best=0x988cbb0 (line=4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key %any to 
> 10.103.6.114 / 10.103.2.75 -> 2
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 10
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 3: match=10
> Jan 21 09:53:47 elisonniven pluto[4299]: | match(10) was not 
> best_match(12)
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 10.103.7.41 
> to 10.103.6.114 / 10.103.2.75 -> 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 8
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 2: match=8
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 
> 10.103.7.155 to 10.103.6.114 / 10.103.2.75 -> 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 8
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 1: match=8
> Jan 21 09:53:47 elisonniven pluto[4299]: | concluding with 
> best_match=12 best=0x988cbb0 (lineno=4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | helper -1 doing 
> build_kenonce op id: 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | processing connection jun
> Jan 21 09:53:47 elisonniven pluto[4299]: | started looking for secret 
> for 10.103.6.114->10.103.2.75 of kind PPK_PSK
> Jan 21 09:53:47 elisonniven pluto[4299]: | actually looking for secret 
> for 10.103.6.114->10.103.2.75 of kind PPK_PSK
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 10.103.2.75 
> to 10.103.6.114 / 10.103.2.75 -> 4
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 12
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 4: match=12
> Jan 21 09:53:47 elisonniven pluto[4299]: | best_match 0>12 
> best=0x988cbb0 (line=4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key %any to 
> 10.103.6.114 / 10.103.2.75 -> 2
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 10
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 3: match=10
> Jan 21 09:53:47 elisonniven pluto[4299]: | match(10) was not 
> best_match(12)
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 10.103.7.41 
> to 10.103.6.114 / 10.103.2.75 -> 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 8
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 2: match=8
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 
> 10.103.7.155 to 10.103.6.114 / 10.103.2.75 -> 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 8
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 1: match=8
> Jan 21 09:53:47 elisonniven pluto[4299]: | concluding with 
> best_match=12 best=0x988cbb0 (lineno=4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | parent1 type: 7 group: 2 
> len: 2680
> Jan 21 09:53:47 elisonniven pluto[4299]: | helper -1 doing compute 
> dh+iv op id: 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | processing connection jun
> Jan 21 09:53:47 elisonniven pluto[4299]: | thinking about whether to 
> send my certificate:
> Jan 21 09:53:47 elisonniven pluto[4299]: |   I have RSA key: 
> OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
> Jan 21 09:53:47 elisonniven pluto[4299]: |   sendcert: CERT_ALWAYSSEND 
> and I did not get a certificate request
> Jan 21 09:53:47 elisonniven pluto[4299]: |   so do not send cert.
> Jan 21 09:53:47 elisonniven pluto[4299]: | I did not send a 
> certificate because digital signatures are not being used. (PSK)
> Jan 21 09:53:47 elisonniven pluto[4299]: |  I am not sending a 
> certificate request
> Jan 21 09:53:47 elisonniven pluto[4299]: | started looking for secret 
> for 10.103.6.114->10.103.2.75 of kind PPK_PSK
> Jan 21 09:53:47 elisonniven pluto[4299]: | actually looking for secret 
> for 10.103.6.114->10.103.2.75 of kind PPK_PSK
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 10.103.2.75 
> to 10.103.6.114 / 10.103.2.75 -> 4
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 12
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 4: match=12
> Jan 21 09:53:47 elisonniven pluto[4299]: | best_match 0>12 
> best=0x988cbb0 (line=4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key %any to 
> 10.103.6.114 / 10.103.2.75 -> 2
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 10
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 3: match=10
> Jan 21 09:53:47 elisonniven pluto[4299]: | match(10) was not 
> best_match(12)
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 10.103.7.41 
> to 10.103.6.114 / 10.103.2.75 -> 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 8
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 2: match=8
> Jan 21 09:53:47 elisonniven pluto[4299]: | 1: compared key 
> 10.103.7.155 to 10.103.6.114 / 10.103.2.75 -> 0
> Jan 21 09:53:47 elisonniven pluto[4299]: | 2: compared key 
> 10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 8
> Jan 21 09:53:47 elisonniven pluto[4299]: | line 1: match=8
> Jan 21 09:53:47 elisonniven pluto[4299]: | concluding with 
> best_match=12 best=0x988cbb0 (lineno=4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | complete state transition 
> with STF_OK
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: transition from 
> state STATE_AGGR_R0 to state STATE_AGGR_R1
> Jan 21 09:53:47 elisonniven pluto[4299]: | sending reply packet to 
> 10.103.2.75:500 (from port 500)
> Jan 21 09:53:47 elisonniven pluto[4299]: | sending 356 bytes for 
> STATE_AGGR_R0 through p18p1:500 to 10.103.2.75:500 (using #1)
> Jan 21 09:53:47 elisonniven pluto[4299]: | inserting event 
> EVENT_RETRANSMIT, timeout in 10 seconds for #1
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: STATE_AGGR_R1: sent 
> AR1, expecting AI2
> Jan 21 09:53:47 elisonniven pluto[4299]: | modecfg pull: noquirk 
> policy:push not-client
> Jan 21 09:53:47 elisonniven pluto[4299]: | phase 1 is done, looking 
> for phase 2 to unpend
> Jan 21 09:53:47 elisonniven pluto[4299]: | complete state transition 
> with STF_INLINE
> Jan 21 09:53:47 elisonniven pluto[4299]: | complete state transition 
> with STF_INLINE
> Jan 21 09:53:47 elisonniven pluto[4299]: | * processed 0 messages from 
> cryptographic helpers
> Jan 21 09:53:47 elisonniven pluto[4299]: | next event EVENT_RETRANSMIT 
> in 10 seconds for #1
> Jan 21 09:53:47 elisonniven pluto[4299]: | next event EVENT_RETRANSMIT 
> in 10 seconds for #1
> Jan 21 09:53:47 elisonniven pluto[4299]: |
> Jan 21 09:53:47 elisonniven pluto[4299]: | *received 100 bytes from 
> 10.103.2.75:500 on p18p1 (port=500)
> Jan 21 09:53:47 elisonniven pluto[4299]: |  processing version=1.0 
> packet with exchange type=ISAKMP_XCHG_AGGR (4)
> Jan 21 09:53:47 elisonniven pluto[4299]: | ICOOKIE:  6c 23 d9 65 fa 87 
> ba 23
> Jan 21 09:53:47 elisonniven pluto[4299]: | RCOOKIE:  94 46 8a 37 2d 46 
> ff 8d
> Jan 21 09:53:47 elisonniven pluto[4299]: | state hash entry 23
> Jan 21 09:53:47 elisonniven pluto[4299]: | v1 peer and cookies match 
> on #1, provided msgid 00000000 vs 00000000
> Jan 21 09:53:47 elisonniven pluto[4299]: | v1 state object #1 found, 
> in STATE_AGGR_R1
> Jan 21 09:53:47 elisonniven pluto[4299]: | processing connection jun
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: packet rejected: 
> should have been encrypted
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: sending 
> notification INVALID_FLAGS to 10.103.2.75:500
> Jan 21 09:53:47 elisonniven pluto[4299]: | sending 40 bytes for 
> notification packet through p18p1:500 to 10.103.2.75:500 (using #1)
> Jan 21 09:53:47 elisonniven pluto[4299]: | * processed 0 messages from 
> cryptographic helpers
> Jan 21 09:53:47 elisonniven pluto[4299]: | next event EVENT_RETRANSMIT 
> in 10 seconds for #1
> Jan 21 09:53:47 elisonniven pluto[4299]: | next event EVENT_RETRANSMIT 
> in 10 seconds for #1
> Jan 21 09:53:47 elisonniven pluto[4299]: |
> Jan 21 09:53:47 elisonniven pluto[4299]: | *received 348 bytes from 
> 10.103.2.75:500 on p18p1 (port=500)
> Jan 21 09:53:47 elisonniven pluto[4299]: |  processing version=1.0 
> packet with exchange type=ISAKMP_XCHG_QUICK (32)
> Jan 21 09:53:47 elisonniven pluto[4299]: | ICOOKIE:  6c 23 d9 65 fa 87 
> ba 23
> Jan 21 09:53:47 elisonniven pluto[4299]: | RCOOKIE:  94 46 8a 37 2d 46 
> ff 8d
> Jan 21 09:53:47 elisonniven pluto[4299]: | state hash entry 23
> Jan 21 09:53:47 elisonniven pluto[4299]: | v1 peer and cookies match 
> on #1, provided msgid e4c27ed0 vs 00000000
> Jan 21 09:53:47 elisonniven pluto[4299]: | v1 state object not found
> Jan 21 09:53:47 elisonniven pluto[4299]: | ICOOKIE:  6c 23 d9 65 fa 87 
> ba 23
> Jan 21 09:53:47 elisonniven pluto[4299]: | RCOOKIE:  94 46 8a 37 2d 46 
> ff 8d
> Jan 21 09:53:47 elisonniven pluto[4299]: | state hash entry 23
> Jan 21 09:53:47 elisonniven pluto[4299]: | v1 peer and cookies match 
> on #1, provided msgid 00000000 vs 00000000
> Jan 21 09:53:47 elisonniven pluto[4299]: | v1 state object #1 found, 
> in STATE_AGGR_R1
> Jan 21 09:53:47 elisonniven pluto[4299]: | processing connection jun
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: Quick Mode message 
> is unacceptable because it is for an incomplete ISAKMP SA
> Jan 21 09:53:47 elisonniven pluto[4299]: | payload malformed after IV
> Jan 21 09:53:47 elisonniven pluto[4299]: |   8d 48 d8 bb  c7 43 10 96  
> a1 f5 f1 52  9d c1 d5 c0
> Jan 21 09:53:47 elisonniven pluto[4299]: |   15 8f be 33
> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: sending 
> notification PAYLOAD_MALFORMED to 10.103.2.75:500
> Jan 21 09:53:47 elisonniven pluto[4299]: | sending 40 bytes for 
> notification packet through p18p1:500 to 10.103.2.75:500 (using #1)
> Jan 21 09:53:47 elisonniven pluto[4299]: | * processed 0 messages from 
> cryptographic helpers
> Jan 21 09:53:47 elisonniven pluto[4299]: | next event EVENT_RETRANSMIT 
> in 10 seconds for #1
> Jan 21 09:53:47 elisonniven pluto[4299]: | next event EVENT_RETRANSMIT 
> in 10 seconds for #1
> Jan 21 09:53:51 elisonniven pluto[4299]: |
> Jan 21 09:53:51 elisonniven pluto[4299]: | *received 348 bytes from 
> 10.103.2.75:500 on p18p1 (port=500)
> Jan 21 09:53:51 elisonniven pluto[4299]: |  processing version=1.0 
> packet with exchange type=ISAKMP_XCHG_QUICK (32)
> Jan 21 09:53:51 elisonniven pluto[4299]: | ICOOKIE:  6c 23 d9 65 fa 87 
> ba 23
> Jan 21 09:53:51 elisonniven pluto[4299]: | RCOOKIE:  94 46 8a 37 2d 46 
> ff 8d
> Jan 21 09:53:51 elisonniven pluto[4299]: | state hash entry 23
> Jan 21 09:53:51 elisonniven pluto[4299]: | v1 peer and cookies match 
> on #1, provided msgid e4c27ed0 vs 00000000
> Jan 21 09:53:51 elisonniven pluto[4299]: | v1 state object not found
> Jan 21 09:53:51 elisonniven pluto[4299]: | ICOOKIE:  6c 23 d9 65 fa 87 
> ba 23
> Jan 21 09:53:51 elisonniven pluto[4299]: | RCOOKIE:  94 46 8a 37 2d 46 
> ff 8d
> Jan 21 09:53:51 elisonniven pluto[4299]: | state hash entry 23
> Jan 21 09:53:51 elisonniven pluto[4299]: | v1 peer and cookies match 
> on #1, provided msgid 00000000 vs 00000000
> Jan 21 09:53:51 elisonniven pluto[4299]: | v1 state object #1 found, 
> in STATE_AGGR_R1
> Jan 21 09:53:51 elisonniven pluto[4299]: | processing connection jun
> Jan 21 09:53:51 elisonniven pluto[4299]: "jun" #1: Quick Mode message 
> is unacceptable because it is for an incomplete ISAKMP SA
> Jan 21 09:53:51 elisonniven pluto[4299]: | payload malformed after IV
> Jan 21 09:53:51 elisonniven pluto[4299]: |   8d 48 d8 bb  c7 43 10 96  
> a1 f5 f1 52  9d c1 d5 c0
> Jan 21 09:53:51 elisonniven pluto[4299]: |   15 8f be 33
> Jan 21 09:53:51 elisonniven pluto[4299]: "jun" #1: sending 
> notification PAYLOAD_MALFORMED to 10.103.2.75:500
> Jan 21 09:53:51 elisonniven pluto[4299]: | sending 40 bytes for 
> notification packet through p18p1:500 to 10.103.2.75:500 (using #1)
> Jan 21 09:53:51 elisonniven pluto[4299]: | * processed 0 messages from 
> cryptographic helpers
> Jan 21 09:53:51 elisonniven pluto[4299]: | next event EVENT_RETRANSMIT 
> in 6 seconds for #1
> Jan 21 09:53:51 elisonniven pluto[4299]: | next event EVENT_RETRANSMIT 
> in 6 seconds for #1
>
> -- 
> Best Regards,
> Elison Niven
>
>



More information about the Swan mailing list