SAD issue



  • 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


Log in to reply