[Swan] disconnect after 3600s
António Silva
asilva at wirelessmundi.com
Tue Jan 26 14:41:03 UTC 2021
Hi Paul,
ikelifetime is 24h, I change salifetime to the same value. It doesn’t disconnect after an hour, but the issue is there..
As for the remote end it is libreswan 3.27, but this start to happen only after upgrading the server to libreswan 3.41.
In the debug when establish for the first time there is the information about the missing certificate:
Jan 25 12:03:56 sol pluto[19224]: | authentication succeeded
Jan 25 12:03:56 sol pluto[19224]: | thinking about whether to send my certificate:
Jan 25 12:03:56 sol pluto[19224]: | I have RSA key: OAKLEY_PRESHARED_KEY cert.type: 0??
Jan 25 12:03:56 sol pluto[19224]: | sendcert: CERT_ALWAYSSEND and I did not get a certificate request
Jan 25 12:03:56 sol pluto[19224]: | so do not send cert.
Jan 25 12:03:56 sol pluto[19224]: | I did not send a certificate because digital signatures are not being used. (PSK)
Jan 25 12:03:56 sol pluto[19224]: | opening output PBS reply packet
Jan 25 12:03:56 sol pluto[19224]: | **emit ISAKMP Message:
Jan 25 12:03:56 sol pluto[19224]: | initiator SPI: 27 e6 51 cd 5e 56 cb eb
Jan 25 12:03:56 sol pluto[19224]: | responder SPI: 5e 32 29 aa 54 2d 89 7e
Jan 25 12:03:56 sol pluto[19224]: | next payload type: ISAKMP_NEXT_NONE (0x0)
Jan 25 12:03:56 sol pluto[19224]: | ISAKMP version: ISAKMP Version 1.0 (rfc2407) (0x10)
Jan 25 12:03:56 sol pluto[19224]: | exchange type: ISAKMP_XCHG_IDPROT (0x2)
Jan 25 12:03:56 sol pluto[19224]: | flags: ISAKMP_FLAG_v1_ENCRYPTION (0x1)
Jan 25 12:03:56 sol pluto[19224]: | Message ID: 0 (00 00 00 00)
Jan 25 12:03:56 sol pluto[19224]: | next payload chain: saving message location 'ISAKMP Message'.'next payload type’
But it does establish the connection.
Then after 1h, the log after the authentication is successful and it fail on “CERTIFICATE_UNAVAILABLE”.
n 25 12:59:26 sol pluto[19224]: "tunnel8"[6] 95.61.168.133 #24: XAUTH: User asilvapt at remote.local: Authentication Successful
Jan 25 12:59:26 sol pluto[19224]: | opening output PBS xauth_buf
Jan 25 12:59:26 sol pluto[19224]: | **emit ISAKMP Message:
Jan 25 12:59:26 sol pluto[19224]: | initiator SPI: 66 6a 3c 3e 85 e9 f9 6d
Jan 25 12:59:26 sol pluto[19224]: | responder SPI: 7c 4c 08 f8 93 21 f7 2a
Jan 25 12:59:26 sol pluto[19224]: | next payload type: ISAKMP_NEXT_NONE (0x0)
Jan 25 12:59:26 sol pluto[19224]: | ISAKMP version: ISAKMP Version 1.0 (rfc2407) (0x10)
Jan 25 12:59:26 sol pluto[19224]: | exchange type: ISAKMP_XCHG_MODE_CFG (0x6)
Jan 25 12:59:26 sol pluto[19224]: | flags: ISAKMP_FLAG_v1_ENCRYPTION (0x1)
Jan 25 12:59:26 sol pluto[19224]: | Message ID: 1337103569 (4f b2 94 d1)
Jan 25 12:59:26 sol pluto[19224]: | next payload chain: saving message location 'ISAKMP Message'.'next payload type'
Jan 25 12:59:26 sol pluto[19224]: | ***emit ISAKMP Hash Payload:
Jan 25 12:59:26 sol pluto[19224]: | next payload type: ISAKMP_NEXT_NONE (0x0)
Jan 25 12:59:26 sol pluto[19224]: | next payload chain: setting previous 'ISAKMP Message'.'next payload type' to current ISAKMP Hash Payload (8:ISAKMP_NEXT_HASH)
Jan 25 12:59:26 sol pluto[19224]: | next payload chain: saving location 'ISAKMP Hash Payload'.'next payload type' in 'xauth_buf'
Jan 25 12:59:26 sol pluto[19224]: | emitting 32 zero bytes of HASH DATA into ISAKMP Hash Payload
Jan 25 12:59:26 sol pluto[19224]: | emitting length of ISAKMP Hash Payload: 36
Jan 25 12:59:26 sol pluto[19224]: | ***emit ISAKMP Mode Attribute:
Jan 25 12:59:26 sol pluto[19224]: | next payload type: ISAKMP_NEXT_NONE (0x0)
Jan 25 12:59:26 sol pluto[19224]: | Attr Msg Type: ISAKMP_CFG_SET (0x3)
Jan 25 12:59:26 sol pluto[19224]: | Identifier: 0 (00 00)
Jan 25 12:59:26 sol pluto[19224]: | next payload chain: setting previous 'ISAKMP Hash Payload'.'next payload type' to current ISAKMP Mode Attribute (14:ISAKMP_NEXT_MODECFG)
Jan 25 12:59:26 sol pluto[19224]: | next payload chain: saving location 'ISAKMP Mode Attribute'.'next payload type' in 'xauth_buf'
Jan 25 12:59:26 sol pluto[19224]: | ****emit ISAKMP ModeCfg attribute:
Jan 25 12:59:26 sol pluto[19224]: | ModeCfg attr type: AF+XAUTH-STATUS (0xc08f)
Jan 25 12:59:26 sol pluto[19224]: | length/value: 1 (00 01)
Jan 25 12:59:26 sol pluto[19224]: | no IKEv1 message padding required
Jan 25 12:59:26 sol pluto[19224]: | emitting length of ISAKMP Mode Attribute: 12
Jan 25 12:59:26 sol pluto[19224]: | XAUTH: status HASH(1):
Jan 25 12:59:26 sol pluto[19224]: | 3a 1b b0 42 f5 9e 74 ce ee 4d 35 ac 28 72 99 52
Jan 25 12:59:26 sol pluto[19224]: | a0 e8 1d 79 87 eb e4 be 67 9f 2e f8 15 d6 be 9c
Jan 25 12:59:26 sol pluto[19224]: | no IKEv1 message padding required
Jan 25 12:59:26 sol pluto[19224]: | emitting length of ISAKMP Message: 76
Jan 25 12:59:26 sol pluto[19224]: | no IKEv1 message padding required
Jan 25 12:59:26 sol pluto[19224]: | emitting length of ISAKMP Message: 76
Jan 25 12:59:26 sol pluto[19224]: | state #24 has no .st_event to delete
Jan 25 12:59:26 sol pluto[19224]: | #24 STATE_XAUTH_R0: retransmits: cleared
Jan 25 12:59:26 sol pluto[19224]: | event_schedule: newref EVENT_RETRANSMIT-pe at 0x55a5339d7158
Jan 25 12:59:26 sol pluto[19224]: | inserting event EVENT_RETRANSMIT, timeout in 0.5 seconds for #24
Jan 25 12:59:26 sol pluto[19224]: | libevent_malloc: newref ptr-libevent at 0x55a5339c0148 size 128
Jan 25 12:59:26 sol pluto[19224]: | #24 STATE_XAUTH_R0: retransmits: first event in 0.5 seconds; timeout in 60 seconds; limit of 12 retransmits; current time is 333161.099021
Jan 25 12:59:26 sol pluto[19224]: | sending 80 bytes for XAUTH: status through pppeth2.24 from 92.211.123.17:4500 to 95.61.168.133:4500 using UDP (for #24)
Jan 25 12:59:26 sol pluto[19224]: | 00 00 00 00 66 6a 3c 3e 85 e9 f9 6d 7c 4c 08 f8
Jan 25 12:59:26 sol pluto[19224]: | 93 21 f7 2a 08 10 06 01 4f b2 94 d1 00 00 00 4c
Jan 25 12:59:26 sol pluto[19224]: | e2 5d 4b 96 00 3d 44 96 0a 70 03 93 20 3b 31 93
Jan 25 12:59:26 sol pluto[19224]: | 91 15 5e 42 d7 2d 36 9f b9 d2 ed ed b1 74 97 d4
Jan 25 12:59:26 sol pluto[19224]: | 87 91 46 64 43 9b 76 c6 f4 9c 9d ca 62 1a e7 70
Jan 25 12:59:26 sol pluto[19224]: | parent state #24: XAUTH_R0(established IKE SA) => XAUTH_R1(established IKE SA)
Jan 25 12:59:26 sol pluto[19224]: | resume xauth immediate for #24 suppresed complete_v1_state_transition()
Jan 25 12:59:26 sol pluto[19224]: | delref mdp at 0x55a5339c0448(1->0) (in resume_handler() at server.c:731)
Jan 25 12:59:26 sol pluto[19224]: | delref fd at NULL (in free_logger() at log.c:845)
Jan 25 12:59:26 sol pluto[19224]: | delref fd at NULL (in free_logger() at log.c:846)
Jan 25 12:59:26 sol pluto[19224]: | #24 spent 0.261 (0.261) milliseconds in resume xauth immediate
Jan 25 12:59:26 sol pluto[19224]: | stop processing: state #24 connection "tunnel8"[6] 95.61.168.133 from 95.61.168.133:4500 (in resume_handler() at server.c:733)
Jan 25 12:59:26 sol pluto[19224]: | libevent_free: delref ptr-libevent at 0x55a5339f5538
Jan 25 12:59:26 sol pluto[19224]: | spent 0.00237 (0.00237) milliseconds in udp_read_packet() calling check_incoming_msg_errqueue()
Jan 25 12:59:26 sol pluto[19224]: | newref md at 0x55a5339c0448(0->1) (in read_message() at demux.c:103)
Jan 25 12:59:26 sol pluto[19224]: | *received 76 bytes from 95.61.168.133:4500 on pppeth2.24 92.211.123.17:4500 using UDP
Jan 25 12:59:26 sol pluto[19224]: | 43 9f 57 5d 9d 4e b0 ae b2 23 af 61 43 7d 07 5d
Jan 25 12:59:26 sol pluto[19224]: | 08 10 05 01 19 09 57 d3 00 00 00 4c 44 ce 04 7d
Jan 25 12:59:26 sol pluto[19224]: | 2a 61 eb df 62 1f 8c 41 5a d3 1e 58 d6 6a e3 fa
Jan 25 12:59:26 sol pluto[19224]: | f1 7e 8b 9d ae ac b7 69 d4 cb 98 a7 bb 71 ed 4d
Jan 25 12:59:26 sol pluto[19224]: | ee 58 47 54 c8 45 42 0f 4e 09 16 c3
Jan 25 12:59:26 sol pluto[19224]: | **parse ISAKMP Message:
Jan 25 12:59:26 sol pluto[19224]: | initiator SPI: 43 9f 57 5d 9d 4e b0 ae
Jan 25 12:59:26 sol pluto[19224]: | responder SPI: b2 23 af 61 43 7d 07 5d
Jan 25 12:59:26 sol pluto[19224]: | next payload type: ISAKMP_NEXT_HASH (0x8)
Jan 25 12:59:26 sol pluto[19224]: | ISAKMP version: ISAKMP Version 1.0 (rfc2407) (0x10)
Jan 25 12:59:26 sol pluto[19224]: | exchange type: ISAKMP_XCHG_INFO (0x5)
Jan 25 12:59:26 sol pluto[19224]: | flags: ISAKMP_FLAG_v1_ENCRYPTION (0x1)
Jan 25 12:59:26 sol pluto[19224]: | Message ID: 420042707 (19 09 57 d3)
Jan 25 12:59:26 sol pluto[19224]: | length: 76 (00 00 00 4c)
Jan 25 12:59:26 sol pluto[19224]: | processing version=1.0 packet with exchange type=ISAKMP_XCHG_INFO (5)
Jan 25 12:59:26 sol pluto[19224]: | peer and cookies match on #23; msgid=00000000 st_msgid=00000000 st_v1_msgid.phase15=b9ea6076
Jan 25 12:59:26 sol pluto[19224]: | p15 state object #23 found, in STATE_XAUTH_R0
Jan 25 12:59:26 sol pluto[19224]: | State DB: found IKEv1 state #23 in XAUTH_R0 (find_v1_info_state)
Jan 25 12:59:26 sol pluto[19224]: | start processing: state #23 connection "tunnel8"[6] 95.61.168.133 from 95.61.168.133:4500 (in process_v1_packet() at ikev1.c:1378)
Jan 25 12:59:26 sol pluto[19224]: | #23 is idle
Jan 25 12:59:26 sol pluto[19224]: | #23 idle
Jan 25 12:59:26 sol pluto[19224]: | received encrypted packet from 95.61.168.133:4500
Jan 25 12:59:26 sol pluto[19224]: | got payload 0x100 (ISAKMP_NEXT_HASH) needed: 0x100 opt: 0x0
Jan 25 12:59:26 sol pluto[19224]: | ***parse ISAKMP Hash Payload:
Jan 25 12:59:26 sol pluto[19224]: | next payload type: ISAKMP_NEXT_N (0xb)
Jan 25 12:59:26 sol pluto[19224]: | length: 36 (00 24)
Jan 25 12:59:26 sol pluto[19224]: | got payload 0x800 (ISAKMP_NEXT_N) needed: 0x0 opt: 0x0
Jan 25 12:59:26 sol pluto[19224]: | ***parse ISAKMP Notification Payload:
Jan 25 12:59:26 sol pluto[19224]: | next payload type: ISAKMP_NEXT_NONE (0x0)
Jan 25 12:59:26 sol pluto[19224]: | length: 12 (00 0c)
Jan 25 12:59:26 sol pluto[19224]: | DOI: ISAKMP_DOI_IPSEC (0x1)
Jan 25 12:59:26 sol pluto[19224]: | protocol ID: 1 (01)
Jan 25 12:59:26 sol pluto[19224]: | SPI size: 0 (00)
Jan 25 12:59:26 sol pluto[19224]: | Notify Message Type: CERTIFICATE_UNAVAILABLE (0x1c)
Jan 25 12:59:26 sol pluto[19224]: | informational HASH(1):
Jan 25 12:59:26 sol pluto[19224]: | 25 d1 55 70 1c c9 ce 35 cd 7f 09 23 8e 45 4b c4
Jan 25 12:59:26 sol pluto[19224]: | ed 88 2e 3f ee bd 06 1c b0 c0 f0 14 43 41 f8 eb
Jan 25 12:59:26 sol pluto[19224]: | received 'informational' message HASH(1) data ok
Jan 25 12:59:26 sol pluto[19224]: "tunnel8"[6] 95.61.168.133 #23: ignoring informational payload CERTIFICATE_UNAVAILABLE, msgid=00000000, length=12
I’ve the full log if you need more info.
Thanks.
--
Saludos / Regards / Cumprimentos
António Silva
> On 25 Jan 2021, at 16:47, Paul Wouters <paul at nohats.ca> wrote:
>
> On Mon, 25 Jan 2021, Kontakt wrote:
>
>> what about my case? ;)
>> I have no certificate and also disconnects - I have PSK.
>
> Please set ikelifetime=24h as well ? This is the default value in
> libreswan 4.2 (which is pending release)
>
> Paul
>
>> pon., 25 sty 2021 o 16:05 Paul Wouters <paul at nohats.ca> napisał(a):
>> On Mon, 25 Jan 2021, António Silva wrote:
>>
>> > I’m using PSK.
>>
>> > Putting extra debug now.
>>
>> If you are using PSK then the error CERTIFICATE_UNAVAILABLE from the
>> remote peer makes no sense whatsoevef.
>>
>> RFC 2408 states:
>>
>> 3. Process the Certificate Request. If a requested Certificate Type
>> with the specified Certificate Authority is not available, then
>> the payload is discarded and the following actions are taken:
>>
>> (a) The event, CERTIFICATE-UNAVAILABLE, MAY be logged in the
>> appropriate system audit file.
>>
>> (b) An Informational Exchange with a Notification payload
>> containing the CERTIFICATE-UNAVAILABLE message type MAY be
>> sent to the transmitting entity. This action is dictated by
>> a system security policy.
>>
>> I guess your debugging will show if libreswan sent any CERT or CERTREQ
>> payload that might have confused the other end ?
>>
>> Paul
>> _______________________________________________
>> Swan mailing list
>> Swan at lists.libreswan.org
>> https://lists.libreswan.org/mailman/listinfo/swan
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20210126/9292cbfd/attachment-0001.html>
More information about the Swan
mailing list