[Swan-dev] IPSec restarts intermittently and crashes sometimes, PAYLOAD_MALFORMED issue observed: resend without logs

Rajeev Gaur rajeev.gaur at niyuj.com
Fri Jan 29 10:17:38 UTC 2016


Hi Paul

I have attached "ipsec status" output, do you feel the AUTH algos used here
could be an issue?

Thanks
Rajeev

On Wed, Jan 27, 2016 at 3:57 PM, Rajeev Gaur <rajeev.gaur at niyuj.com> wrote:

> Hi Paul
>
> One request here, did you had chance to look at 24 and 96 site logs?
> Do you find this same behavior being depicted by the logs?
> If yes, in that case, let me see and check "ipsec status".
> But, if you find it different, please do suggest what difference you found.
> Then, I will dig that matter.
>
> Thanks
> Rajeev
>
> On Wed, Jan 27, 2016 at 3:07 AM, Paul Wouters <paul at nohats.ca> wrote:
>
>> On Tue, 26 Jan 2016, Rajeev Gaur wrote:
>>
>> Hi Rajeev,
>>
>> I wrote:
>>
>>       PAYLOAD_MALFORMED message is received quite sometimes.
>>>
>>> That could be because the other end still has state which the restarted
>>> end does not have.
>>>
>>>       process_packet_tail() -> in_struct() -> [%s of %s has an unknown
>>> value = next payload type of ISAKMP Hash Payload has
>>>       an unknown value: 201]
>>>
>>>
>>> It usually signifies an error in PSK/crypto, so the entire message is
>>> garbage. (you can tell too because 201 is not defined, although it
>>> is in the space of "private use" numbers as listed at
>>>
>>>
>>> http://www.iana.org/assignments/ipsec-registry/ipsec-registry.xhtml#ipsec-registry-21
>>>
>>> [RG]:
>>> As I found further the problem is at following place in
>>> programs/pluto/ikev1.c:
>>>
>>>     if (!in_struct(&pd->payload, sd, &md->message_pbs,
>>>                        &pd->pbs)) {
>>>                 loglog(RC_LOG_SERIOUS,
>>>                        "%smalformed payload in packet",
>>>                        excuse);
>>>                 status_update(STATE_PROBABLE_AUTH_FAILURE,
>>> ip_str(&md->sender), md->sender_port);
>>>                 SEND_NOTIFICATION(PAYLOAD_MALFORMED);
>>>                 return;
>>>             }
>>>
>>> What does the status_update as STATE_PROBABLE_AUTH_FAILURE mean here?
>>> Also, I have checked and rechecked PSK and config, I did not found any
>>> issue?
>>> Please suggest something here.
>>>
>>
>> As I said, a mismatching AUTH can use this when using PSK, because the
>> packet will just become something encrypted to the wrong PSK. So it is
>> decrypted but then becomes nonsense, and we can only try to interpret
>> it, which then fails on the first or second payload.
>>
>> Paul
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan-dev/attachments/20160129/e98f462a/attachment.html>
-------------- next part --------------

000 using kernel interface: netkey
000 interface lo/lo ::1
000 interface lo/lo 127.0.0.1
000 interface eth0/eth0 10.50.1.1
000 interface eth1/eth1 <HUB_PUBLIC_IP>
000 %myid = (none)
000 debug none
000
000 virtual_private (%priv):
000 - allowed 0 subnets:
000 - disallowed 0 subnets:
000 WARNING: Either virtual_private= is not specified, or there is a syntax
000          error in that line. 'left/rightsubnet=vhost:%priv' will not work!
000 WARNING: Disallowed subnets in virtual_private= is empty. If you have
000          private address space in internal use, it should be excluded!
000
000 algorithm ESP encrypt: id=2, name=ESP_DES, ivlen=8, keysizemin=64, keysizemax=64
000 algorithm ESP encrypt: id=3, name=ESP_3DES, ivlen=8, keysizemin=192, keysizemax=192
000 algorithm ESP encrypt: id=12, name=ESP_AES, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP encrypt: id=14, name=ESP_AES_CCM_A, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP encrypt: id=15, name=ESP_AES_CCM_B, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP encrypt: id=16, name=ESP_AES_CCM_C, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP encrypt: id=18, name=ESP_AES_GCM_A, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP encrypt: id=19, name=ESP_AES_GCM_B, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP encrypt: id=20, name=ESP_AES_GCM_C, ivlen=8, keysizemin=128, keysizemax=256
000 algorithm ESP auth attr: id=1, name=AUTH_ALGORITHM_HMAC_MD5, keysizemin=128, keysizemax=128
000 algorithm ESP auth attr: id=2, name=AUTH_ALGORITHM_HMAC_SHA1, keysizemin=160, keysizemax=160
000 algorithm ESP auth attr: id=5, name=AUTH_ALGORITHM_HMAC_SHA2_256, keysizemin=256, keysizemax=256
000 algorithm ESP auth attr: id=6, name=AUTH_ALGORITHM_HMAC_SHA2_384, keysizemin=384, keysizemax=384
000 algorithm ESP auth attr: id=7, name=AUTH_ALGORITHM_HMAC_SHA2_512, keysizemin=512, keysizemax=512
000
000 algorithm IKE encrypt: id=0, name=(null), blocksize=16, keydeflen=131
000 algorithm IKE encrypt: id=3, name=OAKLEY_BLOWFISH_CBC, blocksize=8, keydeflen=128
000 algorithm IKE encrypt: id=5, name=OAKLEY_3DES_CBC, blocksize=8, keydeflen=192
000 algorithm IKE encrypt: id=7, name=OAKLEY_AES_CBC, blocksize=16, keydeflen=128
000 algorithm IKE encrypt: id=65004, name=OAKLEY_SERPENT_CBC, blocksize=16, keydeflen=128
000 algorithm IKE encrypt: id=65005, name=OAKLEY_TWOFISH_CBC, blocksize=16, keydeflen=128
000 algorithm IKE encrypt: id=65289, name=OAKLEY_TWOFISH_CBC_SSH, blocksize=16, keydeflen=128
000 algorithm IKE hash: id=1, name=OAKLEY_MD5, hashsize=16
000 algorithm IKE hash: id=2, name=OAKLEY_SHA1, hashsize=20
000 algorithm IKE hash: id=4, name=OAKLEY_SHA2_256, hashsize=32
000 algorithm IKE hash: id=6, name=OAKLEY_SHA2_512, hashsize=64
000 algorithm IKE dh group: id=2, name=OAKLEY_GROUP_MODP1024, bits=1024
000 algorithm IKE dh group: id=5, name=OAKLEY_GROUP_MODP1536, bits=1536
000 algorithm IKE dh group: id=14, name=OAKLEY_GROUP_MODP2048, bits=2048
000 algorithm IKE dh group: id=15, name=OAKLEY_GROUP_MODP3072, bits=3072
000 algorithm IKE dh group: id=16, name=OAKLEY_GROUP_MODP4096, bits=4096
000 algorithm IKE dh group: id=17, name=OAKLEY_GROUP_MODP6144, bits=6144
000 algorithm IKE dh group: id=18, name=OAKLEY_GROUP_MODP8192, bits=8192
000
000 stats db_ops: {curr_cnt, total_cnt, maxsz} :context={0,1101,36} trans={0,1101,540} attrs={0,1101,720}
000
000 "SPOKE1": 10.50.1.0/24===HUB_PUBLIC_IP<HUB_PUBLIC_IP>[+S=C]---HUB_GW...SPOKE_1_PUBLIC_IP<SPOKE_1_PUBLIC_IP>[+S=C]===10.50.2.0/24; erouted; eroute owner: #21007
000 "SPOKE1":     myip=unset; hisip=unset;
000 "SPOKE1":   ike_life: 28800s; ipsec_life: 86400s; rekey_margin: 600s; rekey_fuzz: 20%; keyingtries: 0
000 "SPOKE1":   policy: PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+lKOD+rKOD; prio: 24,24; interface: eth1;
000 "SPOKE1":   dpd: action:restart; delay:10; timeout:120;
000 "SPOKE1":   newest ISAKMP SA: #20984; newest IPsec SA: #21007;
000 "SPOKE1":   IKE algorithms wanted: 3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2); flags=-strict
000 "SPOKE1":   IKE algorithms found:  3DES_CBC(5)_192-SHA1(2)_160-MODP1024(2)
000 "SPOKE1":   IKE algorithm newest: 3DES_CBC_192-SHA1-MODP1024
000 "SPOKE1":   ESP algorithms wanted: AES(12)_128-SHA1(2)_000; flags=-strict
000 "SPOKE1":   ESP algorithms loaded: AES(12)_128-SHA1(2)_160
000 "SPOKE1":   ESP algorithm newest: AES_128-HMAC_SHA1; pfsgroup=<Phase1>

