Project

General

Profile

Issue #3519

Retransmits events

Added by Dave Brody 2 months ago. Updated 2 months ago.

Status:
Feedback
Priority:
Normal
Assignee:
-
Category:
-
Affected version:
5.6.3
Resolution:

Description

I'm confused on the below sequence of events and the timeline of retransmissions that occur -

Client establishes connection at 2:44. Strongwan sends IKE_AUTH response 5 at 2:44 and then following retransmits 2 times at 2:44. It then waits for 4 mins and then sends 3 more retransmits in a row at 6:41. At 6:41 it gives up and considers the client dead. It appears that the retransmits are not following defaults.

Server is ubuntu 16.04 and Strongswan 5.6.3. Client is iOS 13.4.1

2020-07-20T00:02:44.506359880Z 07[IKE] peer requested virtual IP %any6
2020-07-20T00:02:44.506418683Z 07[IKE] no virtual IP found for %any6 requested by 'testc'
2020-07-20T00:02:44.506449876Z 07[IKE] CHILD_SA ikev2-vpn{4} established with SPIs cb373670_i 09084f58_o and TS 0.0.0.0/0 === 10.10.0.2/32
2020-07-20T00:02:44.506457948Z 07[CHD] updown: VERB RUNNING CLIENT: Sun Jul 19 23:58:41 UTC 2020 : up-client : 10.10.0.2/32 : testc : 0.0.0.0/0
2020-07-20T00:02:44.506464697Z 07[CHD] updown: CMD:  Sun Jul 19 23:58:41 UTC 2020 :UP: 10.10.0.2: https://127.0.0.1:6443/slim/index.php/spinupe2?udid=testc&ip=10.10.0.2
2020-07-20T00:02:44.506471870Z 07[CHD] updown: UP: Sun Jul 19 23:58:41 UTC 2020 :UP:
2020-07-20T00:02:44.506478412Z 07[ENC] generating IKE_AUTH response 5 [ AUTH CPRP(ADDR DNS DNS DNS) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(ADD_4_ADDR) ]
2020-07-20T00:02:44.506484727Z 07[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (272 bytes)
2020-07-20T00:02:44.506491146Z 12[IKE] sending DPD request
2020-07-20T00:02:44.506497410Z 12[ENC] generating INFORMATIONAL request 0 [ ]
2020-07-20T00:02:44.506503750Z 12[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (80 bytes)
2020-07-20T00:02:44.506510429Z 13[IKE] retransmit 1 of request with message ID 0
2020-07-20T00:02:44.506517047Z 13[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (80 bytes)
2020-07-20T00:02:44.506523642Z 15[IKE] retransmit 2 of request with message ID 0
2020-07-20T00:06:41.835670640Z 15[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (80 bytes)
2020-07-20T00:06:41.835722136Z 14[IKE] retransmit 3 of request with message ID 0
2020-07-20T00:06:41.835731861Z 14[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (80 bytes)
2020-07-20T00:06:41.835738929Z 05[IKE] retransmit 4 of request with message ID 0
2020-07-20T00:06:41.835746157Z 05[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (80 bytes)
2020-07-20T00:06:41.835753099Z 04[IKE] retransmit 5 of request with message ID 0
2020-07-20T00:06:41.835760026Z 04[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (80 bytes)
2020-07-20T00:06:41.835766976Z 06[IKE] giving up after 5 retransmits
2020-07-20T00:06:41.835774315Z 06[CHD] updown: VERB RUNNING CLIENT: Mon Jul 20 00:05:18 UTC 2020 : down-client : 10.10.0.1/32 : testc : 0.0.0.0/0
2020-07-20T00:06:41.835782410Z 06[CHD] updown: CMD:  Mon Jul 20 00:05:18 UTC 2020 :DOWN: 10.10.0.1: https://127.0.0.1:6443/slim/index.php/spindowniptables?udid=testc&ip=10.10
2020-07-20T00:06:41.835790213Z 06[CHD] updown: .0.1
2020-07-20T00:06:41.835796924Z 06[CHD] updown: UP: Mon Jul 20 00:05:18 UTC 2020 :DOWN:
2020-07-20T00:06:41.835803714Z 06[CFG] lease 10.10.0.1 by 'testc' went offline
2020-07-20T00:06:41.835826831Z 07[NET] received packet: from 192.168.2.101[4500] to 192.168.2.64[4500] (416 bytes)
2020-07-20T00:06:41.835833394Z 07[ENC] parsed CREATE_CHILD_SA request 6 [ SA No KE ]
2020-07-20T00:06:42.686787371Z strongswan stdout | 07[IKE] 192.168.2.101 is initiating an IKE_SA
2020-07-20T00:06:42.686840768Z 07[IKE] IKE_SA ikev2-vpn[10] rekeyed between 192.168.2.64[mdm.vxenetworks.com]...192.168.2.101[192.168.2.101]
2020-07-20T00:06:42.686853942Z 07[ENC] generating CREATE_CHILD_SA response 6 [ SA No KE ]
2020-07-20T00:06:42.686863082Z 07[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (432 bytes)
2020-07-20T00:06:42.686867853Z 09[NET] received packet: from 192.168.2.101[4500] to 192.168.2.64[4500] (80 bytes)
2020-07-20T00:06:42.686874709Z 09[ENC] parsed INFORMATIONAL request 7 [ D ]
2020-07-20T00:06:42.686881109Z 09[IKE] received DELETE for IKE_SA ikev2-vpn[9]
2020-07-20T00:06:42.686890152Z 09[IKE] deleting IKE_SA ikev2-vpn[9] between 192.168.2.64[mdm.vxenetworks.com]...192.168.2.101[192.168.2.101]
2020-07-20T00:06:42.686897056Z 09[IKE] IKE_SA deleted
2020-07-20T00:06:42.686903358Z 09[ENC] generating INFORMATIONAL response 7 [ ]
2020-07-20T00:06:42.686909710Z 09[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (80 bytes)
2020-07-20T00:06:42.686914162Z 10[NET] received packet: from 192.168.2.101[4500] to 192.168.2.64[4500] (512 bytes)
2020-07-20T00:06:42.686920842Z 10[ENC] parsed CREATE_CHILD_SA request 0 [ N(REKEY_SA) SA No KE TSi TSr ]
2020-07-20T00:06:42.686927321Z 10[IKE] ignoring KE exchange, agreed on a non-PFS proposal
2020-07-20T00:06:42.686933682Z 10[IKE] inbound CHILD_SA ikev2-vpn{5} established with SPIs c04f659f_i 0d7c50f2_o and TS 0.0.0.0/0 === 10.10.0.2/32
2020-07-20T00:08:41.696707180Z 10[ENC] generating CREATE_CHILD_SA response 0 [ SA No TSi TSr ]
2020-07-20T00:08:41.696782067Z 10[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (208 bytes)
2020-07-20T00:08:41.696792475Z 12[NET] received packet: from 192.168.2.101[4500] to 192.168.2.64[4500] (80 bytes)
2020-07-20T00:08:41.696799690Z 12[ENC] parsed INFORMATIONAL request 1 [ D ]
2020-07-20T00:08:41.696806569Z 12[IKE] received DELETE for ESP CHILD_SA with SPI 09084f58
2020-07-20T00:08:41.696813237Z 12[IKE] closing CHILD_SA ikev2-vpn{4} with SPIs cb373670_i (98610 bytes) 09084f58_o (0 bytes) and TS 0.0.0.0/0 === 10.10.0.2/32
2020-07-20T00:08:41.696820223Z 12[IKE] sending DELETE for ESP CHILD_SA with SPI cb373670
2020-07-20T00:08:41.696826782Z 12[IKE] CHILD_SA closed
2020-07-20T00:08:41.696833312Z 12[IKE] outbound CHILD_SA ikev2-vpn{5} established with SPIs c04f659f_i 0d7c50f2_o and TS 0.0.0.0/0 === 10.10.0.2/32
2020-07-20T00:08:41.696839863Z 12[ENC] generating INFORMATIONAL response 1 [ D ]
2020-07-20T00:08:41.696846338Z 12[NET] sending packet: from 192.168.2.64[4500] to 192.168.2.101[4500] (80 bytes)
2020-07-20T00:08:41.696853354Z 11[NET] received packet: from 192.168.2.101[4500] to 192.168.2.64[4500] (128 bytes)
2020-07-20T00:08:41.696875269Z 11[ENC] parsed INFORMATIONAL request 2 [ N(NATD_S_IP) N(NATD_D_IP) ]
2020-07-20T00:08:41.696881691Z 11[ENC] generating INFORMATIONAL response 2 [ N(NATD_S_IP) N(NATD_D_IP) ]

History

#1 Updated by Tobias Brunner 2 months ago

  • Description updated (diff)
  • Status changed from New to Feedback

Maybe a problem with the clock on your system or maybe it got suspended for a while.

Also available in: Atom PDF