Issue #1439
Reauthentication fails with load-tester plugin
Status:
Closed
Priority:
Normal
Assignee:
-
Category:
-
Affected version:
5.3.0
Resolution:
No feedback
Description
Hi
This Reauthentication failure is seen only on my customised setup. But still, the basic ikev2/ikev1 works fine here.
Reauthentication fails arbitrarily after 3 or 4 successful reauths. But it works fine without load-tester.
Rekeying is always fine.
Responder: syslog error message:
Apr 27 14:18:40 cavium-NCD charon: 14[IKE] initiator did not reauthenticate as requested Apr 27 14:18:40 cavium-NCD charon: 14[IKE] IKE_SA rw[2] will timeout in 3 seconds Apr 27 14:18:40 cavium-NCD charon: 05[NET] received packet: from 192.168.10.2[500] to 192.168.10.1[500] (76 bytes) Apr 27 14:18:40 cavium-NCD charon: 05[ENC] parsed INFORMATIONAL request 2 [ D ] Apr 27 14:18:40 cavium-NCD charon: 05[IKE] received DELETE for IKE_SA rw[2] Apr 27 14:18:40 cavium-NCD charon: 05[IKE] deleting IKE_SA rw[2] between 192.168.10.1[CN=srv, OU=load-test, O=strongSwan]...192.168.10.2[CN=c2-r1, OU=load-test, O=strongSwan] Apr 27 14:18:40 cavium-NCD charon: 05[IKE] IKE_SA deleted Apr 27 14:18:40 cavium-NCD vpn: - CN=c2-r1, OU=load-test, O=strongSwan 10.3.10.1/32 == 192.168.10.2 -- 192.168.10.1 == 10.1.0.0/16 Apr 27 14:18:40 cavium-NCD charon: 05[ENC] generating INFORMATIONAL response 2 [ ] Apr 27 14:18:40 cavium-NCD charon: 05[NET] sending packet: from 192.168.10.1[500] to 192.168.10.2[500] (76 bytes) Apr 27 14:18:40 cavium-NCD charon: 15[NET] received packet: from 192.168.10.2[500] to 192.168.10.1[500] (320 bytes) Apr 27 14:18:40 cavium-NCD charon: 15[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(HASH_ALG) ] Apr 27 14:18:40 cavium-NCD charon: 15[IKE] 192.168.10.2 is initiating an IKE_SA Apr 27 14:18:40 cavium-NCD charon: 15[IKE] sending cert request for "CN=srv, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 15[IKE] sending cert request for "CN=srv, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 15[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(HASH_ALG) N(MULT_AUTH) ] Apr 27 14:18:40 cavium-NCD charon: 15[NET] sending packet: from 192.168.10.1[500] to 192.168.10.2[500] (373 bytes) Apr 27 14:18:40 cavium-NCD charon: 07[NET] received packet: from 192.168.10.2[500] to 192.168.10.1[500] (1068 bytes) Apr 27 14:18:40 cavium-NCD charon: 07[ENC] parsed IKE_AUTH request 1 [ IDi CERT CERTREQ IDr AUTH CPRQ(ADDR) N(ESP_TFC_PAD_N) SA TSi TSr N(MULT_AUTH) N(EAP_ONLY) ] Apr 27 14:18:40 cavium-NCD charon: 07[IKE] received cert request for "CN=srv, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 07[IKE] received cert request for "CN=srv, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 07[IKE] received end entity cert "CN=c2-r1, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 07[CFG] looking for peer configs matching 192.168.10.1[CN=srv, OU=load-test, O=strongSwan]...192.168.10.2[CN=c2-r1, OU=load-test, O=strongSwan] Apr 27 14:18:40 cavium-NCD charon: 07[CFG] selected peer config 'rw' Apr 27 14:18:40 cavium-NCD charon: 07[CFG] using certificate "CN=c2-r1, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 07[CFG] using trusted ca certificate "CN=srv, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 07[CFG] checking certificate status of "CN=c2-r1, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 07[CFG] certificate status is not available Apr 27 14:18:40 cavium-NCD charon: 07[CFG] reached self-signed root ca with a path length of 0 Apr 27 14:18:40 cavium-NCD charon: 07[IKE] authentication of 'CN=c2-r1, OU=load-test, O=strongSwan' with RSA_EMSA_PKCS1_SHA256 successful Apr 27 14:18:40 cavium-NCD charon: 07[IKE] received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding Apr 27 14:18:40 cavium-NCD charon: 07[IKE] authentication of 'CN=srv, OU=load-test, O=strongSwan' (myself) with RSA_EMSA_PKCS1_SHA256 successful Apr 27 14:18:40 cavium-NCD charon: 07[IKE] IKE_SA rw[3] established between 192.168.10.1[CN=srv, OU=load-test, O=strongSwan]...192.168.10.2[CN=c2-r1, OU=load-test, O=strongSwan] Apr 27 14:18:40 cavium-NCD charon: 07[IKE] scheduling reauthentication in 117s Apr 27 14:18:40 cavium-NCD charon: 07[IKE] maximum IKE_SA lifetime 120s Apr 27 14:18:40 cavium-NCD charon: 07[IKE] sending end entity cert "CN=srv, OU=load-test, O=strongSwan" Apr 27 14:18:40 cavium-NCD charon: 07[IKE] peer requested virtual IP 10.3.10.1 Apr 27 14:18:40 cavium-NCD charon: 07[CFG] reassigning online lease to 'CN=c2-r1, OU=load-test, O=strongSwan' Apr 27 14:18:40 cavium-NCD charon: 07[IKE] assigning virtual IP 10.3.10.1 to peer 'CN=c2-r1, OU=load-test, O=strongSwan' Apr 27 14:18:40 cavium-NCD charon: 07[KNL] unable to add policy: File exists (17) Apr 27 14:18:40 cavium-NCD charon: 07[KNL] unable to add policy 10.3.10.1/32 === 10.1.0.0/16 in Apr 27 14:18:40 cavium-NCD charon: 07[KNL] error sending to PF_KEY socket: Operation not permitted Apr 27 14:18:40 cavium-NCD charon: 07[KNL] unable to update policy 10.3.10.1/32 === 10.1.0.0/16 in Apr 27 14:18:40 cavium-NCD charon: 07[IKE] unable to install IPsec policies (SPD) in kernel Apr 27 14:18:40 cavium-NCD charon: 07[IKE] failed to establish CHILD_SA, keeping IKE_SA Apr 27 14:18:40 cavium-NCD kernel: [164821.583744] policy handle failed to be found Apr 27 14:18:40 cavium-NCD charon: 07[KNL] error sending to PF_KEY socket: Operation not permitted Apr 27 14:18:40 cavium-NCD charon: 07[KNL] unable to update policy 10.3.10.1/32 === 10.1.0.0/16 in Apr 27 14:18:40 cavium-NCD kernel: [164821.587752] policy handle failed to be found Apr 27 14:18:40 cavium-NCD charon: 07[KNL] unable to delete policy 10.3.10.1/32 === 10.1.0.0/16 in: No such file or directory (2) Apr 27 14:18:40 cavium-NCD kernel: [164821.591786] policy handle failed to be found Apr 27 14:18:40 cavium-NCD charon: 07[ENC] generating IKE_AUTH response 1 [ IDr CERT AUTH CPRP(ADDR) N(AUTH_LFT) N(TS_UNACCEPT) ] Apr 27 14:18:40 cavium-NCD charon: 07[NET] sending packet: from 192.168.10.1[500] to 192.168.10.2[500] (828 bytes)
Initiator: error syslog:
Apr 27 14:18:46 ubnt-113 charon: 27[IKE] reauthenticating IKE_SA load-test[2]
Apr 27 14:18:46 ubnt-113 charon: 27[IKE] deleting IKE_SA load-test[2] between 192.168.10.2[CN=c2-r1, OU=load-test, O=strongSwan]...192.168.10.1[CN=srv, OU=load-test, O=strongSwan]
Apr 27 14:18:46 ubnt-113 charon: 27[IKE] sending DELETE for IKE_SA load-test[2]
Apr 27 14:18:46 ubnt-113 charon: 27[ENC] generating INFORMATIONAL request 2 [ D ]
Apr 27 14:18:46 ubnt-113 charon: 27[NET] sending packet: from 192.168.10.2[500] to 192.168.10.1[500] (76 bytes)
Apr 27 14:18:46 ubnt-113 charon: 29[NET] received packet: from 192.168.10.1[500] to 192.168.10.2[500] (76 bytes)
Apr 27 14:18:46 ubnt-113 charon: 29[ENC] parsed INFORMATIONAL response 2 [ ]
Apr 27 14:18:46 ubnt-113 charon: 29[IKE] IKE_SA deleted
Apr 27 14:18:46 ubnt-113 charon: 29[IKE] installing new virtual IP 10.3.10.1
Apr 27 14:18:46 ubnt-113 charon: 29[IKE] restarting CHILD_SA load-test
Apr 27 14:18:46 ubnt-113 charon: 29[IKE] initiating IKE_SA load-test[3] to 192.168.10.1
Apr 27 14:18:46 ubnt-113 charon: 29[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(HASH_ALG) ]
Apr 27 14:18:46 ubnt-113 charon: 29[NET] sending packet: from 192.168.10.2[500] to 192.168.10.1[500] (320 bytes)
Apr 27 14:18:46 ubnt-113 charon: 30[NET] received packet: from 192.168.10.1[500] to 192.168.10.2[500] (373 bytes)
Apr 27 14:18:46 ubnt-113 charon: 30[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) ]
Apr 27 14:18:46 ubnt-113 charon: 30[IKE] received cert request for "CN=srv, OU=load-test, O=strongSwan"
Apr 27 14:18:46 ubnt-113 charon: 30[IKE] received cert request for "CN=srv, OU=load-test, O=strongSwan"
Apr 27 14:18:46 ubnt-113 charon: 30[IKE] sending cert request for "CN=srv, OU=load-test, O=strongSwan"
Apr 27 14:18:46 ubnt-113 charon: 30[IKE] sending cert request for "CN=srv, OU=load-test, O=strongSwan"
Apr 27 14:18:46 ubnt-113 charon: 30[IKE] authentication of 'CN=c2-r1, OU=load-test, O=strongSwan' (myself) with RSA_EMSA_PKCS1_SHA256 successful
Apr 27 14:18:46 ubnt-113 charon: 30[IKE] sending end entity cert "CN=c2-r1, OU=load-test, O=strongSwan"
Apr 27 14:18:46 ubnt-113 charon: 30[IKE] establishing CHILD_SA load-test{2}
Apr 27 14:18:46 ubnt-113 charon: 30[ENC] generating IKE_AUTH request 1 [ IDi CERT CERTREQ IDr AUTH CPRQ(ADDR) N(ESP_TFC_PAD_N) SA TSi TSr N(MULT_AUTH) N(EAP_ONLY) ]
Apr 27 14:18:46 ubnt-113 charon: 30[NET] sending packet: from 192.168.10.2[500] to 192.168.10.1[500] (1068 bytes)
Apr 27 14:18:46 ubnt-113 charon: 14[NET] received packet: from 192.168.10.1[500] to 192.168.10.2[500] (828 bytes)
Apr 27 14:18:46 ubnt-113 charon: 14[ENC] parsed IKE_AUTH response 1 [ IDr CERT AUTH CPRP(ADDR) N(AUTH_LFT) N(TS_UNACCEPT) ]
Apr 27 14:18:46 ubnt-113 charon: 14[IKE] received end entity cert "CN=srv, OU=load-test, O=strongSwan"
Apr 27 14:18:46 ubnt-113 charon: 14[CFG] using trusted certificate "CN=srv, OU=load-test, O=strongSwan"
Apr 27 14:18:46 ubnt-113 charon: 14[IKE] authentication of 'CN=srv, OU=load-test, O=strongSwan' with RSA_EMSA_PKCS1_SHA256 successful
Apr 27 14:18:46 ubnt-113 charon: 14[IKE] IKE_SA load-test[3] established between 192.168.10.2[CN=c2-r1, OU=load-test, O=strongSwan]...192.168.10.1[CN=srv, OU=load-test, O=strongSwan]
Apr 27 14:18:46 ubnt-113 charon: 14[IKE] installing new virtual IP 10.3.10.1
Apr 27 14:18:46 ubnt-113 charon: 14[IKE] received TS_UNACCEPTABLE notify, no CHILD_SA built
Apr 27 14:18:46 ubnt-113 charon: 14[IKE] failed to establish CHILD_SA, keeping IKE_SA
Apr 27 14:18:46 ubnt-113 charon: 14[IKE] received AUTH_LIFETIME of 117s, scheduling reauthentication in 117s
Responder ipsec.conf:
# /etc/ipsec.conf - strongSwan IPsec configuration file
config setup
uniqueids=never
conn %default
ikelifetime=120s
keylife=5000s
rekeymargin=3s
keyingtries=1
keyexchange=ikev2
mobike=no
leftfirewall=yes
leftid="CN=srv, OU=load-test, O=strongSwan"
rightid=%any
leftcert=responder_cert.pem
authby=pubkey
type=tunnel
auto=add
conn rw
left=192.168.10.1
leftsubnet=10.1.10.0/16
right=%any
rightsourceip=10.3.10.1/16
leftsourceip=10.1.10.1/16
auto=add
Initiator strongswan.conf:
charon {
load = aes des sha1 sha2 md5 pem pkcs1 gmp random nonce x509 curl revocation hmac xcbc stroke kernel-netlink socket-default updown load-tester
reuse_ikesa = no
threads = 32
plugins {
load-tester {
enable = yes
initiators = 1
iterations = 1
delay = 1000
responder = 192.168.10.1
initiator_tsr = 0.0.0.0/0
responder_tsr = 10.1.10.1/24
responder_tsi = 10.3.10.1/16
proposal = aes128-sha1-modp1024
initiator_auth = pubkey
responder_auth = pubkey
request_virtual_ip = yes
ike_rekey = 0
child_rekey = 5000
delete_after_established = no
shutdown_when_complete = no
}
}
}
Seems to be some timing issue in responder side. Please share if any information on this.
Let me know if any options to play with timing parameters.
Thanks
Sudheer
Related issues
History
#1 Updated by Tobias Brunner over 9 years ago
- Related to Bug #1400: charon is unable to add policy to kernel sometimes during the reauth at runtime. added
#2 Updated by Tobias Brunner over 9 years ago
- Description updated (diff)
- Status changed from New to Feedback
- Priority changed from Urgent to Normal
It's probably a race condition (also see #1400). During reauthentication all SAs are deleted and then recreated. This could happen concurrently, which might then cause the following error as the policy might still be installed, but the plugin has no knowledge about it:
Apr 27 14:18:40 cavium-NCD charon: 07[KNL] unable to add policy: File exists (17) Apr 27 14:18:40 cavium-NCD charon: 07[KNL] unable to add policy 10.3.10.1/32 === 10.1.0.0/16 in
That the following update operation fails could be because the policy was deleted just before the SADB_X_SPDUPDATE PF_KEY message was sent. The Linux kernel, for instance, allows using SADB_X_SPDUPDATE even if the policy does not exist (so it basically treats it like SADB_X_SPDADD but ignores any EEXIST errors).
Apr 27 14:18:40 cavium-NCD charon: 07[KNL] error sending to PF_KEY socket: Operation not permitted Apr 27 14:18:40 cavium-NCD charon: 07[KNL] unable to update policy 10.3.10.1/32 === 10.1.0.0/16 in
Refer to ExpiryRekey and #1400 for details.
#3 Updated by Sudheer Anumolu over 9 years ago
Adding 'make_before_break=yes' in initiator solves it and reauthentication passes thru.
As discussed in #1400, the order changed.
But the old policies are not deleted at later stage, instead updated as done in rekeying.
W.r.t pfkey module, I don't see any difference between rekeying and reauthentication.
I understand, inbound & outbound SAs represent the child SAs and are modified during rekeying and reauthentication.
Can you tell how is IKE_SA represented ?
What is the difference in doing 'delete & create' policies and just updating them.
Thanks
Sudheer
#4 Updated by Tobias Brunner over 9 years ago
But the old policies are not deleted at later stage, instead updated as done in rekeying.
W.r.t pfkey module, I don't see any difference between rekeying and reauthentication.
That's the whole point of make-before-break reauthentication.
Can you tell how is IKE_SA represented ?
What do you mean?
What is the difference in doing 'delete & create' policies and just updating them.
Refer to ExpiryRekey.
#5 Updated by Noel Kuntze over 8 years ago
- Status changed from Feedback to Closed
- Resolution set to No feedback