[strongSwan] Strongswan connects, but times out immediately and passes no traffic
Alexander Hill
alex at hill.net.au
Mon Jan 23 10:50:04 CET 2017
I was just troubleshooting a remote device (roadwarrior-style config) that
had stopped talking to our server. Rebooting the device fixed the problem,
but I'd like to get to the bottom of it since these devices are hard to get
to physically.
The device was in a strange state where it would apparently complete a
connection, but no traffic would flow and . It would seemingly
authenticate, get assigned an IP address from the pool, but then fail to
actually transmit any traffic, and time out on retransmit attempts.
I've attached a chunk of the log which hopefully shows what was happening.
Both ends are sending and receiving successfully on port 4500.
Fragmentation isn't an issue (I tried enabling it, no dice). Other network
traffic was OK.
Any idea as to what might have caused this?
Thanks,
Alex
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20170123/f8969916/attachment-0001.html>
-------------- next part --------------
Jan 23 16:26:52 KIOSK1 charon: 00[DMN] Starting IKE charon daemon (strongSwan 5.3.5, Linux 4.8.15-040815-generic, x86_64)
Jan 23 16:26:52 KIOSK1 charon: 00[KNL] known interfaces and IP addresses:
Jan 23 16:26:52 KIOSK1 charon: 00[KNL] lo
Jan 23 16:26:52 KIOSK1 charon: 00[KNL] 127.0.0.1
Jan 23 16:26:52 KIOSK1 charon: 00[KNL] ::1
Jan 23 16:26:52 KIOSK1 charon: 00[KNL] wlp1s0
Jan 23 16:26:52 KIOSK1 charon: 00[KNL] AA.AA.6.14
Jan 23 16:26:52 KIOSK1 charon: 00[KNL] fe80::47fc:13d7:3075:e943
Jan 23 16:26:52 KIOSK1 charon: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts'
Jan 23 16:26:52 KIOSK1 charon: 00[CFG] loaded ca certificate "C=AU, O=MyCompany, CN=MyCompany CA" from '/etc/ipsec.d/cacerts/ca-cert.pem'
Jan 23 16:26:52 KIOSK1 charon: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts'
Jan 23 16:26:52 KIOSK1 charon: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Jan 23 16:26:52 KIOSK1 charon: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts'
Jan 23 16:26:52 KIOSK1 charon: 00[CFG] loading crls from '/etc/ipsec.d/crls'
Jan 23 16:26:52 KIOSK1 charon: 00[CFG] loading secrets from '/etc/ipsec.secrets'
Jan 23 16:26:53 KIOSK1 charon: 00[CFG] loaded RSA private key from '/etc/ipsec.d/private/kiosk-key.pem'
Jan 23 16:26:53 KIOSK1 charon: 00[LIB] loaded plugins: charon test-vectors aes rc2 sha1 sha2 md4 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp agent xcbc hmac gcm attr kernel-netlink resolve socket-default connmark stroke updown
Jan 23 16:26:53 KIOSK1 charon: 00[LIB] dropped capabilities, running as uid 0, gid 0
Jan 23 16:26:53 KIOSK1 charon: 00[JOB] spawning 16 worker threads
Jan 23 16:26:53 KIOSK1 charon: 02[NET] waiting for data on sockets
Jan 23 16:26:53 KIOSK1 charon: 04[CFG] received stroke: add connection 'kiosk-client'
Jan 23 16:26:53 KIOSK1 charon: 04[KNL] BB.BB.84.94 is not a local address or the interface is down
Jan 23 16:26:53 KIOSK1 charon: 04[CFG] loaded certificate "C=AU, O=MyCompany, OU=TV, CN=kiosk.mycompany.net" from 'kiosk-cert.pem'
Jan 23 16:26:53 KIOSK1 charon: 04[CFG] added configuration 'kiosk-client'
Jan 23 16:26:53 KIOSK1 charon: 06[CFG] received stroke: initiate 'kiosk-client'
Jan 23 16:26:53 KIOSK1 charon: 06[KNL] using AA.AA.6.14 as address to reach BB.BB.84.94/32
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_VENDOR task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_INIT task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_NATD task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_CERT_PRE task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_AUTH task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_CERT_POST task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_CONFIG task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_AUTH_LIFETIME task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing IKE_MOBIKE task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] queueing CHILD_CREATE task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating new tasks
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_VENDOR task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_INIT task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_NATD task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_CERT_PRE task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_AUTH task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_CERT_POST task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_CONFIG task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating CHILD_CREATE task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_AUTH_LIFETIME task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] activating IKE_MOBIKE task
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] initiating IKE_SA kiosk-client[1] to BB.BB.84.94
Jan 23 16:26:53 KIOSK1 charon: 06[IKE] IKE_SA kiosk-client[1] state change: CREATED => CONNECTING
Jan 23 16:26:53 KIOSK1 charon: 06[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(HASH_ALG) ]
Jan 23 16:26:53 KIOSK1 charon: 06[NET] sending packet: from AA.AA.6.14[500] to BB.BB.84.94[500] (1124 bytes)
Jan 23 16:26:53 KIOSK1 charon: 03[NET] sending packet: from AA.AA.6.14[500] to BB.BB.84.94[500]
Jan 23 16:26:53 KIOSK1 charon: 02[NET] received packet: from BB.BB.84.94[500] to AA.AA.6.14[500]
Jan 23 16:26:53 KIOSK1 charon: 08[NET] received packet: from BB.BB.84.94[500] to AA.AA.6.14[500] (481 bytes)
Jan 23 16:26:53 KIOSK1 charon: 08[ENC] parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(HASH_ALG) N(MULT_AUTH) ]
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] received SIGNATURE_HASH_ALGORITHMS notify
Jan 23 16:26:53 KIOSK1 charon: 02[NET] waiting for data on sockets
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] local host is behind NAT, sending keep alives
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] remote host is behind NAT
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] received cert request for "C=AU, O=MyCompany, CN=MyCompany CA"
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] reinitiating already active tasks
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] IKE_CERT_PRE task
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] IKE_AUTH task
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] sending cert request for "C=AU, O=MyCompany, CN=MyCompany CA"
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] authentication of 'kiosk.mycompany.net' (myself) with RSA_EMSA_PKCS1_SHA384 successful
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] sending end entity cert "C=AU, O=MyCompany, OU=TV, CN=kiosk.mycompany.net"
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] building INTERNAL_IP4_DNS attribute
Jan 23 16:26:53 KIOSK1 charon: 08[IKE] establishing CHILD_SA kiosk-client
Jan 23 16:26:53 KIOSK1 charon: 08[KNL] got SPI c80f1d46
Jan 23 16:26:53 KIOSK1 charon: 08[ENC] generating IKE_AUTH request 1 [ IDi CERT N(INIT_CONTACT) CERTREQ IDr AUTH CPRQ(ADDR DNS) SA TSi TSr N(MOBIKE_SUP) N(NO_ADD_ADDR) N(MULT_AUTH) N(EAP_ONLY) ]
Jan 23 16:26:53 KIOSK1 charon: 08[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500] (2380 bytes)
Jan 23 16:26:53 KIOSK1 charon: 03[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500]
Jan 23 16:26:53 KIOSK1 charon: 02[NET] received packet: from BB.BB.84.94[4500] to AA.AA.6.14[4500]
Jan 23 16:26:53 KIOSK1 charon: 02[NET] waiting for data on sockets
Jan 23 16:26:53 KIOSK1 charon: 09[NET] received packet: from BB.BB.84.94[4500] to AA.AA.6.14[4500] (2172 bytes)
Jan 23 16:26:53 KIOSK1 charon: 09[ENC] parsed IKE_AUTH response 1 [ IDr CERT AUTH CPRP(ADDR) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) ]
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] received end entity cert "C=AU, O=MyCompany, OU=TV, CN=mycompany.net"
Jan 23 16:26:53 KIOSK1 charon: 09[CFG] using certificate "C=AU, O=MyCompany, OU=TV, CN=mycompany.net"
Jan 23 16:26:53 KIOSK1 charon: 09[CFG] using trusted ca certificate "C=AU, O=MyCompany, CN=MyCompany CA"
Jan 23 16:26:53 KIOSK1 charon: 09[CFG] checking certificate status of "C=AU, O=MyCompany, OU=TV, CN=mycompany.net"
Jan 23 16:26:53 KIOSK1 charon: 09[CFG] certificate status is not available
Jan 23 16:26:53 KIOSK1 charon: 09[CFG] reached self-signed root ca with a path length of 0
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] authentication of 'kiosk-endpoint.mycompany.net' with RSA_EMSA_PKCS1_SHA384 successful
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] IKE_SA kiosk-client[1] established between AA.AA.6.14[kiosk.mycompany.net]...BB.BB.84.94[kiosk-endpoint.mycompany.net]
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] IKE_SA kiosk-client[1] state change: CONNECTING => ESTABLISHED
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] scheduling rekeying in 10018s
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] maximum IKE_SA lifetime 10558s
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] processing INTERNAL_IP4_ADDRESS attribute
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] AA.AA.6.14 is on interface wlp1s0
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] installing new virtual IP 172.16.0.10
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] virtual IP 172.16.0.10 installed on lo
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] adding SAD entry with SPI c80f1d46 and reqid {1} (mark 0/0x00000000)
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using encryption algorithm AES_CBC with key size 128
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using integrity algorithm HMAC_SHA1_96 with key size 160
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using replay window of 32 packets
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] adding SAD entry with SPI c266762e and reqid {1} (mark 0/0x00000000)
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using encryption algorithm AES_CBC with key size 128
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using integrity algorithm HMAC_SHA1_96 with key size 160
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using replay window of 32 packets
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] adding policy 172.16.0.10/32 === 172.16.0.0/16 out (mark 0/0x00000000)
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] adding policy 172.16.0.0/16 === 172.16.0.10/32 in (mark 0/0x00000000)
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] adding policy 172.16.0.0/16 === 172.16.0.10/32 fwd (mark 0/0x00000000)
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] getting a local address in traffic selector 172.16.0.10/32
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using host 172.16.0.10
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using 10.61.6.254 as nexthop to reach BB.BB.84.94/32
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] AA.AA.6.14 is on interface wlp1s0
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] installing route: 172.16.0.0/16 via 10.61.6.254 src 172.16.0.10 dev wlp1s0
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] getting iface index for wlp1s0
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] policy 172.16.0.10/32 === 172.16.0.0/16 out (mark 0/0x00000000) already exists, increasing refcount
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] updating policy 172.16.0.10/32 === 172.16.0.0/16 out (mark 0/0x00000000)
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] policy 172.16.0.0/16 === 172.16.0.10/32 in (mark 0/0x00000000) already exists, increasing refcount
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] updating policy 172.16.0.0/16 === 172.16.0.10/32 in (mark 0/0x00000000)
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] policy 172.16.0.0/16 === 172.16.0.10/32 fwd (mark 0/0x00000000) already exists, increasing refcount
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] updating policy 172.16.0.0/16 === 172.16.0.10/32 fwd (mark 0/0x00000000)
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] getting a local address in traffic selector 172.16.0.10/32
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using host 172.16.0.10
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] using 10.61.6.254 as nexthop to reach BB.BB.84.94/32
Jan 23 16:26:53 KIOSK1 charon: 09[KNL] AA.AA.6.14 is on interface wlp1s0
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] CHILD_SA kiosk-client{1} established with SPIs c80f1d46_i c266762e_o and TS 172.16.0.10/32 === 172.16.0.0/16
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] peer supports MOBIKE
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] got additional MOBIKE peer address: 172.16.16.1
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] activating new tasks
Jan 23 16:26:53 KIOSK1 charon: 09[IKE] nothing to initiate
Jan 23 16:26:53 KIOSK1 charon: 13[KNL] virtual IP 172.16.0.10 is on interface lo
Jan 23 16:26:53 KIOSK1 charon: 13[KNL] getting iface index for wlp1s0
Jan 23 16:27:13 KIOSK1 charon: 04[KNL] querying policy 172.16.0.10/32 === 172.16.0.0/16 out (mark 0/0x00000000)
Jan 23 16:27:13 KIOSK1 charon: 04[KNL] querying SAD entry with SPI c266762e (mark 0/0x00000000)
Jan 23 16:27:17 KIOSK1 charon: 07[KNL] querying policy 172.16.0.10/32 === 172.16.0.0/16 out (mark 0/0x00000000)
Jan 23 16:27:17 KIOSK1 charon: 07[KNL] querying SAD entry with SPI c266762e (mark 0/0x00000000)
Jan 23 16:27:17 KIOSK1 charon: 07[IKE] sending keep alive to BB.BB.84.94[4500]
Jan 23 16:27:17 KIOSK1 charon: 03[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500]
Jan 23 16:27:23 KIOSK1 charon: 06[KNL] querying policy 172.16.0.0/16 === 172.16.0.10/32 in (mark 0/0x00000000)
Jan 23 16:27:23 KIOSK1 charon: 06[KNL] querying policy 172.16.0.0/16 === 172.16.0.10/32 fwd (mark 0/0x00000000)
Jan 23 16:27:23 KIOSK1 charon: 06[KNL] querying SAD entry with SPI c80f1d46 (mark 0/0x00000000)
Jan 23 16:27:23 KIOSK1 charon: 06[IKE] sending DPD request
Jan 23 16:27:23 KIOSK1 charon: 06[IKE] queueing IKE_MOBIKE task
Jan 23 16:27:23 KIOSK1 charon: 06[IKE] activating new tasks
Jan 23 16:27:23 KIOSK1 charon: 06[IKE] activating IKE_MOBIKE task
Jan 23 16:27:23 KIOSK1 charon: 06[KNL] using AA.AA.6.14 as address to reach BB.BB.84.94/32
Jan 23 16:27:23 KIOSK1 charon: 06[ENC] generating INFORMATIONAL request 2 [ N(NATD_S_IP) N(NATD_D_IP) ]
Jan 23 16:27:23 KIOSK1 charon: 06[KNL] using AA.AA.6.14 as address to reach BB.BB.84.94/32
Jan 23 16:27:23 KIOSK1 charon: 06[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500] (124 bytes)
Jan 23 16:27:23 KIOSK1 charon: 03[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500]
Jan 23 16:27:27 KIOSK1 charon: 08[IKE] retransmit 1 of request with message ID 2
Jan 23 16:27:27 KIOSK1 charon: 08[KNL] using AA.AA.6.14 as address to reach BB.BB.84.94/32
Jan 23 16:27:27 KIOSK1 charon: 08[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500] (124 bytes)
Jan 23 16:27:27 KIOSK1 charon: 03[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500]
Jan 23 16:27:34 KIOSK1 charon: 10[IKE] retransmit 2 of request with message ID 2
Jan 23 16:27:34 KIOSK1 charon: 10[KNL] using AA.AA.6.14 as address to reach BB.BB.84.94/32
Jan 23 16:27:34 KIOSK1 charon: 10[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500] (124 bytes)
Jan 23 16:27:34 KIOSK1 charon: 03[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500]
Jan 23 16:27:37 KIOSK1 charon: 11[KNL] querying policy 172.16.0.10/32 === 172.16.0.0/16 out (mark 0/0x00000000)
Jan 23 16:27:47 KIOSK1 charon: 12[IKE] retransmit 3 of request with message ID 2
Jan 23 16:27:47 KIOSK1 charon: 12[KNL] using AA.AA.6.14 as address to reach BB.BB.84.94/32
Jan 23 16:27:47 KIOSK1 charon: 12[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500] (124 bytes)
Jan 23 16:27:47 KIOSK1 charon: 03[NET] sending packet: from AA.AA.6.14[4500] to BB.BB.84.94[4500]
...
I manually stopped ipsec at this point, but the pattern is five retransmits and then failure.
On the server you see similar. It's much less clear because there are many clients, but you see a lot of this, followed by retransmits to failure:
Jan 23 16:27:27 kiosk-endpoint charon: 05[ENC] parsed INFORMATIONAL request 2 [ N(NATD_S_IP) N(NATD_D_IP) ]
Jan 23 16:27:27 kiosk-endpoint charon: 05[IKE] received retransmit of request with ID 2, retransmitting response
More information about the Users
mailing list