[Swan] Aggressive mode not possible with Juniper Netscreen

Philippe Vouters philippe.vouters at laposte.net
Tue Jan 22 15:41:38 EET 2013


Dear Elison,

Reading the source code, it appears obvious that this trace:
modecfg pull: noquirk policy:push not-client
I focused onto has no importance other than partially showing how you 
did configure your Libreswan connection.

However and to be able to follow the code path with leads to the 
STF_INLINE return (routine aggr_inR1_outI2_tail, file: 
programs/pluto/ikev1_aggr.c), would you be so kind as to recall me how 
you did configure your Libreswan connection supposed to match Netscreen 
? My expressed need is very relevant in your case as per a first look to 
this routine.

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

Le 22/01/2013 14:09, Philippe Vouters a écrit :
> Dear Elison,
>
> What I shall be focusing onto is the STF_INLINE return after Aggregate 
> R1 expecting Aggregate I2.
> 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
>
> What I do also wonder from your trace is the real importance which can 
> be given to this trace I previously focused onto which led me to send 
> you the patch.
> Jan 22 18:00:03 elisonniven pluto[24093]: | modecfg pull: noquirk 
> policy:push not-client
>
> A question to you to make absolutely sure. Was this last trace indeed 
> produced with the patch I sent you applied ??? I do not observe much 
> difference in the behaviour with previous.
>
> Philippe Vouters (Fontainebleau/France)
> URL: http://vouters.dyndns.org/
> SIP: sip:Vouters at sip.linphone.org
> Le 22/01/2013 13:46, Elison Niven a écrit :
>> 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