000 "SPOKE2": 10.50.1.0/24===HUB_PUBLIC_IP<HUB_PUBLIC_IP>[+S=C]---HUB_GW...SPOKE_2_PUBLIC_IP<SPOKE_2_PUBLIC_IP>[+S=C]===10.50.4.0/24; erouted HOLD; eroute owner: #0
000 "SPOKE2":     myip=unset; hisip=unset;
000 "SPOKE2":   ike_life: 28800s; ipsec_life: 86400s; rekey_margin: 600s; rekey_fuzz: 20%; keyingtries: 0
000 "SPOKE2":   policy: PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+lKOD+rKOD; prio: 24,24; interface: eth1;
000 "SPOKE2":   dpd: action:restart; delay:10; timeout:120;
000 "SPOKE2":   newest ISAKMP SA: #21208; newest IPsec SA: #0;
000 "SPOKE2":   IKE algorithms wanted: 3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2); flags=-strict
000 "SPOKE2":   IKE algorithms found:  3DES_CBC(5)_192-SHA1(2)_160-MODP1024(2)
000 "SPOKE2":   IKE algorithm newest: 3DES_CBC_192-SHA1-MODP1024
000 "SPOKE2":   ESP algorithms wanted: AES(12)_128-SHA1(2)_000; flags=-strict
000 "SPOKE2":   ESP algorithms loaded: AES(12)_128-SHA1(2)_160

