SAD issue

mattv

Hello,

The original post is on the french section :

https://forum.pfsense.org/index.php?topic=132048.0

I have encountered for several weeks a problem with an IPSEC configuration between 2 sites.
Both internet connections are stable with a good response time (+/- 20-30 ms)
The tunnel is mounted and stable, the renewal of the keys happen without problem in some case.
The routers are installed in a production environment and serve to increase availability between two sites.
Router B is used with 5 other pfsense routers version 2.3.3 release p1 and with the same configuration.
Router B is the center point of the 'web'.

The problem is (to my knowledge) on ESP protocol.
The number of SAD entries used / preserved on the router B are sometimes too high for 1 configuration.
If I disconnect the tunnel for which I have too many entries (name tunnel from site C to B) the SAD ar deleted and allow me to solve the problem of my tunnel between site A and B.
Randomly I find for the 6 tunnels (in this case configuration # 6):

<con6|2534>unable to query SAD entry with SPI c69555cb: No such file or directory (2)
<con6|2534>unable to delete SAD entry with SPI c69555cb: No such file or directory (2)</con6|2534></con6|2534>

Schemas :

Routeur A Routeur B
(X)–-------internet---------(X)

Router A configuraiton

version 2.3.3 release p1
wan : 91.X.X.X PPPoE connexion
lan : 192.168.50.0/24

ipsec configuration
conn con3
fragmentation = yes
keyexchange = ikev2
reauth = yes
forceencaps = no
mobike = no

rekey = yes
installpolicy = yes
type = tunnel
dpdaction = restart
dpddelay = 10s
dpdtimeout = 60s
auto = route
left = 109.Y.Y.Y
right = 91.X.X.X
leftid = 109.Y.Y.Y
ikelifetime = 28800s
lifetime = 3600s
ike = aes256-sha1-modp1024!
esp = aes256-sha1,aes192-sha1,aes128-sha1!
leftauth = psk
rightauth = psk
rightid = 91.X.X.X
rightsubnet = 192.168.50.0/24
leftsubnet = 192.168.10.0/24

Router B configuration

version 2.3.3 release p1
wan : 109.Y.Y.Y /30
lan : 192.168.10.0/24

ipsec configuraiton :
conn con1
fragmentation = yes
keyexchange = ikev2
reauth = yes
forceencaps = no
mobike = no

rekey = yes
installpolicy = yes
type = tunnel
dpdaction = restart
dpddelay = 10s
dpdtimeout = 60s
auto = route
left = 91.X.X.X
right = 109.Y.Y.Y
leftid = 91.X.X.X
ikelifetime = 28800s
lifetime = 3600s
ike = aes256-sha1-modp1024!
esp = aes256-sha1,aes192-sha1,aes128-sha1!
leftauth = psk
rightauth = psk
rightid = 109.Y.Y.Y
rightsubnet = 192.168.10.0/24
leftsubnet = 192.168.50.0/24

Question :
Is my configuration correct ? how can I tune or upgrade it?

Is it possible to configure/manage the SAD entries ?

Actually I just disconnect the tunnels who have too many SAD entries to solve this issue.

Logs :

Router A :

Jun 12 11:41:30 routerA charon: 08[IKE] <con1|66>INFORMATIONAL request with message ID 0 processing failed
Jun 12 11:41:35 routerA charon: 13[IKE] <con1|66>retransmit 2 of request with message ID 0
Jun 12 11:41:35 routerA charon: 13[NET] <con1|66>sending packet: from 91.X.X.X[500] to 109.Y.Y.Y[500] (336 bytes)
Jun 12 11:41:35 routerA charon: 05[KNL] creating acquire job for policy 91.X.X.X/32|/0 === 109.Y.Y.Y/32|/0 with reqid {3}
Jun 12 11:41:48 routerA charon: 13[IKE] <con1|66>retransmit 3 of request with message ID 0
Jun 12 11:41:48 routerA charon: 13[NET] <con1|66>sending packet: from 91.X.X.X[500] to 109.Y.Y.Y[500] (336 bytes)
Jun 12 11:41:56 routerA charon: 08[KNL] creating acquire job for policy 91.X.X.X/32|/0 === 109.Y.Y.Y/32|/0 with reqid {3}
Jun 12 11:41:56 routerA charon: 13[CFG] ignoring acquire, connection attempt pending
Jun 12 11:42:09 routerA charon: 13[KNL] creating acquire job for policy 91.X.X.X/32|/0 === 109.Y.Y.Y/32|/0 with reqid {3}
Jun 12 11:42:09 routerA charon: 08[CFG] ignoring acquire, connection attempt pending
Jun 12 11:42:11 routerA charon: 08[IKE] <con1|66>retransmit 4 of request with message ID 0
Jun 12 11:42:11 routerA charon: 08[NET] <con1|66>sending packet: from 91.X.X.X[500] to 109.Y.Y.Y[500] (336 bytes)
Jun 12 11:42:18 routerA charon: 13[KNL] creating acquire job for policy 91.X.X.X/32|/0 === 109.Y.Y.Y/32|/0 with reqid {3}
Jun 12 11:42:18 routerA charon: 08[CFG] ignoring acquire, connection attempt pending
Jun 12 11:42:40 routerA charon: 08[KNL] creating acquire job for policy 91.X.X.X/32|/0 === 109.Y.Y.Y/32|/0 with reqid {3}
Jun 12 11:42:40 routerA charon: 13[CFG] ignoring acquire, connection attempt pending
Jun 12 11:42:45 routerA charon: 13[KNL] creating acquire job for policy 91.X.X.X/32|/0 === 109.Y.Y.Y/32|/0 with reqid {3}
Jun 12 11:42:45 routerA charon: 14[CFG] ignoring acquire, connection attempt pending
Jun 12 11:42:53 routerA charon: 14[IKE] <con1|66>retransmit 5 of request with message ID 0
Jun 12 11:42:53 routerA charon: 14[NET] <con1|66>sending packet: from 91.X.X.X[500] to 109.Y.Y.Y[500] (336 bytes)
Jun 12 11:43:06 routerA charon: 07[KNL] creating acquire job for policy 91.X.X.X/32|/0 === 109.Y.Y.Y/32|/0 with reqid {3}
Jun 12 11:43:06 routerA charon: 08[CFG] ignoring acquire, connection attempt pending
Jun 12 11:43:24 routerA charon: 07[NET] <con1|66>received packet: from 109.Y.Y.Y[500] to 91.X.X.X[500] (40 bytes)
Jun 12 11:43:24 routerA charon: 07[ENC] <con1|66>payload type NOTIFY was not encrypted
Jun 12 11:43:24 routerA charon: 07[ENC] <con1|66>could not decrypt payloads
Jun 12 11:43:24 routerA charon: 07[IKE] <con1|66>integrity check failed
Jun 12 11:43:24 routerA charon: 07[IKE] <con1|66>INFORMATIONAL request with message ID 0 processing failed</con1|66></con1|66></con1|66></con1|66></con1|66></con1|66></con1|66></con1|66></con1|66></con1|66></con1|66></con1|66></con1|66></con1|66>

Router B :

Jun 12 11:41:26 routerB charon: 01[IKE] <con3|2575>retransmit 5 of request with message ID 0
Jun 12 11:41:26 routerB charon: 01[NET] <con3|2575>sending packet: from 109.Y.Y.Y[500] to 91.X.X.X[500] (336 bytes)
Jun 12 11:41:26 routerB charon: 04[NET] error writing to socket: Permission denied
Jun 12 11:41:37 routerB charon: 01[KNL] creating acquire job for policy 109.Y.Y.Y/32|/0 === 91.X.X.X/32|/0 with reqid {17}
Jun 12 11:41:37 routerB charon: 08[CFG] ignoring acquire, connection attempt pending
Jun 12 11:42:15 routerB charon: 01[KNL] creating acquire job for policy 109.Y.Y.Y/32|/0 === 91.X.X.X/32|/0 with reqid {17}
Jun 12 11:42:15 routerB charon: 09[CFG] ignoring acquire, connection attempt pending
Jun 12 11:42:37 routerB charon: 09[KNL] creating acquire job for policy 109.Y.Y.Y/32|/0 === 91.X.X.X/32|/0 with reqid {17}
Jun 12 11:42:37 routerB charon: 10[CFG] ignoring acquire, connection attempt pending
Jun 12 11:42:42 routerB charon: 10[IKE] <con3|2575>giving up after 5 retransmits
Jun 12 11:42:42 routerB charon: 10[IKE] <con3|2575>peer not responding, trying again (2/3)
Jun 12 11:42:42 routerB charon: 10[IKE] <con3|2575>initiating IKE_SA con3[2575] to 91.X.X.X
Jun 12 11:42:42 routerB charon: 10[ENC] <con3|2575>generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Jun 12 11:42:42 routerB charon: 10[NET] <con3|2575>sending packet: from 109.Y.Y.Y[500] to 91.X.X.X[500] (336 bytes)
Jun 12 11:42:42 routerB charon: 04[NET] error writing to socket: Permission denied
Jun 12 11:42:46 routerB charon: 09[IKE] <con3|2575>retransmit 1 of request with message ID 0
Jun 12 11:42:46 routerB charon: 09[NET] <con3|2575>sending packet: from 109.Y.Y.Y[500] to 91.X.X.X[500] (336 bytes)
Jun 12 11:42:46 routerB charon: 04[NET] error writing to socket: Permission denied
Jun 12 11:42:53 routerB charon: 15[IKE] <con3|2575>retransmit 2 of request with message ID 0
Jun 12 11:42:53 routerB charon: 15[NET] <con3|2575>sending packet: from 109.Y.Y.Y[500] to 91.X.X.X[500] (336 bytes)
Jun 12 11:42:53 routerB charon: 04[NET] error writing to socket: Permission denied
Jun 12 11:43:06 routerB charon: 09[IKE] <con3|2575>retransmit 3 of request with message ID 0
Jun 12 11:43:06 routerB charon: 09[NET] <con3|2575>sending packet: from 109.Y.Y.Y[500] to 91.X.X.X[500] (336 bytes)
Jun 12 11:43:06 routerB charon: 04[NET] error writing to socket: Permission denied
Jun 12 11:43:18 routerB charon: 09[KNL] creating acquire job for policy 109.Y.Y.Y/32|/0 === 91.X.X.X/32|/0 with reqid {17}
Jun 12 11:43:18 routerB charon: 09[CFG] ignoring acquire, connection attempt pending
Jun 12 11:43:29 routerB charon: 12[IKE] <con3|2575>retransmit 4 of request with message ID 0
Jun 12 11:43:29 routerB charon: 12[NET] <con3|2575>sending packet: from 109.Y.Y.Y[500] to 91.X.X.X[500] (336 bytes)
Jun 12 11:43:29 routerB charon: 04[NET] error writing to socket: Permission denied
Jun 12 11:43:47 routerB charon: 14[KNL] creating acquire job for policy 109.Y.Y.Y/32|/0 === 91.X.X.X/32|/0 with reqid {17}
Jun 12 11:43:47 routerB charon: 07[CFG] ignoring acquire, connection attempt pending
Jun 12 11:44:11 routerB charon: 07[IKE] <con3|2575>retransmit 5 of request with message ID 0
Jun 12 11:44:11 routerB charon: 07[NET] <con3|2575>sending packet: from 109.Y.Y.Y[500] to 91.X.X.X[500] (336 bytes)
Jun 12 11:44:11 routerB charon: 04[NET] error writing to socket: Permission denied
Jun 12 11:44:12 routerB charon: 13[KNL] creating acquire job for policy 109.Y.Y.Y/32|/0 === 91.X.X.X/32|/0 with reqid {17}
Jun 12 11:44:12 routerB charon: 08[CFG] ignoring acquire, connection attempt pending
Jun 12 11:44:33 routerB charon: 08[KNL] creating acquire job for policy 109.Y.Y.Y/32|/0 === 91.X.X.X/32|/0 with reqid {17}
Jun 12 11:44:33 routerB charon: 06[CFG] ignoring acquire, connection attempt pending</con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575></con3|2575>

On router B I find too :

Jun 12 10:34:23 routerB charon: 08[CFG] <con6|2566>selected peer config 'con6'
Jun 12 10:34:23 routerB charon: 08[IKE] <con6|2566>authentication of '194.Z.Z.Z' with pre-shared key successful
Jun 12 10:34:23 routerB charon: 08[IKE] <con6|2566>received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
Jun 12 10:34:23 routerB charon: 08[IKE] <con6|2566>authentication of '109.Y.Y.Y' (myself) with pre-shared key
Jun 12 10:34:23 routerB charon: 08[IKE] <con6|2534>destroying duplicate IKE_SA for peer '194.Z.Z.Z', received INITIAL_CONTACT
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c69555cb: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c76aaa53: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c71ba1a6: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c2ad329a: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI cf8496fa: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c2f57537: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c49944c5: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI cec7a50c: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c02bb364: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI ce28510b: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c25d4530: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c1c9afb6: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c91262c9: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI c523fbae: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to query SAD entry with SPI cd2fb749: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI cd2fb749: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c523fbae: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c91262c9: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c1c9afb6: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c25d4530: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI ce28510b: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c02bb364: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI cec7a50c: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c49944c5: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c2f57537: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI cf8496fa: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c2ad329a: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c71ba1a6: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c76aaa53: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[KNL] <con6|2534>unable to delete SAD entry with SPI c69555cb: No such file or directory (2)
Jun 12 10:34:23 routerB charon: 08[IKE] <con6|2566>IKE_SA con6[2566] established between 109.Y.Y.Y[109.Y.Y.Y]…194.Z.Z.Z.Z[194.Z.Z.Z.Z]
Jun 12 10:34:23 routerB charon: 08[IKE] <con6|2566>scheduling reauthentication in 27782s
Jun 12 10:34:23 routerB charon: 08[IKE] <con6|2566>maximum IKE_SA lifetime 28322s</con6|2566></con6|2566></con6|2566></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2534></con6|2566></con6|2566></con6|2566></con6|2566>

This information says which tunnel I need to disconnect "to help" the other one to mount.

I think I found the solution in RFC3706 (DPD configuration)
http://www.ietf.org/rfc/rfc3706.txt

I modifed 2 tunnels configurations (with the most errors) but the problem persists

Thanks in advance and sorry for my English.

Regards,

Mathieu