[Swan] Libreswan don't want to up a child SA
Ivan Kuznetsov
kia at solvo.ru
Wed Dec 22 11:28:53 EET 2021
Hello
We have a linux box with libreswan 3.32 and kernel
4.1.12-112.14.10.el6uek.x86_64 (Oracle Linux 6) terminating a number of
IPsec site-to-site tunnels with our customers.
The problem tunnel configuration is typical for us, customer side uses a
Mikrotik router. Public IP's are masked as A.B.C.D our and E.F.G.H
customer's
conn customer
type=tunnel
auto=ondemand
authby=secret
left=A.B.C.D
leftsubnet=172.16.80.0/20
right=E.F.G.H
rightsubnets=10.50.1.8/29,10.50.2.8/29
ikev2=yes
ikelifetime=8h
ike=aes256-sha2;modp2048
phase2=esp
salifetime=1h
pfs=yes
encapsulation=no
rekey=yes
rekeymargin=5m
keyingtries=3
fragmentation=yes
dpddelay=30
dpdtimeout=120
dpdaction=restart
Sometimes there is a situation when first sub-tunnel to 10.50.1.8/29 is
up and works correctly but the second to 10.50.2.8/29 is not going up
while intersting traffic come in. Our side does not try to initiate
corresponding ESP SA up, there is no any IKE traffic to customer side at
that time. So we have access to one customer's network but not to
another. In some cases the problem disappears after some hours, probably
after parent SA rekey. Or we need to terminate/initiate the tunnel manually
The status in the problem state:
$ sudo ipsec auto --status |grep customer
000 "customer/0x1":
172.16.80.0/20===A.B.C.D<A.B.C.D>...E.F.G.H<E.F.G.H>===10.50.1.8/29;
erouted; eroute owner: #33751
000 "customer/0x1": oriented; my_ip=unset; their_ip=unset;
my_updown=ipsec _updown;
000 "customer/0x1": xauth us:none, xauth them:none,
my_username=[any]; their_username=[any]
000 "customer/0x1": our auth:secret, their auth:secret
000 "customer/0x1": modecfg info: us:none, them:none, modecfg
policy:push, dns:unset, domains:unset, banner:unset, cat:unset;
000 "customer/0x1": policy_label:unset;
000 "customer/0x1": ike_life: 28800s; ipsec_life: 3600s;
replay_window: 32; rekey_margin: 300s; rekey_fuzz: 100%; keyingtries: 3;
000 "customer/0x1": retransmit-interval: 500ms; retransmit-timeout: 60s;
000 "customer/0x1": initial-contact:no; cisco-unity:no;
fake-strongswan:no; send-vendorid:no; send-no-esp-tfc:no;
000 "customer/0x1": policy:
PSK+ENCRYPT+TUNNEL+PFS+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO;
000 "customer/0x1": v2-auth-hash-policy: none;
000 "customer/0x1": conn_prio: 20,29; interface: bond0.5; metric: 0;
mtu: unset; sa_prio:auto; sa_tfc:none;
000 "customer/0x1": nflog-group: unset; mark: unset; vti-iface:unset;
vti-routing:no; vti-shared:no; nic-offload:auto;
000 "customer/0x1": our idtype: ID_IPV4_ADDR; our id=A.B.C.D; their
idtype: ID_IPV4_ADDR; their id=E.F.G.H
000 "customer/0x1": dpd: action:restart; delay:30; timeout:120; nat-t:
encaps:no; nat_keepalive:yes; ikev1_natt:both
000 "customer/0x1": newest ISAKMP SA: #33417; newest IPsec SA: #33751;
000 "customer/0x1": aliases: customer
000 "customer/0x1": IKE algorithms: AES_CBC_256-HMAC_SHA2_256-MODP2048
000 "customer/0x1": IKEv2 algorithm newest:
AES_CBC_256-HMAC_SHA2_256-MODP2048
000 "customer/0x1": ESP algorithm newest:
AES_CBC_256-HMAC_SHA2_256_128; pfsgroup=<Phase1>
000 "customer/0x2":
172.16.80.0/20===A.B.C.D<A.B.C.D>...E.F.G.H<E.F.G.H>===10.50.2.8/29;
prospective erouted; eroute owner: #0
000 "customer/0x2": oriented; my_ip=unset; their_ip=unset;
my_updown=ipsec _updown;
000 "customer/0x2": xauth us:none, xauth them:none,
my_username=[any]; their_username=[any]
000 "customer/0x2": our auth:secret, their auth:secret
000 "customer/0x2": modecfg info: us:none, them:none, modecfg
policy:push, dns:unset, domains:unset, banner:unset, cat:unset;
000 "customer/0x2": policy_label:unset;
000 "customer/0x2": ike_life: 28800s; ipsec_life: 3600s;
replay_window: 32; rekey_margin: 300s; rekey_fuzz: 100%; keyingtries: 3;
000 "customer/0x2": retransmit-interval: 500ms; retransmit-timeout: 60s;
000 "customer/0x2": initial-contact:no; cisco-unity:no;
fake-strongswan:no; send-vendorid:no; send-no-esp-tfc:no;
000 "customer/0x2": policy:
PSK+ENCRYPT+TUNNEL+PFS+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO;
000 "customer/0x2": v2-auth-hash-policy: none;
000 "customer/0x2": conn_prio: 20,29; interface: bond0.5; metric: 0;
mtu: unset; sa_prio:auto; sa_tfc:none;
000 "customer/0x2": nflog-group: unset; mark: unset; vti-iface:unset;
vti-routing:no; vti-shared:no; nic-offload:auto;
000 "customer/0x2": our idtype: ID_IPV4_ADDR; our id=A.B.C.D; their
idtype: ID_IPV4_ADDR; their id=E.F.G.H
000 "customer/0x2": dpd: action:restart; delay:30; timeout:120; nat-t:
encaps:no; nat_keepalive:yes; ikev1_natt:both
000 "customer/0x2": newest ISAKMP SA: #0; newest IPsec SA: #0;
000 "customer/0x2": aliases: customer
000 "customer/0x2": IKE algorithms: AES_CBC_256-HMAC_SHA2_256-MODP2048
000 #33417: "customer/0x1":500 STATE_PARENT_I3 (PARENT SA established);
EVENT_SA_REKEY in 16654s; newest ISAKMP; idle;
000 #33751: "customer/0x1":500 STATE_V2_IPSEC_R (IPsec SA established);
EVENT_SA_REKEY in 3414s; newest IPSEC; eroute owner; isakmp#33417; idle;
000 #33751: "customer/0x1" esp.9d603d4 at E.F.G.H esp.232cb42f at A.B.C.D
tun.0 at E.F.G.H tun.0 at A.B.C.D ref=0 refhim=0 Traffic: ESPin=0B ESPout=0B!
ESPmax=0B
I began to ping 10.50.2.11 from 172.16.80.160 at 10:35:56 and took a
debug log, fragment is attached.
What can be a diagnose tactics?
--
Regards, Ivan Kuznetsov
SOVLO ltd
-------------- next part --------------
Dec 22 10:35:56.152809: | kernel_process_msg_cb process netlink message
Dec 22 10:35:56.152870: | netlink_get: XFRM_MSG_ACQUIRE message
Dec 22 10:35:56.152875: | xfrm netlink msg len 376
Dec 22 10:35:56.152878: | xfrm acquire rtattribute type 5
Dec 22 10:35:56.152881: | xfrm template attribute with reqid:0, spi:0, proto:50
Dec 22 10:35:56.152884: | xfrm acquire rtattribute type 16
Dec 22 10:35:56.152891: | subnet from endpoint 172.16.85.160:8 (in netlink_acquire() at kernel_xfrm.c:1822)
Dec 22 10:35:56.152895: | subnet from address 10.50.2.11 (in netlink_acquire() at kernel_xfrm.c:1823)
Dec 22 10:35:56.152900: | subnet from endpoint 172.16.85.160:8 (in has_bare_hold() at kernel.c:1265)
Dec 22 10:35:56.152904: | subnet from address 10.50.2.11 (in has_bare_hold() at kernel.c:1266)
Dec 22 10:35:56.152915: | add bare shunt 0xd20b50 172.16.85.160/32:8 --1--> 10.50.2.11/32:0 => %hold 0 %acquire-netlink
Dec 22 10:35:56.152922: initiate on demand from 172.16.85.160:8 to 10.50.2.11:0 proto=1 because: acquire
Dec 22 10:35:56.152929: | find_connection: looking for policy for connection: 172.16.85.160:1/8 -> 10.50.2.11:1/0
Dec 22 10:35:56.152932: | FOR_EACH_CONNECTION_... in find_connection_for_clients
Dec 22 10:35:56.152953: | find_connection: conn "customer/0x2" has compatible peers: 172.16.80.0/20:0 -> 10.50.2.8/29:0 [pri: 21030922]
Dec 22 10:35:56.152957: | find_connection: first OK "customer/0x2" [pri:21030922]{0xccd690} (child none)
Dec 22 10:35:56.152966: | find_connection: concluding with "customer/0x2" [pri:21030922]{0xccd690} kind=CK_PERMANENT
Dec 22 10:35:56.152970: | assign hold, routing was prospective erouted, needs to be erouted HOLD
Dec 22 10:35:56.152973: | assign_holdpass() need broad(er) shunt
Dec 22 10:35:56.152977: | priority calculation of connection "customer/0x2" is 0x1fd7c4
Dec 22 10:35:56.152983: | eroute_connection replace %trap with broad %pass or %hold eroute 172.16.80.0/20:0 --0-> 10.50.2.8/29:0 => %hold>%hold using reqid 0 (raw_eroute)
Dec 22 10:35:56.152989: | netlink_raw_eroute: SPI_HOLD implemented as no-op
Dec 22 10:35:56.152993: | raw_eroute result=success
Dec 22 10:35:56.152995: | assign_holdpass() eroute_connection() done
Dec 22 10:35:56.152999: | fiddle_bare_shunt called
Dec 22 10:35:56.153003: | subnet from endpoint 172.16.85.160:8 (in fiddle_bare_shunt() at kernel.c:1344)
Dec 22 10:35:56.153006: | subnet from address 10.50.2.11 (in fiddle_bare_shunt() at kernel.c:1345)
Dec 22 10:35:56.153010: | fiddle_bare_shunt with transport_proto 1
Dec 22 10:35:56.153013: | removing specific host-to-host bare shunt
Dec 22 10:35:56.153019: | delete narrow %hold eroute 172.16.85.160/32:8 --1-> 10.50.2.11/32:0 => %hold using reqid 0 (raw_eroute)
Dec 22 10:35:56.153022: | netlink_raw_eroute: SPI_PASS
Dec 22 10:35:56.153033: | raw_eroute result=success
Dec 22 10:35:56.153037: | raw_eroute with op='delete' for transport_proto='1' kernel shunt succeeded, bare shunt lookup succeeded
Dec 22 10:35:56.153043: | delete bare shunt 0xd20b50 172.16.85.160/32:8 --1--> 10.50.2.11/32:0 => %hold 0 %acquire-netlink
Dec 22 10:35:56.153047: assign_holdpass() delete_bare_shunt() failed
Dec 22 10:35:56.153050: initiate_ondemand_body() failed to install negotiation_shunt,
Dec 22 10:35:56.153053: | FOR_EACH_STATE_... in find_phase1_state
Dec 22 10:35:56.153069: | FOR_EACH_STATE_... in find_pending_phase2
Dec 22 10:35:56.153085: | addref fd at NULL (in new_state() at state.c:555)
Dec 22 10:35:56.153089: | creating state object #33787 at 0xe00c00
Dec 22 10:35:56.153093: | State DB: adding IKEv2 state #33787 in UNDEFINED
Dec 22 10:35:56.153098: | serialno list: inserting #33787 (nil)<-0xe01470->(nil) into list HEAD 0xf18610<-0x798e40->0xe0aa10
Dec 22 10:35:56.153102: | serialno list: inserted #33787 0xf18610<-0xe01470->0x798e40 into list HEAD 0xe01470<-0x798e40->0xe0aa10
Dec 22 10:35:56.153106: | st_serialno table: inserting #33787 (nil)<-0xe01490->(nil) into list HEAD 0xd16be0<-0x77f560->0xd16be0
Dec 22 10:35:56.153110: | st_serialno table: inserted #33787 0xd16be0<-0xe01490->0x77f560 into list HEAD 0xe01490<-0x77f560->0xd16be0
Dec 22 10:35:56.153114: | st_connection table: inserting #33787 (nil)<-0xe014b0->(nil) into list HEAD 0x7812c0<-0x7812c0->0x7812c0
Dec 22 10:35:56.153117: | st_connection table: inserted #33787 0x7812c0<-0xe014b0->0x7812c0 into list HEAD 0xe014b0<-0x7812c0->0xe014b0
Dec 22 10:35:56.153121: | st_reqid table: inserting #33787 (nil)<-0xe014d0->(nil) into list HEAD 0xf18670<-0x785120->0xe0aa70
Dec 22 10:35:56.153125: | st_reqid table: inserted #33787 0xf18670<-0xe014d0->0x785120 into list HEAD 0xe014d0<-0x785120->0xe0aa70
Dec 22 10:35:56.153132: | IKE SPI[ir] table: inserting #33787: d2 f4 27 1f 2e 33 24 99 5f 65 35 39 75 07 61 a3 (nil)<-0xe014f0->(nil) into list HEAD 0xd0f740<-0x78a0a0->0xf52070
Dec 22 10:35:56.153139: | IKE SPI[ir] table: inserted #33787: d2 f4 27 1f 2e 33 24 99 5f 65 35 39 75 07 61 a3 0xd0f740<-0xe014f0->0x78a0a0 into list HEAD 0xe014f0<-0x78a0a0->0xf52070
Dec 22 10:35:56.153144: | IKE SPIi table: inserting #33787: d2 f4 27 1f 2e 33 24 99 (nil)<-0xe01510->(nil) into list HEAD 0xd0f760<-0x78d7e0->0xf52090
Dec 22 10:35:56.153149: | IKE SPIi table: inserted #33787: d2 f4 27 1f 2e 33 24 99 0xd0f760<-0xe01510->0x78d7e0 into list HEAD 0xe01510<-0x78d7e0->0xf52090
Dec 22 10:35:56.153152: | pstats #33787 ikev2.child started
Dec 22 10:35:56.153156: | duplicating state object #33417 "customer/0x1" as #33787 for IPSEC SA
Dec 22 10:35:56.153160: | st_connection table: removing #33787 0x7812c0<-0xe014b0->0x7812c0
Dec 22 10:35:56.153163: | st_connection table: empty
Dec 22 10:35:56.153177: | st_connection table: inserting #33787 (nil)<-0xe014b0->(nil) into list HEAD 0xd0f700<-0x784120->0xf52030
Dec 22 10:35:56.153181: | st_connection table: inserted #33787 0xd0f700<-0xe014b0->0x784120 into list HEAD 0xe014b0<-0x784120->0xf52030
Dec 22 10:35:56.153186: | #33787 setting local endpoint to A.B.C.D:500 from #33417.st_localport (in duplicate_state() at state.c:1548)
Dec 22 10:35:56.153195: | Message ID: CHILD #33417.#33787 initializing (CHILD SA): ike.initiator.sent=397 ike.initiator.recv=175 ike.responder.sent=125 ike.responder.recv=125 child.wip.initiator=0->-1 child.wip.responder=0->-1
Dec 22 10:35:56.153198: | st_connection table: removing #33787 0xd0f700<-0xe014b0->0x784120
Dec 22 10:35:56.153202: | st_connection table: updated older #33751 0xf52030<-0xd0f700->0x784120
Dec 22 10:35:56.153205: | st_connection table: updated newer HEAD 0xd0f700<-0x784120->0xf52030
Dec 22 10:35:56.153209: | st_connection table: inserting #33787 (nil)<-0xe014b0->(nil) into list HEAD 0x785080<-0x785080->0x785080
Dec 22 10:35:56.153213: | st_connection table: inserted #33787 0x785080<-0xe014b0->0x785080 into list HEAD 0xe014b0<-0x785080->0xe014b0
Dec 22 10:35:56.153216: | in connection_discard for connection customer/0x1
Dec 22 10:35:56.153221: | start processing: state #33787 connection "customer/0x2" from E.F.G.H:500 (in ikev2_initiate_child_sa() at ikev2_parent.c:5825)
Dec 22 10:35:56.153226: | child state #33787: UNDEFINED(ignore) => V2_CREATE_I0(established IKE SA)
Dec 22 10:35:56.153237: | using existing local ESP/AH proposals for customer/0x2 (ESP/AH initiator emitting proposals): 1:ESP=AES_GCM_C_256-NONE-MODP2048-DISABLED 2:ESP=AES_GCM_C_128-NONE-MODP2048-DISABLED 3:ESP=AES_CBC_256-HMAC_SHA2_512_256+HMAC_SHA2_256_128-MODP2048-DISABLED 4:ESP=AES_CBC_128-HMAC_SHA2_512_256+HMAC_SHA2_256_128-MODP2048-DISABLED
Dec 22 10:35:56.153247: | #33787 schedule initiate IPsec SA PSK+ENCRYPT+TUNNEL+PFS+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO using IKE# 33417 pfs=MODP2048
Dec 22 10:35:56.153251: | event_schedule: newref EVENT_v2_INITIATE_CHILD-pe at 0xd48df0
Dec 22 10:35:56.153255: | inserting event EVENT_v2_INITIATE_CHILD, timeout in 0 seconds for #33787
Dec 22 10:35:56.153259: | libevent_malloc: newref ptr-libevent at 0xe64b10 size 136
Dec 22 10:35:56.153266: | RESET processing: state #33787 connection "customer/0x2" from E.F.G.H:500 (in ikev2_initiate_child_sa() at ikev2_parent.c:5923)
Dec 22 10:35:56.153271: | initiate on demand using RSASIG from 172.16.85.160 to 10.50.2.11
Dec 22 10:35:56.153279: | spent 0.41 milliseconds in kernel message
Dec 22 10:35:56.153286: | timer_event_cb: processing event at 0xd48df0
Dec 22 10:35:56.153290: | handling event EVENT_v2_INITIATE_CHILD for child state #33787
Dec 22 10:35:56.153295: | start processing: state #33787 connection "customer/0x2" from E.F.G.H:500 (in timer_event_cb() at timer.c:250)
Dec 22 10:35:56.153301: | adding Child Initiator KE and nonce ni work-order 57429 for state #33787
Dec 22 10:35:56.153305: | event_schedule: newref EVENT_CRYPTO_TIMEOUT-pe at 0xe2fda0
Dec 22 10:35:56.153308: | inserting event EVENT_CRYPTO_TIMEOUT, timeout in 60 seconds for #33787
Dec 22 10:35:56.153311: | libevent_malloc: newref ptr-libevent at 0xd0e820 size 136
Dec 22 10:35:56.153316: | backlog: inserting work-order 57429 state #33787 (nil)<-0xf5e0a0->(nil) into list HEAD 0x79dc20<-0x79dc20->0x79dc20
Dec 22 10:35:56.153320: | backlog: inserted work-order 57429 state #33787 0x79dc20<-0xf5e0a0->0x79dc20 into list HEAD 0xf5e0a0<-0x79dc20->0xf5e0a0
Dec 22 10:35:56.153328: | libevent_free: delref ptr-libevent at 0xe64b10
Dec 22 10:35:56.153331: | free_event_entry: delref EVENT_v2_INITIATE_CHILD-pe at 0xd48df0
Dec 22 10:35:56.153336: | #33787 spent 0.0492 milliseconds in timer_event_cb() EVENT_v2_INITIATE_CHILD
Dec 22 10:35:56.153341: | stop processing: state #33787 connection "customer/0x2" from E.F.G.H:500 (in timer_event_cb() at timer.c:557)
Dec 22 10:35:56.153345: | crypto helper 1 resuming
Dec 22 10:35:56.153360: | backlog: removing work-order 57429 state #33787 0x79dc20<-0xf5e0a0->0x79dc20
Dec 22 10:35:56.153363: | backlog: empty
Dec 22 10:35:56.153368: | crypto helper 1 starting work-order 57429 for state #33787
Dec 22 10:35:56.153372: | crypto helper 1 doing build KE and nonce (Child Initiator KE and nonce ni); request ID 57429
Dec 22 10:35:56.154110: | crypto helper 1 finished build KE and nonce (Child Initiator KE and nonce ni); request ID 57429 time elapsed 0.000738 seconds
Dec 22 10:35:56.154119: | (#33787) spent 0.745 milliseconds in crypto helper computing work-order 57429: Child Initiator KE and nonce ni (pcr)
Dec 22 10:35:56.154123: | crypto helper 1 sending results from work-order 57429 for state #33787 to event queue
Dec 22 10:35:56.154126: | scheduling resume sending helper answer for #33787
Dec 22 10:35:56.154130: | libevent_malloc: newref ptr-libevent at 0x7f5a5404a040 size 136
Dec 22 10:35:56.154138: | crypto helper 1 waiting (nothing to do)
Dec 22 10:35:56.154186: | processing resume sending helper answer for #33787
Dec 22 10:35:56.154200: | start processing: state #33787 connection "customer/0x2" from E.F.G.H:500 (in resume_handler() at server.c:817)
Dec 22 10:35:56.154205: | unsuspending #33787 MD (nil)
Dec 22 10:35:56.154209: | crypto helper 1 replies to request ID 57429
Dec 22 10:35:56.154212: | calling continuation function 0x4aae90
Dec 22 10:35:56.154215: | ikev2_child_outI_continue() for #33787 STATE_V2_CREATE_I0
Dec 22 10:35:56.154221: | adding CHILD SA #33787 to IKE SA #33417 message initiator queue
Dec 22 10:35:56.154225: | state #33787 requesting EVENT_CRYPTO_TIMEOUT to be deleted
Dec 22 10:35:56.154229: | libevent_free: delref ptr-libevent at 0xd0e820
Dec 22 10:35:56.154232: | free_event_entry: delref EVENT_CRYPTO_TIMEOUT-pe at 0xe2fda0
Dec 22 10:35:56.154235: | event_schedule: newref EVENT_SA_REPLACE-pe at 0xe2fda0
Dec 22 10:35:56.154239: | inserting event EVENT_SA_REPLACE, timeout in 200 seconds for #33787
Dec 22 10:35:56.154247: | libevent_malloc: newref ptr-libevent at 0xf522c0 size 136
Dec 22 10:35:56.154253: | Message ID: CHILD #33417.#LOST next initiator blocked by outstanding response (unack 222): ike.initiator.sent=397 ike.initiator.recv=175 ike.responder.sent=125 ike.responder.recv=125
Dec 22 10:35:56.154257: | MD.ST contains the CHILD SA #33787
Dec 22 10:35:56.154262: | [RE]START processing: state #33787 connection "customer/0x2" from E.F.G.H:500 (in complete_v2_state_transition() at ikev2.c:3235)
Dec 22 10:35:56.154266: | #33787 complete_v2_state_transition() V2_CREATE_I0 -> V2_CREATE_I with status STF_SUSPEND
Dec 22 10:35:56.154270: | suspending state #33787 and saving MD 0xf08040
Dec 22 10:35:56.154273: | #33787 is busy; has suspended MD 0xf08040
Dec 22 10:35:56.154277: | [RE]START processing: state #33787 connection "customer/0x2" from E.F.G.H:500 (in log_stf_suspend() at ikev2.c:3030)
Dec 22 10:35:56.154281: | "customer/0x2" #33787 complete v2 state STATE_V2_CREATE_I0 transition with STF_SUSPEND suspended from complete_v2_state_transition:3313
Dec 22 10:35:56.154285: | resume sending helper answer for #33787 suppresed complete_v2_state_transition()
Dec 22 10:35:56.154290: | #33787 spent 0.0839 milliseconds in resume sending helper answer
Dec 22 10:35:56.154295: | stop processing: state #33787 connection "customer/0x2" from E.F.G.H:500 (in resume_handler() at server.c:860)
Dec 22 10:35:56.154298: | libevent_free: delref ptr-libevent at 0x7f5a5404a040
Dec 22 10:36:05.114632: | timer_event_cb: processing event at 0xf04500
Dec 22 10:36:05.114675: | handling event EVENT_v2_LIVENESS for child state #33751
Dec 22 10:36:05.114696: | start processing: state #33751 connection "customer/0x1" from E.F.G.H:500 (in timer_event_cb() at timer.c:250)
Dec 22 10:36:05.114713: | [RE]START processing: state #33751 connection "customer/0x1" from E.F.G.H:500 (in liveness_check() at timer.c:113)
Dec 22 10:36:05.114733: | get_sa_info esp.232cb42f at A.B.C.D
Dec 22 10:36:05.114770: | #33751 liveness_check - last_liveness: 21827561.686895, now: 21827619.411601 parent #33417
Dec 22 10:36:05.114783: | Opening output PBS liveness probe informational request
Dec 22 10:36:05.114794: | **emit ISAKMP Message:
Dec 22 10:36:05.114807: | initiator cookie: d2 f4 27 1f 2e 33 24 99
Dec 22 10:36:05.114820: | responder cookie: 5f 65 35 39 75 07 61 a3
Dec 22 10:36:05.114829: | next payload type: ISAKMP_NEXT_NONE (0x0)
Dec 22 10:36:05.114838: | ISAKMP version: IKEv2 version 2.0 (rfc4306/rfc5996) (0x20)
Dec 22 10:36:05.114848: | exchange type: ISAKMP_v2_INFORMATIONAL (0x25)
Dec 22 10:36:05.114858: | flags: ISAKMP_FLAG_v2_IKE_INIT (0x8)
Dec 22 10:36:05.114869: | Message ID: 398 (00 00 01 8e)
Dec 22 10:36:05.114879: | next payload chain: saving message location 'ISAKMP Message'.'next payload type'
Dec 22 10:36:05.114906: | ***emit IKEv2 Encryption Payload:
Dec 22 10:36:05.114916: | next payload type: ISAKMP_NEXT_v2NONE (0x0)
Dec 22 10:36:05.114925: | flags: none (0x0)
Dec 22 10:36:05.114936: | next payload chain: setting previous 'ISAKMP Message'.'next payload type' to current IKEv2 Encryption Payload (46:ISAKMP_NEXT_v2SK)
Dec 22 10:36:05.114945: | next payload chain: saving location 'IKEv2 Encryption Payload'.'next payload type' in 'liveness probe informational request'
Dec 22 10:36:05.114956: | emitting 16 zero bytes of IV into IKEv2 Encryption Payload
Dec 22 10:36:05.114984: | adding 16 bytes of padding (including 1 byte padding-length)
Dec 22 10:36:05.114995: | emitting 1 0x00 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115004: | emitting 1 0x01 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115013: | emitting 1 0x02 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115022: | emitting 1 0x03 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115031: | emitting 1 0x04 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115040: | emitting 1 0x05 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115049: | emitting 1 0x06 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115058: | emitting 1 0x07 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115067: | emitting 1 0x08 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115076: | emitting 1 0x09 repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115085: | emitting 1 0x0a repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115094: | emitting 1 0x0b repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115103: | emitting 1 0x0c repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115112: | emitting 1 0x0d repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115121: | emitting 1 0x0e repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115130: | emitting 1 0x0f repeated bytes of padding and length into IKEv2 Encryption Payload
Dec 22 10:36:05.115140: | emitting 16 zero bytes of length of truncated HMAC/KEY into IKEv2 Encryption Payload
Dec 22 10:36:05.115149: | emitting length of IKEv2 Encryption Payload: 52
Dec 22 10:36:05.115157: | emitting length of ISAKMP Message: 80
Dec 22 10:36:05.115271: | sending 80 bytes for liveness probe informational request through bond0.5 from A.B.C.D:500 to E.F.G.H:500 (using #33751)
Dec 22 10:36:05.115282: | d2 f4 27 1f 2e 33 24 99 5f 65 35 39 75 07 61 a3
Dec 22 10:36:05.115288: | 2e 20 25 08 00 00 01 8e 00 00 00 50 00 00 00 34
Dec 22 10:36:05.115294: | ad bd 88 41 f4 61 20 77 b0 2d d1 fd 67 d2 d9 c7
Dec 22 10:36:05.115300: | 89 9c 40 e2 e3 b4 2c d6 20 16 c5 cc be 83 45 31
Dec 22 10:36:05.115306: | 5e cd a8 24 63 b0 26 9f b7 df ed 47 d4 98 cc 47
Dec 22 10:36:05.115348: | Message ID: CHILD #33417.#33751 XXX: in ikev2_send_livenss_probe() hacking around record'n'send bypassing send queue: ike.initiator.sent=397 ike.initiator.recv=175 ike.responder.sent=125 ike.responder.recv=125 child.wip.initiator=-1 child.wip.responder=-1
Dec 22 10:36:05.115361: | Message ID: IKE #33417 XXX: expecting sender.wip.initiator 397 == -1 - suspect record'n'send out-of-order?): ike.initiator.sent=398 ike.initiator.recv=175 ike.responder.sent=125 ike.responder.recv=125 ike.wip.initiator=398 ike.wip.responder=-1
Dec 22 10:36:05.115371: | Message ID: IKE #33417 updating initiator sent message request 398: ike.initiator.sent=397->398 ike.initiator.recv=175 ike.responder.sent=125 ike.responder.recv=125 ike.wip.initiator=397->398 ike.wip.responder=-1
Dec 22 10:36:05.115379: | #33751 liveness_check - peer E.F.G.H is missing - giving them some time to come back
Dec 22 10:36:05.115403: | #33751 liveness_check - peer E.F.G.H is ok schedule new
Dec 22 10:36:05.115412: | event_schedule: newref EVENT_v2_LIVENESS-pe at 0xdf4da0
Dec 22 10:36:05.115419: | inserting event EVENT_v2_LIVENESS, timeout in 30 seconds for #33751
Dec 22 10:36:05.115427: | libevent_malloc: newref ptr-libevent at 0xd0b670 size 136
Dec 22 10:36:05.115437: | libevent_free: delref ptr-libevent at 0xe15720
Dec 22 10:36:05.115444: | free_event_entry: delref EVENT_v2_LIVENESS-pe at 0xf04500
Dec 22 10:36:05.115458: | #33751 spent 0.829 milliseconds in timer_event_cb() EVENT_v2_LIVENESS
Dec 22 10:36:05.115469: | stop processing: state #33751 connection "customer/0x1" from E.F.G.H:500 (in timer_event_cb() at timer.c:557)
More information about the Swan
mailing list