000 "SPOKE3": 10.50.1.0/24===HUB_PUBLIC_IP<HUB_PUBLIC_IP>[+S=C]---174.47.49.241...SPOKE_3_PUBLIC_IP<SPOKE_3_PUBLIC_IP>[+S=C]===10.50.3.0/24; erouted; eroute owner: #20521
000 "SPOKE3":     myip=unset; hisip=unset;
000 "SPOKE3":   ike_life: 28800s; ipsec_life: 86400s; rekey_margin: 600s; rekey_fuzz: 20%; keyingtries: 0
000 "SPOKE3":   policy: PSK+ENCRYPT+TUNNEL+PFS+UP+IKEv2ALLOW+lKOD+rKOD; prio: 24,24; interface: eth1;
000 "SPOKE3":   dpd: action:restart; delay:10; timeout:120;
000 "SPOKE3":   newest ISAKMP SA: #20819; newest IPsec SA: #20521;
000 "SPOKE3":   IKE algorithms wanted: 3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2); flags=-strict
000 "SPOKE3":   IKE algorithms found:  3DES_CBC(5)_192-SHA1(2)_160-MODP1024(2)
000 "SPOKE3":   IKE algorithm newest: 3DES_CBC_192-SHA1-MODP1024
000 "SPOKE3":   ESP algorithms wanted: AES(12)_128-SHA1(2)_000; flags=-strict
000 "SPOKE3":   ESP algorithms loaded: AES(12)_128-SHA1(2)_160
000 "SPOKE3":   ESP algorithm newest: AES_128-HMAC_SHA1; pfsgroup=<Phase1>

000 #21007: "Chestnut_Primary":5074 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 69149s; newest IPSEC; eroute owner; isakmp#20984; idle; import:not set
000 #21007: "Chestnut_Primary" esp.f34045d7 at 65.242.101.94 esp.90732061@<HUB_PUBLIC_IP> tun.0@<SPOKE_1_PUBLIC_IP> tun.0@<HUB_PUBLIC_IP> ref=0 refhim=4294901761
000 #20984: "Chestnut_Primary":5074 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 10250s; newest ISAKMP; lastdpd=15s(seq in:11369 out:0); idle; import:not set
000 #25443: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 9s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25442: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 9s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25441: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 9s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25440: "SPOKE2":20606 STATE_QUICK_I1 (sent QI1, expecting QR1); EVENT_RETRANSMIT in 9s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25439: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 8s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25438: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 8s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25437: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 8s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25436: "SPOKE2":20606 STATE_QUICK_I1 (sent QI1, expecting QR1); EVENT_RETRANSMIT in 8s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25435: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 7s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25434: "SPOKE2":20606 STATE_QUICK_I1 (sent QI1, expecting QR1); EVENT_RETRANSMIT in 7s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25433: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25432: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25431: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25430: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 5s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25429: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 5s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25428: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 5s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25427: "SPOKE2":20606 STATE_QUICK_I1 (sent QI1, expecting QR1); EVENT_RETRANSMIT in 5s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25426: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 4s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25425: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 4s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25424: "SPOKE2":20606 STATE_QUICK_R1 (sent QR1, inbound IPsec SA installed, expecting QI2); EVENT_RETRANSMIT in 4s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25423: "SPOKE2":20606 STATE_QUICK_I1 (sent QI1, expecting QR1); EVENT_RETRANSMIT in 4s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate
000 #25422: "SPOKE2":20606 STATE_QUICK_I1 (sent QI1, expecting QR1); EVENT_RETRANSMIT in 4s; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate



More information about the Swan-dev mailing list