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