Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    charon: trap not found, unable to acquire reqid

    Scheduled Pinned Locked Moved
    IPsec
    1
    1
    378
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • M
      mamawe
      last edited by mamawe

      Hi all,

      I'm not sure if I should file this as a regression or bug in the bugtracker.

      I already looked through this forum post and strongSwan bug #2315 but they seem to be related to older versions of strongSwan.
      I am using pfSense 2.5.0-RELEASE (amd64) with strongSwan 5.9.1.

      Yesterday there was an outage in the connection to an IPsec peer while rekeying of the child SA was due. After five retransmits the rekeying was abandoned and I've got creating acquire job for policy and trap not found, unable to acquire reqid messages in turn in the logs. There were more the 40000 messages for the whole day while the outage lasted only about one hour.

      Today I could reconnect the VPN in the web interface of the pfSense.

      These are the (slightly sanitized) logs for (Do you need any more information?):

      May  2 00:00:27 10.105.250.252 dpinger[36064]: RMG_IN_MAA_VTIV4 10.105.249.5: Alarm latency 162833us stddev 448us loss 22%
May  2 00:00:27 10.105.250.252 rc.gateway_alarm[57652]: >>> Gateway alarm: RMG_IN_MAA_VTIV4 (Addr:10.105.249.5 Alarm:1 RTT:162.833ms RTTsd:.448ms Loss:22%)
May  2 00:00:43 10.105.250.252 dpinger[36064]: RMG_IN_MAA_VTIV4 10.105.249.5: sendto error: 50
May  2 00:00:43 10.105.250.252 charon[186]: 15[KNL] 10.105.249.4 disappeared from ipsec1000
May  2 00:00:43 10.105.250.252 charon[186]: 07[KNL] 10.105.249.4 appeared on ipsec1000
May  2 00:00:43 10.105.250.252 charon[186]: 13[IKE] <con1000|2458> keeping statically configured path 172.16.1.39 - 172.16.2.123
May  2 00:00:45 10.105.250.252 charon[186]: 14[CFG] loaded IKE shared key with id 'ike-0' for: '%any', '172.16.2.123'
May  2 00:00:45 10.105.250.252 charon[186]: 11[CFG]  conn con1000:
May  2 00:00:45 10.105.250.252 charon[186]: 11[CFG]   child con1000:
May  2 00:00:45 10.105.250.252 charon[186]: 11[CFG]    local_ts = 10.105.249.4/32|/0 0.0.0.0/0|/0
May  2 00:00:45 10.105.250.252 charon[186]: 11[CFG]    remote_ts = 10.105.249.5/32|/0 0.0.0.0/0|/0
May  2 00:00:45 10.105.250.252 charon[186]: 11[CFG]   remote_addrs = 172.16.2.123
May  2 00:00:45 10.105.250.252 charon[186]: 11[CFG]    id = 172.16.2.123
May  2 00:00:45 10.105.250.252 charon[186]: 11[CFG] updated vici connection: con1000
May  2 00:00:45 10.105.250.252 charon[186]: 16[KNL] 10.105.249.4 disappeared from ipsec1000
May  2 00:00:45 10.105.250.252 charon[186]: 16[IKE] <con1000|2458> keeping statically configured path 172.16.1.39 - 172.16.2.123
May  2 00:00:45 10.105.250.252 filterlog[10226]: 102,,,1616666040,em1,match,pass,in,4,0x0,,63,365,0,none,1,icmp,29,10.105.249.4,10.105.249.5,request,36064,50059
May  2 00:00:46 10.105.250.252 charon[186]: 07[IKE] <con1000|2458> keeping statically configured path 172.16.1.39 - 172.16.2.123
May  2 00:05:06 10.105.250.252 filterlog[10226]: 96,,,1613566279,enc0,match,pass,in,4,0x0,,64,34791,0,none,1,icmp,29,10.105.249.5,10.105.249.4,request,7067,536149
May  2 00:56:05 10.105.250.252 charon[186]: 13[KNL] creating rekey job for CHILD_SA ESP/0xc05c8ff1/172.16.2.123
May  2 00:56:05 10.105.250.252 charon[186]: 15[IKE] <con1000|2458> queueing CHILD_REKEY task
May  2 00:56:05 10.105.250.252 charon[186]: 15[IKE] <con1000|2458> activating new tasks
May  2 00:56:05 10.105.250.252 charon[186]: 15[IKE] <con1000|2458>   activating CHILD_REKEY task
May  2 00:56:05 10.105.250.252 charon[186]: 15[CFG] <con1000|2458> proposing traffic selectors for us:
May  2 00:56:05 10.105.250.252 charon[186]: 15[CFG] <con1000|2458>  10.105.249.4/32|/0
May  2 00:56:05 10.105.250.252 charon[186]: 15[CFG] <con1000|2458>  0.0.0.0/0|/0
May  2 00:56:05 10.105.250.252 charon[186]: 15[CFG] <con1000|2458> proposing traffic selectors for other:
May  2 00:56:05 10.105.250.252 charon[186]: 15[CFG] <con1000|2458>  10.105.249.5/32|/0
May  2 00:56:05 10.105.250.252 charon[186]: 15[CFG] <con1000|2458>  0.0.0.0/0|/0
May  2 00:56:05 10.105.250.252 charon[186]: 15[CFG] <con1000|2458> configured proposals: ESP:AES_GCM_16_128/ECP_256/NO_EXT_SEQ, ESP:AES_GCM_12_128/ECP_256/NO_EXT_SEQ, ESP:AES_GCM_8_128/ECP_256/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA2_256_128/ECP_256/NO_EXT_SEQ
May  2 00:56:05 10.105.250.252 charon[186]: 15[IKE] <con1000|2458> establishing CHILD_SA con1000{7550} reqid 1000
May  2 00:56:05 10.105.250.252 charon[186]: 15[CHD] <con1000|2458> CHILD_SA con1000{7534} state change: INSTALLED => REKEYING
May  2 00:56:05 10.105.250.252 charon[186]: 15[ENC] <con1000|2458> generating CREATE_CHILD_SA request 0 [ N(REKEY_SA) N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
May  2 00:56:05 10.105.250.252 charon[186]: 15[NET] <con1000|2458> sending packet: from 172.16.1.39[500] to 172.16.2.123[500] (416 bytes)
May  2 00:56:09 10.105.250.252 charon[186]: 13[IKE] <con1000|2458> retransmit 1 of request with message ID 0
May  2 00:56:09 10.105.250.252 charon[186]: 13[NET] <con1000|2458> sending packet: from 172.16.1.39[500] to 172.16.2.123[500] (416 bytes)
May  2 00:56:16 10.105.250.252 charon[186]: 15[IKE] <con1000|2458> retransmit 2 of request with message ID 0
May  2 00:56:16 10.105.250.252 charon[186]: 15[NET] <con1000|2458> sending packet: from 172.16.1.39[500] to 172.16.2.123[500] (416 bytes)
May  2 00:56:29 10.105.250.252 charon[186]: 15[IKE] <con1000|2458> retransmit 3 of request with message ID 0
May  2 00:56:29 10.105.250.252 charon[186]: 15[NET] <con1000|2458> sending packet: from 172.16.1.39[500] to 172.16.2.123[500] (416 bytes)
May  2 00:56:52 10.105.250.252 charon[186]: 08[IKE] <con1000|2458> retransmit 4 of request with message ID 0
May  2 00:56:52 10.105.250.252 charon[186]: 08[NET] <con1000|2458> sending packet: from 172.16.1.39[500] to 172.16.2.123[500] (416 bytes)
May  2 00:57:34 10.105.250.252 charon[186]: 07[IKE] <con1000|2458> retransmit 5 of request with message ID 0
May  2 00:57:34 10.105.250.252 charon[186]: 07[NET] <con1000|2458> sending packet: from 172.16.1.39[500] to 172.16.2.123[500] (416 bytes)
May  2 00:57:38 10.105.250.252 charon[186]: 09[IKE] <con1000|2458> queueing CHILD_REKEY task
May  2 00:57:38 10.105.250.252 charon[186]: 09[IKE] <con1000|2458> delaying task initiation, CREATE_CHILD_SA exchange in progress
May  2 00:58:50 10.105.250.252 charon[186]: 14[IKE] <con1000|2458> giving up after 5 retransmits
May  2 00:58:50 10.105.250.252 charon[186]: 14[IKE] <con1000|2458> IKE_SA con1000[2458] state change: ESTABLISHED => DESTROYING
May  2 00:58:50 10.105.250.252 charon[186]: 14[CHD] <con1000|2458> CHILD_SA con1000{7550} state change: CREATED => DESTROYING
May  2 00:58:50 10.105.250.252 charon[186]: 14[KNL] <con1000|2458> unable to delete SAD entry with SPI c2d85cf4: No such process (3)
May  2 00:58:50 10.105.250.252 charon[186]: 14[CHD] <con1000|2458> CHILD_SA con1000{7534} state change: REKEYING => DESTROYING
May  2 00:58:50 10.105.250.252 charon[186]: 11[KNL] creating acquire job for policy 172.16.1.39/32|/0 === 172.16.2.123/32|/0 with reqid {1000}
May  2 00:58:50 10.105.250.252 charon[186]: 13[CFG] trap not found, unable to acquire reqid 1000
May  2 00:58:53 10.105.250.252 charon[186]: 13[KNL] creating acquire job for policy 172.16.1.39/32|/0 === 172.16.2.123/32|/0 with reqid {1000}
May  2 00:58:53 10.105.250.252 charon[186]: 11[CFG] trap not found, unable to acquire reqid 1000
May  2 00:58:56 10.105.250.252 charon[186]: 11[KNL] creating acquire job for policy 172.16.1.39/32|/0 === 172.16.2.123/32|/0 with reqid {1000}
May  2 00:58:56 10.105.250.252 charon[186]: 13[CFG] trap not found, unable to acquire reqid 1000
May  2 00:58:59 10.105.250.252 charon[186]: 13[KNL] creating acquire job for policy 172.16.1.39/32|/0 === 172.16.2.123/32|/0 with reqid {1000}
May  2 00:58:59 10.105.250.252 charon[186]: 15[CFG] trap not found, unable to acquire reqid 1000
May  2 00:59:02 10.105.250.252 charon[186]: 15[KNL] creating acquire job for policy 172.16.1.39/32|/0 === 172.16.2.123/32|/0 with reqid {1000}
May  2 00:59:02 10.105.250.252 charon[186]: 13[CFG] trap not found, unable to acquire reqid 1000
May  2 00:59:06 10.105.250.252 charon[186]: 13[KNL] creating acquire job for policy 172.16.1.39/32|/0 === 172.16.2.123/32|/0 with reqid {1000}
May  2 00:59:06 10.105.250.252 charon[186]: 15[CFG] trap not found, unable to acquire reqid 1000
...
May  2 23:59:51 10.105.250.252 charon[186]: 12[KNL] creating acquire job for policy 172.16.1.39/32|/0 === 172.16.2.123/32|/0 with reqid {1000}
May  2 23:59:51 10.105.250.252 charon[186]: 13[CFG] trap not found, unable to acquire reqid 1000
May  2 23:59:56 10.105.250.252 charon[186]: 12[KNL] creating acquire job for policy 172.16.1.39/32|/0 === 172.16.2.123/32|/0 with reqid {1000}
May  2 23:59:56 10.105.250.252 charon[186]: 16[CFG] trap not found, unable to acquire reqid 1000
      1 Reply Last reply Reply Quote 0
      • First post
        Last post
      Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.