[Swan-dev] During rekey, pluto always sends delete SAs, then add SAs results in data packets dropped
Sonia Rovner
sonrov at gmail.com
Tue Aug 25 02:15:36 UTC 2020
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.
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
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)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan-dev/attachments/20200824/1399ddab/attachment-0001.html>
More information about the Swan-dev
mailing list