<div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr">We are using Libreswan 3.32.  We would like to replace the IPsec Kernel stack with our software to handle encryption and decryption of data packets. We would like to use Libreswan to negotiate the IPSec SA keys for us.  We have prototyped a socket between our software and pluto using the netlink model. We are receiving Add SA, Del SA and Get SA commands.  We didn't think we needed any of the other APIs.</div><div dir="ltr"><br></div><div dir="ltr">The problem we are running into is during rekey, the Del SA for outbound and inbound are always called first.  Then, Add SA for outbound and inbound is called.  This is causing data packets to be dropped during the rekey.  Is there an api that we need to implement so that we get the new SA setup first before deleting the old SAs.<br></div><div dir="ltr"><br></div><div>Pluto.log shows that the old SA is deleted then a new IKE negotiation is triggered.  This always happens whether data is being sent or not.   </div><div><br></div><div>Please advise.  Thank you.<br></div><div><br></div><div>Regards,</div><div>Sonia Rovner</div><div><br></div><div dir="ltr"><br></div><div>Below is the pluto log output during rekey:</div><div><br></div><div>Aug 25 00:18:57.537093: | start processing: state #6 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in timer_event_cb() at timer.c:250)<br>Aug 25 00:18:57.537099: | [RE]START processing: state #6 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in liveness_check() at timer.c:113)<br>Aug 25 00:18:57.537109: | get_sa_info <a href="mailto:esp.521fc1dd@10.210.0.2">esp.521fc1dd@10.210.0.2</a><br>Aug 25 00:18:57.537296: | #6 liveness_check - last_liveness: 6010.490076, now: 6280.531282 parent #5<br>Aug 25 00:18:57.537305: | Opening output PBS liveness probe informational request<br>Aug 25 00:18:57.537309: | **emit ISAKMP Message:<br>Aug 25 00:18:57.537324: |    initiator cookie: ee 79 84 10  1d 53 54 d0<br>Aug 25 00:18:57.537328: |    responder cookie: 45 ff 34 f4  d3 c7 7e fc<br>Aug 25 00:18:57.537331: |    next payload type: ISAKMP_NEXT_NONE (0x0)<br>Aug 25 00:18:57.537333: |    ISAKMP version: IKEv2 version 2.0 (rfc4306/rfc5996) (0x20)<br>Aug 25 00:18:57.537336: |    exchange type: ISAKMP_v2_INFORMATIONAL (0x25)<br>Aug 25 00:18:57.537339: |    flags: ISAKMP_FLAG_v2_IKE_INIT (0x8)<br>Aug 25 00:18:57.537343: |    Message ID: 42 (00 00 00 2a)<br>Aug 25 00:18:57.537345: | next payload chain: saving message location 'ISAKMP Message'.'next payload type'<br>Aug 25 00:18:57.537349: | ***emit IKEv2 Encryption Payload:<br>Aug 25 00:18:57.537351: |    next payload type: ISAKMP_NEXT_v2NONE (0x0)<br>Aug 25 00:18:57.537354: |    flags: none (0x0)<br>Aug 25 00:18:57.537356: | next payload chain: setting previous 'ISAKMP Message'.'next payload type' to current IKEv2 Encryption Payload (46:ISAKMP_NEXT_v2SK)<br>Aug 25 00:18:57.537359: | next payload chain: saving location 'IKEv2 Encryption Payload'.'next payload type' in 'liveness probe informational request'<br>Aug 25 00:18:57.537362: | emitting 16 zero bytes of IV into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537375: | adding 16 bytes of padding (including 1 byte padding-length)<br>Aug 25 00:18:57.537378: | emitting 1 0x00 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537380: | emitting 1 0x01 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537383: | emitting 1 0x02 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537385: | emitting 1 0x03 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537387: | emitting 1 0x04 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537390: | emitting 1 0x05 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537392: | emitting 1 0x06 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537415: | emitting 1 0x07 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537418: | emitting 1 0x08 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537420: | emitting 1 0x09 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537423: | emitting 1 0x0a repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537425: | emitting 1 0x0b repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537427: | emitting 1 0x0c repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537430: | emitting 1 0x0d repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537432: | emitting 1 0x0e repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537434: | emitting 1 0x0f repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537437: | emitting 16 zero bytes of length of truncated HMAC/KEY into IKEv2 Encryption Payload<br>Aug 25 00:18:57.537439: | emitting length of IKEv2 Encryption Payload: 52<br>Aug 25 00:18:57.537441: | emitting length of ISAKMP Message: 80<br>Aug 25 00:18:57.537499: | sending 80 bytes for liveness probe informational request through vni-1 from <a href="http://10.210.0.2:500">10.210.0.2:500</a> to <a href="http://10.213.0.2:500">10.213.0.2:500</a> (using #6)<br>Aug 25 00:18:57.537504: |   ee 79 84 10  1d 53 54 d0  45 ff 34 f4  d3 c7 7e fc<br>Aug 25 00:18:57.537506: |   2e 20 25 08  00 00 00 2a  00 00 00 50  00 00 00 34<br>Aug 25 00:18:57.537508: |   5b 06 d3 31  78 55 93 ee  85 4c 74 af  9d b3 ad df<br>Aug 25 00:18:57.537510: |   71 1c 85 be  d6 bf 83 2d  5f c6 17 5b  4f db 6d 82<br>Aug 25 00:18:57.537512: |   a1 86 7c c9  50 ca 67 65  f2 d0 cd 8e  1e 9b f6 9c<br>Aug 25 00:18:57.537539: | Message ID: CHILD #5.#6 XXX: in ikev2_send_livenss_probe() hacking around record'n'send bypassing send queue: ike.initiator.sent=41 ike.initiator.recv=33 ike.responder.sent=5 ike.responder.recv=5 child.wip.initiator=-1 child.wip.responder=-1<br>Aug 25 00:18:57.537545: | Message ID: IKE #5 XXX: expecting sender.wip.initiator 41 == -1 - suspect record'n'send out-of-order?): ike.initiator.sent=42 ike.initiator.recv=33 ike.responder.sent=5 ike.responder.recv=5 ike.wip.initiator=42 ike.wip.responder=-1<br>Aug 25 00:18:57.537612: | Message ID: IKE #5 updating initiator sent message request 42: ike.initiator.sent=41->42 ike.initiator.recv=33 ike.responder.sent=5 ike.responder.recv=5 ike.wip.initiator=41->42 ike.wip.responder=-1<br>Aug 25 00:18:57.537618: | #6 liveness_check - peer 10.213.0.2 is missing - giving them some time to come back<br>Aug 25 00:18:57.537620: | #6 liveness_check - peer 10.213.0.2 is ok schedule new<br>Aug 25 00:18:57.537624: | event_schedule: newref EVENT_v2_LIVENESS-pe@0x5594dd92b068<br>Aug 25 00:18:57.537627: | inserting event EVENT_v2_LIVENESS, timeout in 30 seconds for #6<br>Aug 25 00:18:57.537631: | libevent_malloc: newref ptr-libevent@0x5594dd9385d8 size 136<br>Aug 25 00:18:57.537682: | libevent_free: delref ptr-libevent@0x5594dd92c9b8<br>Aug 25 00:18:57.537687: | free_event_entry: delref EVENT_v2_LIVENESS-pe@0x5594dd934f98<br>Aug 25 00:18:57.537695: | #6 spent 0.44 milliseconds in timer_event_cb() EVENT_v2_LIVENESS<br>Aug 25 00:18:57.537700: | stop processing: state #6 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in timer_event_cb() at timer.c:557)<br>Aug 25 00:19:09.673111: | processing global timer EVENT_SHUNT_SCAN<br>Aug 25 00:19:09.673141: | checking for aged bare shunts from shunt table to expire<br>Aug 25 00:19:09.673148: | spent 0.00548 milliseconds in global timer EVENT_SHUNT_SCAN<br>Aug 25 00:19:27.555043: | timer_event_cb: processing event@0x5594dd92b068<br>Aug 25 00:19:27.555071: | handling event EVENT_v2_LIVENESS for child state #6<br>Aug 25 00:19:27.555080: | start processing: state #6 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in timer_event_cb() at timer.c:250)<br>Aug 25 00:19:27.555097: | [RE]START processing: state #6 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in liveness_check() at timer.c:113)<br>Aug 25 00:19:27.555107: | get_sa_info <a href="mailto:esp.521fc1dd@10.210.0.2">esp.521fc1dd@10.210.0.2</a><br>Aug 25 00:19:27.555215: | #6 liveness_check - last_liveness: 6010.490076, now: 6310.5492 parent #5<br>Aug 25 00:19:27.555241: "bn" #6: liveness_check - peer 10.213.0.2 has not responded in 300 seconds, with a timeout of 300, taking action:hold<br>Aug 25 00:19:27.555246: "bn" #6: liveness action - putting connection into hold<br>Aug 25 00:19:27.555249: | Deleting states for connection - including all other IPsec SA's of this IKE SA<br>Aug 25 00:19:27.555251: | pass 0<br>Aug 25 00:19:27.555253: | FOR_EACH_STATE_... in foreach_state_by_connection_func_delete<br>Aug 25 00:19:27.555256: | state #6<br>Aug 25 00:19:27.555260: | [RE]START processing: state #6 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in foreach_state_by_connection_func_delete() at state.c:1376)<br>Aug 25 00:19:27.555278: | pstats #6 ikev2.child deleted completed<br>Aug 25 00:19:27.555321: | #6 spent 27.2 milliseconds in total<br>Aug 25 00:19:27.555326: | [RE]START processing: state #6 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in delete_state() at state.c:944)<br>Aug 25 00:19:27.555330: "bn" #6: deleting state (STATE_V2_IPSEC_I) aged 1530.654s and sending notification<br>Aug 25 00:19:27.555333: | child state #6: V2_IPSEC_I(established CHILD SA) => delete<br>Aug 25 00:19:27.555337: | get_sa_info <a href="mailto:esp.c5a6537e@10.213.0.2">esp.c5a6537e@10.213.0.2</a><br>Aug 25 00:19:27.555373: | get_sa_info <a href="mailto:esp.521fc1dd@10.210.0.2">esp.521fc1dd@10.210.0.2</a><br>Aug 25 00:19:27.555394: "bn" #6: ESP traffic information: in=0B out=0B<br>Aug 25 00:19:27.555398: | unsuspending #6 MD (nil)<br>Aug 25 00:19:27.555401: | #6 send IKEv2 delete notification for STATE_V2_IPSEC_I<br>Aug 25 00:19:27.555404: | Opening output PBS informational exchange delete request<br>Aug 25 00:19:27.555408: | **emit ISAKMP Message:<br>Aug 25 00:19:27.555413: |    initiator cookie: ee 79 84 10  1d 53 54 d0<br>Aug 25 00:19:27.555416: |    responder cookie: 45 ff 34 f4  d3 c7 7e fc<br>Aug 25 00:19:27.555419: |    next payload type: ISAKMP_NEXT_NONE (0x0)<br>Aug 25 00:19:27.555422: |    ISAKMP version: IKEv2 version 2.0 (rfc4306/rfc5996) (0x20)<br>Aug 25 00:19:27.555424: |    exchange type: ISAKMP_v2_INFORMATIONAL (0x25)<br>Aug 25 00:19:27.555427: |    flags: ISAKMP_FLAG_v2_IKE_INIT (0x8)<br>Aug 25 00:19:27.555431: |    Message ID: 43 (00 00 00 2b)<br>Aug 25 00:19:27.555434: | next payload chain: saving message location 'ISAKMP Message'.'next payload type'<br>Aug 25 00:19:27.555437: | ***emit IKEv2 Encryption Payload:<br>Aug 25 00:19:27.555440: |    next payload type: ISAKMP_NEXT_v2NONE (0x0)<br>Aug 25 00:19:27.555442: |    flags: none (0x0)<br>Aug 25 00:19:27.555445: | next payload chain: setting previous 'ISAKMP Message'.'next payload type' to current IKEv2 Encryption Payload (46:ISAKMP_NEXT_v2SK)<br>Aug 25 00:19:27.555447: | next payload chain: saving location 'IKEv2 Encryption Payload'.'next payload type' in 'informational exchange delete request'<br>Aug 25 00:19:27.555450: | emitting 16 zero bytes of IV into IKEv2 Encryption Payload<br>Aug 25 00:19:27.555468: | ****emit IKEv2 Delete Payload:<br>Aug 25 00:19:27.555471: |    next payload type: ISAKMP_NEXT_v2NONE (0x0)<br>Aug 25 00:19:27.555473: |    flags: none (0x0)<br>Aug 25 00:19:27.555475: |    protocol ID: PROTO_v2_ESP (0x3)<br>Aug 25 00:19:27.555478: |    SPI size: 4 (04)<br>Aug 25 00:19:27.555481: |    number of SPIs: 1 (00 01)<br>Aug 25 00:19:27.555483: | next payload chain: setting previous 'IKEv2 Encryption Payload'.'next payload type' to current IKEv2 Delete Payload (42:ISAKMP_NEXT_v2D)<br>Aug 25 00:19:27.555486: | next payload chain: saving location 'IKEv2 Delete Payload'.'next payload type' in 'informational exchange delete request'<br>Aug 25 00:19:27.555489: | emitting 4 raw bytes of local spis into IKEv2 Delete Payload<br>Aug 25 00:19:27.555504: | local spis: 52 1f c1 dd<br>Aug 25 00:19:27.555506: | emitting length of IKEv2 Delete Payload: 12<br>Aug 25 00:19:27.555509: | adding 4 bytes of padding (including 1 byte padding-length)<br>Aug 25 00:19:27.555512: | emitting 1 0x00 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.555514: | emitting 1 0x01 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.555517: | emitting 1 0x02 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.555519: | emitting 1 0x03 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.555530: | emitting 16 zero bytes of length of truncated HMAC/KEY into IKEv2 Encryption Payload<br>Aug 25 00:19:27.555533: | emitting length of IKEv2 Encryption Payload: 52<br>Aug 25 00:19:27.555535: | emitting length of ISAKMP Message: 80<br>Aug 25 00:19:27.555589: | sending 80 bytes for delete notification through vni-1 from <a href="http://10.210.0.2:500">10.210.0.2:500</a> to <a href="http://10.213.0.2:500">10.213.0.2:500</a> (using #6)<br>Aug 25 00:19:27.555594: |   ee 79 84 10  1d 53 54 d0  45 ff 34 f4  d3 c7 7e fc<br>Aug 25 00:19:27.555596: |   2e 20 25 08  00 00 00 2b  00 00 00 50  2a 00 00 34<br>Aug 25 00:19:27.555598: |   29 41 7d 9b  c7 64 1c 1f  58 1d 83 2c  4d f7 2d c5<br>Aug 25 00:19:27.555600: |   00 16 4f ed  84 d1 78 a0  4e 0f 60 68  3c 39 42 37<br>Aug 25 00:19:27.555602: |   70 f4 b0 62  d1 4d 2e fa  97 b4 ef e3  80 c4 27 ac<br>Aug 25 00:19:27.555629: | Message ID: IKE #5 sender #6 in send_delete hacking around record ' send<br>Aug 25 00:19:27.555637: | Message ID: IKE #5 XXX: expecting sender.wip.initiator 42 == -1 - suspect record'n'send out-of-order?): ike.initiator.sent=43 ike.initiator.recv=33 ike.responder.sent=5 ike.responder.recv=5 ike.wip.initiator=43 ike.wip.responder=-1<br>Aug 25 00:19:27.555641: | Message ID: IKE #5 updating initiator sent message request 43: ike.initiator.sent=42->43 ike.initiator.recv=33 ike.responder.sent=5 ike.responder.recv=5 ike.wip.initiator=42->43 ike.wip.responder=-1<br>Aug 25 00:19:27.555726: | state #6 requesting EVENT_SA_REKEY to be deleted<br>Aug 25 00:19:27.555744: | libevent_free: delref ptr-libevent@0x5594dd938108<br>Aug 25 00:19:27.555748: | free_event_entry: delref EVENT_SA_REKEY-pe@0x5594dd91a1b8<br>Aug 25 00:19:27.555778: | running updown command "ipsec _updown" for verb down <br>Aug 25 00:19:27.555787: | command executing down-client<br>Aug 25 00:19:27.555846: | executing down-client: PLUTO_VERB='down-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bn' PLUTO_VIRT_INTERFACE='vni-1' PLUTO_INTERFACE='vni-1' PLUTO_XFRMI_ROUTE='' PLUTO_NEXT_HOP='10.210.0.1' PLUTO_ME='10.210.0.2' PLUTO_MY_ID='10.210.0.2' PLUTO_MY_CLIENT='<a href="http://10.220.0.0/24">10.220.0.0/24</a>' PLUTO_MY_CLIENT_NET='10.220.0.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_SA_REQID='16388' PLUTO_SA_TYPE='ESP' PLUTO_PEER='10.213.0.2' PLUTO_PEER_ID='10.213.0.2' PLUTO_PEER_CLIENT='<a href="http://10.213.0.0/16">10.213.0.0/16</a>' PLUTO_PEER_CLIENT_NET='10.213.0.0' PLUTO_PEER_CLIENT_MASK='255.255.0.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey' PLUTO_ADDTIME='1598327636' PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+UP+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO' PLUTO_CONN_KIND='CK_PERMANENT' PLUTO_CONN_ADDRFAMILY='ipv4' XAUTH_FAILED=0 PLUTO_MY_SOURCEIP='10.210.0.2' PLUTO_MOBIKE_EVENT='' PLUTO_IS_PEER_CISCO='0' PLUTO_PEER_DNS_INFO='' PLUTO_PEER_DOMAIN_INFO='' PLUTO_PEER_BANNER='' PLUTO_CFG_SERVER='0...<br>Aug 25 00:19:27.555851: | popen cmd is 1144 chars long<br>Aug 25 00:19:27.555854: | cmd(   0):PLUTO_VERB='down-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bn' PLUTO_VIRT_IN:<br>Aug 25 00:19:27.555856: | cmd(  80):TERFACE='vni-1' PLUTO_INTERFACE='vni-1' PLUTO_XFRMI_ROUTE='' PLUTO_NEXT_HOP='10.:<br>Aug 25 00:19:27.555858: | cmd( 160):210.0.1' PLUTO_ME='10.210.0.2' PLUTO_MY_ID='10.210.0.2' PLUTO_MY_CLIENT='10.220.:<br>Aug 25 00:19:27.555860: | cmd( 240):0.0/24' PLUTO_MY_CLIENT_NET='10.220.0.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PL:<br>Aug 25 00:19:27.555862: | cmd( 320):UTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_SA_REQID='16388' PLUTO_SA_TYPE='ESP':<br>Aug 25 00:19:27.555865: | cmd( 400): PLUTO_PEER='10.213.0.2' PLUTO_PEER_ID='10.213.0.2' PLUTO_PEER_CLIENT='<a href="http://10.213.0.">10.213.0.</a>:<br>Aug 25 00:19:27.555867: | cmd( 480):0/16' PLUTO_PEER_CLIENT_NET='10.213.0.0' PLUTO_PEER_CLIENT_MASK='255.255.0.0' PL:<br>Aug 25 00:19:27.555869: | cmd( 560):UTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey' :<br>Aug 25 00:19:27.555871: | cmd( 640):PLUTO_ADDTIME='1598327636' PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+UP+IKEV2_ALLOW+:<br>Aug 25 00:19:27.555873: | cmd( 720):SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO' PLUTO_CONN_KIND='CK_PERMANENT' PLUTO_CONN_ADD:<br>Aug 25 00:19:27.555884: | cmd( 800):RFAMILY='ipv4' XAUTH_FAILED=0 PLUTO_MY_SOURCEIP='10.210.0.2' PLUTO_MOBIKE_EVENT=:<br>Aug 25 00:19:27.555886: | cmd( 880):'' PLUTO_IS_PEER_CISCO='0' PLUTO_PEER_DNS_INFO='' PLUTO_PEER_DOMAIN_INFO='' PLUT:<br>Aug 25 00:19:27.555888: | cmd( 960):O_PEER_BANNER='' PLUTO_CFG_SERVER='0' PLUTO_CFG_CLIENT='0' PLUTO_NM_CONFIGURED=':<br>Aug 25 00:19:27.555891: | cmd(1040):0' VTI_IFACE='' VTI_ROUTING='no' VTI_SHARED='no' SPI_IN=0xc5a6537e SPI_OUT=0x521:<br>Aug 25 00:19:27.555893: | cmd(1120):fc1dd ipsec _updown 2>&1:<br>Aug 25 00:19:27.571897: | shunt_eroute() called for connection 'bn' to 'replace with shunt' for rt_kind 'prospective erouted' using protoports <a href="http://10.220.0.0/24:0">10.220.0.0/24:0</a> --0->- <a href="http://10.213.0.0/16:0">10.213.0.0/16:0</a><br>Aug 25 00:19:27.571930: | netlink_shunt_eroute for proto 0, and source <a href="http://10.220.0.0/24:0">10.220.0.0/24:0</a> dest <a href="http://10.213.0.0/16:0">10.213.0.0/16:0</a><br>Aug 25 00:19:27.571935: | priority calculation of connection "bn" is 0x1fcfde<br>Aug 25 00:19:27.571970: | IPsec Sa SPD priority set to 2084830<br>Aug 25 00:19:27.571993: | delete <a href="mailto:esp.c5a6537e@10.213.0.2">esp.c5a6537e@10.213.0.2</a><br>Aug 25 00:19:27.572058: | XFRM: deleting IPsec SA with reqid 0<br>Aug 25 00:19:27.572077: | netlink response for Del SA <a href="mailto:esp.c5a6537e@10.213.0.2">esp.c5a6537e@10.213.0.2</a> included non-error error<br>Aug 25 00:19:27.572081: | priority calculation of connection "bn" is 0x1fcfde<br>Aug 25 00:19:27.572088: | delete inbound eroute <a href="http://10.213.0.0/16:0">10.213.0.0/16:0</a> --0-> <a href="http://10.220.0.0/24:0">10.220.0.0/24:0</a> => <a href="mailto:unk.10000@10.210.0.2">unk.10000@10.210.0.2</a> using reqid 0 (raw_eroute)<br>Aug 25 00:19:27.572100: | raw_eroute result=success<br>Aug 25 00:19:27.572103: | delete <a href="mailto:esp.521fc1dd@10.210.0.2">esp.521fc1dd@10.210.0.2</a><br>Aug 25 00:19:27.572127: | XFRM: deleting IPsec SA with reqid 0<br>Aug 25 00:19:27.572137: | netlink response for Del SA <a href="mailto:esp.521fc1dd@10.210.0.2">esp.521fc1dd@10.210.0.2</a> included non-error error<br>Aug 25 00:19:27.572157: | in connection_discard for connection bn<br>Aug 25 00:19:27.572162: | State DB: deleting IKEv2 state #6 in V2_IPSEC_I<br>Aug 25 00:19:27.572169: | child state #6: V2_IPSEC_I(established CHILD SA) => UNDEFINED(ignore)<br>Aug 25 00:19:27.572171: | releasing #6's fd-fd@(nil) because deleting state<br>Aug 25 00:19:27.572174: | delref fdp@NULL (in delete_state() at state.c:1185)<br>Aug 25 00:19:27.572182: | stop processing: state #6 from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in delete_state() at state.c:1211)<br>Aug 25 00:19:27.572196: | processing: STOP state #0 (in foreach_state_by_connection_func_delete() at state.c:1378)<br>Aug 25 00:19:27.572199: | state #5<br>Aug 25 00:19:27.572201: | pass 1<br>Aug 25 00:19:27.572203: | FOR_EACH_STATE_... in foreach_state_by_connection_func_delete<br>Aug 25 00:19:27.572205: | state #5<br>Aug 25 00:19:27.572210: | start processing: state #5 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in foreach_state_by_connection_func_delete() at state.c:1376)<br>Aug 25 00:19:27.572212: | pstats #5 ikev2.ike deleted completed<br>Aug 25 00:19:27.572219: | #5 spent 19.9 milliseconds in total<br>Aug 25 00:19:27.572223: | [RE]START processing: state #5 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in delete_state() at state.c:944)<br>Aug 25 00:19:27.572227: "bn" #5: deleting state (STATE_PARENT_I3) aged 1530.732s and sending notification<br>Aug 25 00:19:27.572230: | parent state #5: PARENT_I3(established IKE SA) => delete<br>Aug 25 00:19:27.572232: | unsuspending #5 MD (nil)<br>Aug 25 00:19:27.572235: | #5 send IKEv2 delete notification for STATE_PARENT_I3<br>Aug 25 00:19:27.572238: | Opening output PBS informational exchange delete request<br>Aug 25 00:19:27.572241: | **emit ISAKMP Message:<br>Aug 25 00:19:27.572245: |    initiator cookie: ee 79 84 10  1d 53 54 d0<br>Aug 25 00:19:27.572248: |    responder cookie: 45 ff 34 f4  d3 c7 7e fc<br>Aug 25 00:19:27.572251: |    next payload type: ISAKMP_NEXT_NONE (0x0)<br>Aug 25 00:19:27.572254: |    ISAKMP version: IKEv2 version 2.0 (rfc4306/rfc5996) (0x20)<br>Aug 25 00:19:27.572256: |    exchange type: ISAKMP_v2_INFORMATIONAL (0x25)<br>Aug 25 00:19:27.572259: |    flags: ISAKMP_FLAG_v2_IKE_INIT (0x8)<br>Aug 25 00:19:27.572262: |    Message ID: 44 (00 00 00 2c)<br>Aug 25 00:19:27.572265: | next payload chain: saving message location 'ISAKMP Message'.'next payload type'<br>Aug 25 00:19:27.572268: | ***emit IKEv2 Encryption Payload:<br>Aug 25 00:19:27.572319: |    next payload type: ISAKMP_NEXT_v2NONE (0x0)<br>Aug 25 00:19:27.572323: |    flags: none (0x0)<br>Aug 25 00:19:27.572336: | next payload chain: setting previous 'ISAKMP Message'.'next payload type' to current IKEv2 Encryption Payload (46:ISAKMP_NEXT_v2SK)<br>Aug 25 00:19:27.572339: | next payload chain: saving location 'IKEv2 Encryption Payload'.'next payload type' in 'informational exchange delete request'<br>Aug 25 00:19:27.572343: | emitting 16 zero bytes of IV into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572355: | ****emit IKEv2 Delete Payload:<br>Aug 25 00:19:27.572357: |    next payload type: ISAKMP_NEXT_v2NONE (0x0)<br>Aug 25 00:19:27.572360: |    flags: none (0x0)<br>Aug 25 00:19:27.572362: |    protocol ID: PROTO_v2_IKE (0x1)<br>Aug 25 00:19:27.572365: |    SPI size: 0 (00)<br>Aug 25 00:19:27.572368: |    number of SPIs: 0 (00 00)<br>Aug 25 00:19:27.572371: | next payload chain: setting previous 'IKEv2 Encryption Payload'.'next payload type' to current IKEv2 Delete Payload (42:ISAKMP_NEXT_v2D)<br>Aug 25 00:19:27.572373: | next payload chain: saving location 'IKEv2 Delete Payload'.'next payload type' in 'informational exchange delete request'<br>Aug 25 00:19:27.572376: | emitting length of IKEv2 Delete Payload: 8<br>Aug 25 00:19:27.572378: | adding 8 bytes of padding (including 1 byte padding-length)<br>Aug 25 00:19:27.572381: | emitting 1 0x00 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572383: | emitting 1 0x01 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572386: | emitting 1 0x02 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572388: | emitting 1 0x03 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572390: | emitting 1 0x04 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572393: | emitting 1 0x05 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572395: | emitting 1 0x06 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572397: | emitting 1 0x07 repeated bytes of padding and length into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572400: | emitting 16 zero bytes of length of truncated HMAC/KEY into IKEv2 Encryption Payload<br>Aug 25 00:19:27.572402: | emitting length of IKEv2 Encryption Payload: 52<br>Aug 25 00:19:27.572405: | emitting length of ISAKMP Message: 80<br>Aug 25 00:19:27.572462: | sending 80 bytes for delete notification through vni-1 from <a href="http://10.210.0.2:500">10.210.0.2:500</a> to <a href="http://10.213.0.2:500">10.213.0.2:500</a> (using #5)<br>Aug 25 00:19:27.572479: |   ee 79 84 10  1d 53 54 d0  45 ff 34 f4  d3 c7 7e fc<br>Aug 25 00:19:27.572481: |   2e 20 25 08  00 00 00 2c  00 00 00 50  2a 00 00 34<br>Aug 25 00:19:27.572483: |   7c 00 c8 3e  0f bd 20 83  0f 2e a3 bb  3a 78 20 e9<br>Aug 25 00:19:27.572485: |   43 9c 5c 80  25 ce 7f ef  b7 29 95 bc  a0 07 4d ae<br>Aug 25 00:19:27.572487: |   f4 bc 43 3c  b0 1b b3 15  3e ad 28 67  af c1 41 24<br>Aug 25 00:19:27.572538: | Message ID: IKE #5 sender #5 in send_delete hacking around record ' send<br>Aug 25 00:19:27.572559: | Message ID: IKE #5 XXX: expecting sender.wip.initiator 43 == -1 - suspect record'n'send out-of-order?): ike.initiator.sent=44 ike.initiator.recv=33 ike.responder.sent=5 ike.responder.recv=5 ike.wip.initiator=44 ike.wip.responder=-1<br>Aug 25 00:19:27.572564: | Message ID: IKE #5 updating initiator sent message request 44: ike.initiator.sent=43->44 ike.initiator.recv=33 ike.responder.sent=5 ike.responder.recv=5 ike.wip.initiator=43->44 ike.wip.responder=-1<br>Aug 25 00:19:27.572567: | state #5 requesting EVENT_SA_REKEY to be deleted<br>Aug 25 00:19:27.572573: | libevent_free: delref ptr-libevent@0x5594dd92c8e8<br>Aug 25 00:19:27.572577: | free_event_entry: delref EVENT_SA_REKEY-pe@0x5594dd933798<br>Aug 25 00:19:27.572580: | State DB: IKEv2 state not found (flush_incomplete_children)<br>Aug 25 00:19:27.572583: | picked newest_isakmp_sa #0 for #5<br>Aug 25 00:19:27.572586: "bn" #5: deleting IKE SA but connection is supposed to remain up; schedule EVENT_REVIVE_CONNS<br>Aug 25 00:19:27.572589: | add revival: connection 'bn' added to the list and scheduled for 0 seconds<br>Aug 25 00:19:27.572593: | global one-shot timer EVENT_REVIVE_CONNS scheduled in 0 seconds<br>Aug 25 00:19:27.572605: | in connection_discard for connection bn<br>Aug 25 00:19:27.572608: | State DB: deleting IKEv2 state #5 in PARENT_I3<br>Aug 25 00:19:27.572617: | parent state #5: PARENT_I3(established IKE SA) => UNDEFINED(ignore)<br>Aug 25 00:19:27.572620: | releasing #5's fd-fd@(nil) because deleting state<br>Aug 25 00:19:27.572622: | delref fdp@NULL (in delete_state() at state.c:1185)<br>Aug 25 00:19:27.572648: | stop processing: state #5 from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in delete_state() at state.c:1211)<br>Aug 25 00:19:27.572677: | processing: STOP state #0 (in foreach_state_by_connection_func_delete() at state.c:1378)<br>Aug 25 00:19:27.572681: | libevent_free: delref ptr-libevent@0x5594dd9385d8<br>Aug 25 00:19:27.572684: | free_event_entry: delref EVENT_v2_LIVENESS-pe@0x5594dd92b068<br>Aug 25 00:19:27.572687: | in statetime_stop() and could not find #6<br>Aug 25 00:19:27.572689: | processing: STOP state #0 (in timer_event_cb() at timer.c:557)<br>Aug 25 00:19:27.572701: | processing global timer EVENT_REVIVE_CONNS<br>Aug 25 00:19:27.572705: | FOR_EACH_CONNECTION_... in conn_by_name<br>Aug 25 00:19:27.572708: "bn": initiating connection which received a Delete/Notify but must remain up per local policy<br>Aug 25 00:19:27.572712: | start processing: connection "bn" (in initiate_connection() at initiate.c:182)<br>Aug 25 00:19:27.572715: | connection 'bn' +POLICY_UP<br>Aug 25 00:19:27.572717: | FOR_EACH_STATE_... in find_phase1_state<br>Aug 25 00:19:27.572729: | addref fd@NULL (in new_state() at state.c:555)<br>Aug 25 00:19:27.572732: | creating state object #7 at 0x5594dd92b608<br>Aug 25 00:19:27.572735: | State DB: adding IKEv2 state #7 in UNDEFINED<br>Aug 25 00:19:27.572788: | pstats #7 ikev2.ike started<br>Aug 25 00:19:27.572794: | parent state #7: UNDEFINED(ignore) => PARENT_I0(ignore)<br>Aug 25 00:19:27.572799: | Message ID: IKE #7 initializing (IKE SA): ike.initiator.sent=0->-1 ike.initiator.recv=0->-1 ike.responder.sent=0->-1 ike.responder.recv=0->-1 ike.wip.initiator=0->-1 ike.wip.responder=0->-1<br>Aug 25 00:19:27.572805: | suspend processing: connection "bn" (in ikev2_parent_outI1() at ikev2_parent.c:549)<br>Aug 25 00:19:27.572809: | start processing: state #7 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in ikev2_parent_outI1() at ikev2_parent.c:549)<br>Aug 25 00:19:27.572814: | addref fd@NULL (in add_pending() at pending.c:88)<br>Aug 25 00:19:27.572818: | "bn": queuing pending IPsec SA negotiating with 10.213.0.2 IKE SA #7 "bn"<br>Aug 25 00:19:27.572821: "bn" #7: initiating IKEv2 IKE SA<br>Aug 25 00:19:27.572841: | using existing local IKE proposals for connection bn (IKE SA initiator selecting KE): 1:IKE=AES_CBC_256-HMAC_SHA2_256-HMAC_SHA2_256_128-MODP1536<br>Aug 25 00:19:27.572848: | adding ikev2_outI1 KE work-order 7 for state #7<br>Aug 25 00:19:27.572851: | event_schedule: newref EVENT_CRYPTO_TIMEOUT-pe@0x5594dd92b068<br>Aug 25 00:19:27.572853: | inserting event EVENT_CRYPTO_TIMEOUT, timeout in 60 seconds for #7<br>Aug 25 00:19:27.572857: | libevent_malloc: newref ptr-libevent@0x5594dd929aa8 size 136<br>Aug 25 00:19:27.572869: | #7 spent 0.116 milliseconds in ikev2_parent_outI1()<br>Aug 25 00:19:27.572874: | RESET processing: state #7 connection "bn" from <a href="http://10.213.0.2:500">10.213.0.2:500</a> (in ikev2_parent_outI1() at ikev2_parent.c:633)<br>Aug 25 00:19:27.572889: | RESET processing: connection "bn" (in ikev2_parent_outI1() at ikev2_parent.c:633)<br>Aug 25 00:19:27.572892: | processing: STOP connection NULL (in initiate_connection() at initiate.c:357)<br>Aug 25 00:19:27.572896: | spent 0.151 milliseconds in global timer EVENT_REVIVE_CONNS<br>Aug 25 00:19:27.572898: | processing signal PLUTO_SIGCHLD<br>Aug 25 00:19:27.572902: | waitpid returned ECHILD (no child processes left)<br>Aug 25 00:19:27.572905: | spent 0.00373 milliseconds in signal handler PLUTO_SIGCHLD<br>Aug 25 00:19:27.572912: | crypto helper 0 resuming<br>Aug 25 00:19:27.572942: | crypto helper 0 starting work-order 7 for state #7<br>Aug 25 00:19:27.572951: | crypto helper 0 doing build KE and nonce (ikev2_outI1 KE); request ID 7<br>Aug 25 00:19:27.573409: | crypto helper 0 finished build KE and nonce (ikev2_outI1 KE); request ID 7 time elapsed 0.000457 seconds<br>Aug 25 00:19:27.573435: | (#7) spent 0.483 milliseconds in crypto helper computing work-order 7: ikev2_outI1 KE (pcr)<br>Aug 25 00:19:27.573439: | crypto helper 0 sending results from work-order 7 for state #7 to event queue<br>Aug 25 00:19:27.573442: | scheduling resume sending helper answer for #7<br>Aug 25 00:19:27.573445: | libevent_malloc: newref ptr-libevent@0x7f385c003068 size 136<br>Aug 25 00:19:27.573452: | crypto helper 0 waiting (nothing to do)<br></div></div></div></div>