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
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
_______________________________________________ Users mailing list Users@lists.strongswan.org https://lists.strongswan.org/mailman/listinfo/users