[Swan] Aggressive mode not possible with Juniper Netscreen

Elison Niven elison.niven at cyberoam.com
Tue Jan 22 14:46:08 EET 2013


Hi,

Great thanks for your time and help.
I still am getting the same error :
Jan 22 18:00:03 elisonniven pluto[24093]: |
Jan 22 18:00:03 elisonniven pluto[24093]: | *received 324 bytes from 
10.103.2.75:500 on p18p1 (port=500)
Jan 22 18:00:03 elisonniven pluto[24093]: |  processing version=1.0 
packet with exchange type=ISAKMP_XCHG_AGGR (4)
Jan 22 18:00:03 elisonniven pluto[24093]: packet from 10.103.2.75:500: 
ignoring unknown Vendor ID payload 
[4a4340b543e02b84c88a8b96a8af9ebe77d9accc0000000b00000500]
Jan 22 18:00:03 elisonniven pluto[24093]: packet from 10.103.2.75:500: 
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
Jan 22 18:00:03 elisonniven pluto[24093]: packet from 10.103.2.75:500: 
ignoring Vendor ID payload [HeartBeat Notify 386b0100]
Jan 22 18:00:03 elisonniven pluto[24093]: | creating state object #3 at 
0x82e5f00
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: Aggressive mode 
peer ID is ID_IPV4_ADDR: '10.103.2.75'
Jan 22 18:00:03 elisonniven pluto[24093]: | started looking for secret 
for 10.103.6.114->10.103.2.75 of kind PPK_PSK
Jan 22 18:00:03 elisonniven pluto[24093]: | actually looking for secret 
for 10.103.6.114->10.103.2.75 of kind PPK_PSK
Jan 22 18:00:03 elisonniven pluto[24093]: | 1: compared key 10.103.2.75 
to 10.103.6.114 / 10.103.2.75 -> 4
Jan 22 18:00:03 elisonniven pluto[24093]: | 2: compared key 
10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 12
Jan 22 18:00:03 elisonniven pluto[24093]: | line 4: match=12
Jan 22 18:00:03 elisonniven pluto[24093]: | best_match 0>12 
best=0x82b5990 (line=4)
Jan 22 18:00:03 elisonniven pluto[24093]: | concluding with 
best_match=12 best=0x82b5990 (lineno=4)
Jan 22 18:00:03 elisonniven pluto[24093]: | offered CA: '%none'
Jan 22 18:00:03 elisonniven pluto[24093]: | processing connection jun
Jan 22 18:00:03 elisonniven pluto[24093]: | ICOOKIE:  77 69 66 f7  66 
35 b1 a7
Jan 22 18:00:03 elisonniven pluto[24093]: | RCOOKIE:  b3 ec 0a ee  8c 
8d 52 1d
Jan 22 18:00:03 elisonniven pluto[24093]: | state hash entry 9
Jan 22 18:00:03 elisonniven pluto[24093]: | inserting state object #3
Jan 22 18:00:03 elisonniven pluto[24093]: | inserting event 
EVENT_SO_DISCARD, timeout in 0 seconds for #3
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: responding to 
Aggressive Mode, state #3, connection "jun" from 10.103.2.75
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: enabling possible 
NAT-traversal with method draft-ietf-ipsec-nat-t-ike-00/01
Jan 22 18:00:03 elisonniven pluto[24093]: | started looking for secret 
for 10.103.6.114->10.103.2.75 of kind PPK_PSK
Jan 22 18:00:03 elisonniven pluto[24093]: | actually looking for secret 
for 10.103.6.114->10.103.2.75 of kind PPK_PSK
Jan 22 18:00:03 elisonniven pluto[24093]: | 1: compared key 10.103.2.75 
to 10.103.6.114 / 10.103.2.75 -> 4
Jan 22 18:00:03 elisonniven pluto[24093]: | 2: compared key 
10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 12
Jan 22 18:00:03 elisonniven pluto[24093]: | line 4: match=12
Jan 22 18:00:03 elisonniven pluto[24093]: | best_match 0>12 
best=0x82b5990 (line=4)
Jan 22 18:00:03 elisonniven pluto[24093]: | concluding with 
best_match=12 best=0x82b5990 (lineno=4)
Jan 22 18:00:03 elisonniven pluto[24093]: | helper -1 doing 
build_kenonce op id: 0
Jan 22 18:00:03 elisonniven pluto[24093]: | processing connection jun
Jan 22 18:00:03 elisonniven pluto[24093]: | started looking for secret 
for 10.103.6.114->10.103.2.75 of kind PPK_PSK
Jan 22 18:00:03 elisonniven pluto[24093]: | actually looking for secret 
for 10.103.6.114->10.103.2.75 of kind PPK_PSK
Jan 22 18:00:03 elisonniven pluto[24093]: | 1: compared key 10.103.2.75 
to 10.103.6.114 / 10.103.2.75 -> 4
Jan 22 18:00:03 elisonniven pluto[24093]: | 2: compared key 
10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 12
Jan 22 18:00:03 elisonniven pluto[24093]: | line 4: match=12
Jan 22 18:00:03 elisonniven pluto[24093]: | best_match 0>12 
best=0x82b5990 (line=4)
Jan 22 18:00:03 elisonniven pluto[24093]: | concluding with 
best_match=12 best=0x82b5990 (lineno=4)
Jan 22 18:00:03 elisonniven pluto[24093]: | parent1 type: 7 group: 2 
len: 2680
Jan 22 18:00:03 elisonniven pluto[24093]: | helper -1 doing compute 
dh+iv op id: 0
Jan 22 18:00:03 elisonniven pluto[24093]: | processing connection jun
Jan 22 18:00:03 elisonniven pluto[24093]: | thinking about whether to 
send my certificate:
Jan 22 18:00:03 elisonniven pluto[24093]: |   I have RSA key: 
OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
Jan 22 18:00:03 elisonniven pluto[24093]: |   sendcert: CERT_ALWAYSSEND 
and I did not get a certificate request
Jan 22 18:00:03 elisonniven pluto[24093]: |   so do not send cert.
Jan 22 18:00:03 elisonniven pluto[24093]: | I did not send a 
certificate because digital signatures are not being used. (PSK)
Jan 22 18:00:03 elisonniven pluto[24093]: |  I am not sending a 
certificate request
Jan 22 18:00:03 elisonniven pluto[24093]: | started looking for secret 
for 10.103.6.114->10.103.2.75 of kind PPK_PSK
Jan 22 18:00:03 elisonniven pluto[24093]: | actually looking for secret 
for 10.103.6.114->10.103.2.75 of kind PPK_PSK
Jan 22 18:00:03 elisonniven pluto[24093]: | 1: compared key 10.103.2.75 
to 10.103.6.114 / 10.103.2.75 -> 4
Jan 22 18:00:03 elisonniven pluto[24093]: | 2: compared key 
10.103.6.114 to 10.103.6.114 / 10.103.2.75 -> 12
Jan 22 18:00:03 elisonniven pluto[24093]: | line 4: match=12
Jan 22 18:00:03 elisonniven pluto[24093]: | best_match 0>12 
best=0x82b5990 (line=4)
Jan 22 18:00:03 elisonniven pluto[24093]: | concluding with 
best_match=12 best=0x82b5990 (lineno=4)
Jan 22 18:00:03 elisonniven pluto[24093]: | complete state transition 
with STF_OK
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: transition from 
state STATE_AGGR_R0 to state STATE_AGGR_R1
Jan 22 18:00:03 elisonniven pluto[24093]: | sending reply packet to 
10.103.2.75:500 (from port 500)
Jan 22 18:00:03 elisonniven pluto[24093]: | sending 356 bytes for 
STATE_AGGR_R0 through p18p1:500 to 10.103.2.75:500 (using #3)
Jan 22 18:00:03 elisonniven pluto[24093]: | inserting event 
EVENT_RETRANSMIT, timeout in 10 seconds for #3
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: STATE_AGGR_R1: sent 
AR1, expecting AI2
Jan 22 18:00:03 elisonniven pluto[24093]: | modecfg pull: noquirk 
policy:push not-client
Jan 22 18:00:03 elisonniven pluto[24093]: | phase 1 is done, looking 
for phase 2 to unpend
Jan 22 18:00:03 elisonniven pluto[24093]: | complete state transition 
with STF_INLINE
Jan 22 18:00:03 elisonniven pluto[24093]: | complete state transition 
with STF_INLINE
Jan 22 18:00:03 elisonniven pluto[24093]: | * processed 0 messages from 
cryptographic helpers
Jan 22 18:00:03 elisonniven pluto[24093]: | next event EVENT_RETRANSMIT 
in 10 seconds for #3
Jan 22 18:00:03 elisonniven pluto[24093]: | next event EVENT_RETRANSMIT 
in 10 seconds for #3
Jan 22 18:00:03 elisonniven pluto[24093]: |
Jan 22 18:00:03 elisonniven pluto[24093]: | *received 100 bytes from 
10.103.2.75:500 on p18p1 (port=500)
Jan 22 18:00:03 elisonniven pluto[24093]: |  processing version=1.0 
packet with exchange type=ISAKMP_XCHG_AGGR (4)
Jan 22 18:00:03 elisonniven pluto[24093]: | ICOOKIE:  77 69 66 f7  66 
35 b1 a7
Jan 22 18:00:03 elisonniven pluto[24093]: | RCOOKIE:  b3 ec 0a ee  8c 
8d 52 1d
Jan 22 18:00:03 elisonniven pluto[24093]: | state hash entry 9
Jan 22 18:00:03 elisonniven pluto[24093]: | v1 peer and cookies match 
on #3, provided msgid 00000000 vs 00000000
Jan 22 18:00:03 elisonniven pluto[24093]: | v1 state object #3 found, 
in STATE_AGGR_R1
Jan 22 18:00:03 elisonniven pluto[24093]: | processing connection jun
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: packet rejected: 
should have been encrypted
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: sending 
notification INVALID_FLAGS to 10.103.2.75:500
Jan 22 18:00:03 elisonniven pluto[24093]: | sending 40 bytes for 
notification packet through p18p1:500 to 10.103.2.75:500 (using #3)
Jan 22 18:00:03 elisonniven pluto[24093]: | * processed 0 messages from 
cryptographic helpers
Jan 22 18:00:03 elisonniven pluto[24093]: | next event EVENT_RETRANSMIT 
in 10 seconds for #3
Jan 22 18:00:03 elisonniven pluto[24093]: | next event EVENT_RETRANSMIT 
in 10 seconds for #3
Jan 22 18:00:03 elisonniven pluto[24093]: |
Jan 22 18:00:03 elisonniven pluto[24093]: | *received 348 bytes from 
10.103.2.75:500 on p18p1 (port=500)
Jan 22 18:00:03 elisonniven pluto[24093]: |  processing version=1.0 
packet with exchange type=ISAKMP_XCHG_QUICK (32)
Jan 22 18:00:03 elisonniven pluto[24093]: | ICOOKIE:  77 69 66 f7  66 
35 b1 a7
Jan 22 18:00:03 elisonniven pluto[24093]: | RCOOKIE:  b3 ec 0a ee  8c 
8d 52 1d
Jan 22 18:00:03 elisonniven pluto[24093]: | state hash entry 9
Jan 22 18:00:03 elisonniven pluto[24093]: | v1 peer and cookies match 
on #3, provided msgid 0ed326db vs 00000000
Jan 22 18:00:03 elisonniven pluto[24093]: | v1 state object not found
Jan 22 18:00:03 elisonniven pluto[24093]: | ICOOKIE:  77 69 66 f7  66 
35 b1 a7
Jan 22 18:00:03 elisonniven pluto[24093]: | RCOOKIE:  b3 ec 0a ee  8c 
8d 52 1d
Jan 22 18:00:03 elisonniven pluto[24093]: | state hash entry 9
Jan 22 18:00:03 elisonniven pluto[24093]: | v1 peer and cookies match 
on #3, provided msgid 00000000 vs 00000000
Jan 22 18:00:03 elisonniven pluto[24093]: | v1 state object #3 found, 
in STATE_AGGR_R1
Jan 22 18:00:03 elisonniven pluto[24093]: | processing connection jun
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: Quick Mode message 
is unacceptable because it is for an incomplete ISAKMP SA
Jan 22 18:00:03 elisonniven pluto[24093]: | payload malformed after IV
Jan 22 18:00:03 elisonniven pluto[24093]: |   ae e2 f9 37  e0 cb 1f 39  
22 b5 53 9b  15 ae 62 df
Jan 22 18:00:03 elisonniven pluto[24093]: |   b7 0a 6b 84
Jan 22 18:00:03 elisonniven pluto[24093]: "jun" #3: sending 
notification PAYLOAD_MALFORMED to 10.103.2.75:500
Jan 22 18:00:03 elisonniven pluto[24093]: | sending 40 bytes for 
notification packet through p18p1:500 to 10.103.2.75:500 (using #3)
Jan 22 18:00:03 elisonniven pluto[24093]: | * processed 0 messages from 
cryptographic helpers
Jan 22 18:00:03 elisonniven pluto[24093]: | next event EVENT_RETRANSMIT 
in 10 seconds for #3
Jan 22 18:00:03 elisonniven pluto[24093]: | next event EVENT_RETRANSMIT 
in 10 seconds for #3


On Tuesday 22 January 2013 05:04:00 PM IST, Philippe Vouters wrote:
> Dear Elison,
>
> Reading the code producing this trace (routine process_v1_packet,
> file: ./libreswan/programs/pluto/ikev1.c):
> Jan 21 09:53:51 elisonniven pluto[4299]: "jun" #1: Quick Mode message
> is unacceptable because it is for an incomplete ISAKMP SA
> which appears AFTER:
> 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
> leads to:
>             if (!IS_ISAKMP_SA_ESTABLISHED(st->st_state))
>             {
>                 loglog(RC_LOG_SERIOUS, "Quick Mode message is
> unacceptable because"
>                     " it is for an incomplete ISAKMP SA");
>                 SEND_NOTIFICATION(PAYLOAD_MALFORMED /* XXX ? */);
>                 return;
>             }
> In consequence, the message "phase 1 is done, looking
> for phase 2 to unpen" apparently seems to be misleading. Anyhow it
> confused me.
>
> Those past days I have been changing IS_PHASE1 to
> IS_ISAKMP_SA_ESTABLISHED inside the above mentioned routine for a
> racoon/iphone issue which highlighted Libreswan not respecting this
> RFC you can read at
> http://www.ietf.org/proceedings/43/I-D/draft-ietf-ipsec-isakmp-mode-cfg-04.txt
>
>
> This Libreswan trace draws all my current attention:
> Jan 21 09:53:47 elisonniven pluto[4299]: | modecfg pull: noquirk
>
> As you rebuilt Libreswan from sources, would you be so kind as to copy
> the original ./libreswan/programs/pluto/ikev1.c file to a safe place,
> patch this file in your Libreswan source tree  with the attached .diff
> and give me news upon how Libreswan now behaves with Netscreen when
> running this patch.
>
> Thanks in advance and regards,
>
> Philippe Vouters (Fontainebleau/France)
> URL: http://vouters.dyndns.org/
> SIP: sip:Vouters at sip.linphone.org
>
> Le 22/01/2013 11:38, Elison Niven a écrit :
>> Hi,
>>
>> Also Phase 1 on Libreswan is not complete as ipsec auto --status does
>> not say that ISAKMP SA established.
>> #ipsec auto --status | tail
>> 000 #527: "jun":500 STATE_AGGR_R1 (sent AR1, expecting AI2);
>> EVENT_RETRANSMIT in 22s; nodpd; idle; import:respond to stranger
>>
>> On Tuesday 22 January 2013 09:28:53 AM IST, Elison Niven wrote:
>>> Hi,
>>>
>>> Thanks.
>>> But then libreswan says:
>>> Jan 21 09:53:47 elisonniven pluto[4299]: "jun" #1: Quick Mode message
>>> is unacceptable because it is for an incomplete ISAKMP SA"
>>>
>>> On Monday 21 January 2013 06:45:50 PM IST, Philippe Vouters wrote:
>>>> I am NOT misleading you at all. Read your traces. Libreswan says this:
>>>>
>>>> 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
>>>>
>>>> So Libreswan is already in phase 2 before it says:
>>>>
>>>> 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)
>>>>
>>>> And you should retrieve this INVALID_FLAGS notification from
>>>> Libnreswan in your Netscreen traces. Set Netscreen to a more
>>>> appropriate log level and you'll find this notification.
>>>>
>>>> Philippe Vouters (Fontainebleau/France)
>>>> URL: http://vouters.dyndns.org/
>>>> SIP: sip:Vouters at sip.linphone.org
>>>>
>>>> Le 21/01/2013 12:01, Elison Niven a écrit :
>>>>> No, you are mistaken.
>>>>> According to Netscreen, Phase 1 is completed.
>>>>> According to Libreswan, Phase 1 is incomplete.
>>>>> These logs are of the Netscreen :
>>>>> 2013-01-18 21:19:38    info    IKE<10.103.6.114> Phase 2: Initiated
>>>>> negotiations.
>>>>>
>>>>> On Monday 21 January 2013 04:26:59 PM IST, Philippe Vouters wrote:
>>>>>> Hi,
>>>>>>
>>>>>> Run Wireshark on the Libreswan side and locate the network packet
>>>>>> coming from Netscreen which is not using the ESP protocol when it
>>>>>> should. According to your Libreswan traces, you are in phase 2.
>>>>>>
>>>>>> 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
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>> --
>>>>> Best Regards,
>>>>> Elison Niven
>>>>>
>>>>>
>>>>
>>>>
>>>>
>>>
>>> --
>>> Best Regards,
>>> Elison Niven
>>>
>>> _______________________________________________
>>> Swan mailing list
>>> Swan at lists.libreswan.org
>>> https://lists.libreswan.org/mailman/listinfo/swan
>>
>> --
>> Best Regards,
>> Elison Niven
>>
>>
>

--
Best Regards,
Elison Niven



More information about the Swan mailing list