[ClusterLabs] Constant stop/start of resource in spite of interval=0
Kadlecsik József
kadlecsik.jozsef at wigner.mta.hu
Mon May 20 08:37:26 EDT 2019
On Sun, 19 May 2019, Kadlecsik József wrote:
> On Sat, 18 May 2019, Kadlecsik József wrote:
>
> > On Sat, 18 May 2019, Kadlecsik József wrote:
> >
> > > On Sat, 18 May 2019, Andrei Borzenkov wrote:
> > >
> > > > 18.05.2019 18:34, Kadlecsik József пишет:
> > >
> > > > > We have a resource agent which creates IP tunnels. In spite of the
> > > > > configuration setting
> > > > >
> > > > > primitive tunnel-eduroam ocf:local:tunnel \
> > > > > params ....
> > > > > op start timeout=120s interval=0 \
> > > > > op stop timeout=300s interval=0 \
> > > > > op monitor timeout=30s interval=30s depth=0 \
> > > > > meta target-role=Started
> > > > > order bifur-eduroam-ipv4-before-tunnel-eduroam \
> > > > > Mandatory: bifur-eduroam-ipv4 tunnel-eduroam
> > > > > colocation tunnel-eduroam-on-bifur-eduroam-ipv4 inf: tunnel-eduroam \
> > > > > bifur-eduroam-ipv4:Started
> > > > >
> > > > > the resource is restarted again and again. According to the debug logs:
> > > > >
> > > > > Parameters to tunnel-eduroam_start_0 on bifur1 changed: was
> > > > > 94afff0ff7cfc62f7cb1d5bf5b4d83aa vs. now f2317cad3d54cec5d7d7aa7d0bf35cf8
> > > > > (restart:3.0.11) 0:0;48:3:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
> > > >
> > > > This means that instance attributes changed in this case pacemaker
> > > > restarts resource to apply new values. Turning on trace level hopefully
> > > > will show what exactly is being changed. You can also dump CIB before
> > > > and after restart to compare current information.
> > >
> > > The strange thing is that the new value seems never be stored. Just the
> > > "was-now" part from the log lines:
> > >
> > > was 94afff0ff7cfc62f7cb1d5bf5b4d83aa vs. now f2317cad3d54cec5d7d7aa7d0bf35cf8
> > > was 94afff0ff7cfc62f7cb1d5bf5b4d83aa vs. now f2317cad3d54cec5d7d7aa7d0bf35cf8
> > > was 94afff0ff7cfc62f7cb1d5bf5b4d83aa vs. now f2317cad3d54cec5d7d7aa7d0bf35cf8
> > > ...
> > >
> > > However, after issuing "cibadmin --query --local", the whole flipping
> > > stopped! :-) Thanks!
> >
> > No, I was wrong - it still repeats every ~15mins. The diff between two cib
> > xml dumps doesn't say much to me - I'm going to enable tracing.
>
> I have attached the trace file created according to
> http://blog.clusterlabs.org/blog/2013/pacemaker-logging.
>
> What looks strange to me is that build_parameter_list() first rejects
> attributes, then accepts them:
>
> trace May 18 23:02:49 build_operation_update(787):0: Including additional digests for ocf::local:tunnel
> trace May 18 23:02:49 build_parameter_list(621):0: Rejecting name for unique
> trace May 18 23:02:49 build_parameter_list(614):0: Attr id is unique
> trace May 18 23:02:49 build_parameter_list(632):0: Adding attr id=0 to the xml result
> trace May 18 23:02:49 build_parameter_list(621):0: Rejecting src_ip for unique
> trace May 18 23:02:49 build_parameter_list(621):0: Rejecting dst_ip for unique
> ...
> trace May 18 23:02:49 calculate_xml_digest_v1(71):0: Sorting xml...
> trace May 18 23:02:49 calculate_xml_digest_v1(73):0: Done
> trace May 18 23:02:49 crm_md5sum(2102):0: Beginning digest of 22 bytes
> trace May 18 23:02:49 crm_md5sum(2110):0: Digest 94afff0ff7cfc62f7cb1d5bf5b4d83aa.
>
> and then:
>
> trace May 18 23:02:49 calculate_xml_digest_v1(83):0: digest:source <parameters id="0"/>
> trace May 18 23:02:49 append_restart_list(693):0: tunnel-eduroam: 94afff0ff7cfc62f7cb1d5bf5b4d83aa, id
> trace May 18 23:02:49 append_restart_list(694):0: restart digest source <parameters id="0"/>
> trace May 18 23:02:49 build_parameter_list(621):0: Rejecting name for private
> trace May 18 23:02:49 build_parameter_list(625):0: Inverting name match for private xml
> trace May 18 23:02:49 build_parameter_list(632):0: Adding attr name=eduroam IPv4 tunnel to the xml result
> trace May 18 23:02:49 build_parameter_list(621):0: Rejecting id for private
> trace May 18 23:02:49 build_parameter_list(625):0: Inverting id match for private xml
> trace May 18 23:02:49 build_parameter_list(632):0: Adding attr id=0 to the xml result
> ....
>
> By the way, it's debian stretch with pacemaker 1.1.16-1.
I have double and triple checked the agent and it seems just a normal,
working agent.
The agent accepts the reload operation, it is advertised in the actions
section of its metadata, there are parameters with unique set to 0 and
still stop/start is called instead of reload. (I could even live with
reload instead of start/stop in every 15 mins).
As a desperate attempt, I deleted the resource and re-added and it of
course did not help.
I also created the attached trace file during creating the resource in the
hope that it could help find the reason of the permanent stop/start.
Best regards,
Jozsef
--
E-mail : kadlecsik.jozsef at wigner.mta.hu
PGP key: http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address: Wigner Research Centre for Physics, Hungarian Academy of Sciences
H-1525 Budapest 114, POB. 49, Hungary
-------------- next part --------------
Dumping the contents of /var/lib/pacemaker/blackbox/crmd-3055.10
Ringbuffer:
->NORMAL
->write_pt [57310]
->read_pt [0]
->size [1311744 words]
=>free [5017732 bytes]
=>used [229240 bytes]
trace May 20 13:56:15 crm_ipc_read(1003):0: Received cib_shm event 16857, size=5101, rc=5101, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_apply_diff" cib_rc="0" cib_object_type="di
trace May 20 13:56:15 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 5061 (I/O condition=1)
trace May 20 13:56:15 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:15 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 20 13:56:15 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 20 13:56:15 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 20 13:56:15 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:15 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 20 13:56:15 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:15 xml_patch_versions(1747):0: Got 590 for del[epoch]
trace May 20 13:56:15 xml_patch_versions(1747):0: Got 5 for del[num_updates]
trace May 20 13:56:15 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:15 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:15 xml_patch_versions(1758):0: Got 0 for add[num_updates]
debug May 20 13:56:15 te_update_diff(390):0: Processing (cib_apply_diff) diff: 0.590.5 -> 0.591.0 (S_IDLE)
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <diff format="2" digest="959e8ef4142dda015c89d034f0bf0171">
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <version>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="590" num_updates="5"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="591" num_updates="0"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </version>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <change-attr name="epoch" operation="set" value="591"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="0"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="591" num_updates="0" admin_epoch="0" cib-last-written="Mon May 20 13:54:59 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <change operation="create" path="/cib/configuration/resources" position="21">
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <primitive id="tunnel-eduroam" class="ocf" provider="local" type="tunnel">
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <instance_attributes id="tunnel-eduroam-instance_attributes">
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="name" value="eduroam IPv4 tunnel" id="tunnel-eduroam-instance_attributes-name"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="id" value="0" id="tunnel-eduroam-instance_attributes-id"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="src_ip" value="a.b.c.d" id="tunnel-eduroam-instance_attributes-src_ip"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="dst_ip" value="e.f.g.h" id="tunnel-eduroam-instance_attributes-dst_ip"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="tunnel_src_ip" value="10.10.1.1" id="tunnel-eduroam-instance_attributes-tunnel_src_ip"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="tunnel_dst_ip" value="10.10.0.1" id="tunnel-eduroam-instance_attributes-tunnel_dst_ip"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="network" value="i.j.k.l/24" id="tunnel-eduroam-instance_attributes-network"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="iface_out" value="publ-br1" id="tunnel-eduroam-instance_attributes-iface_out"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="iface_in" value="publ-br0.18" id="tunnel-eduroam-instance_attributes-iface_in"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </instance_attributes>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <operations>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <op name="start" timeout="120s" interval="0" id="tunnel-eduroam-start-0"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <op name="stop" timeout="300s" interval="0" id="tunnel-eduroam-stop-0"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <op name="monitor" timeout="30" interval="30" id="tunnel-eduroam-monitor-30"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </operations>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <meta_attributes id="tunnel-eduroam-meta_attributes">
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <nvpair name="target-role" value="Started" id="tunnel-eduroam-meta_attributes-target-role"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </meta_attributes>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </primitive>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <change operation="create" path="/cib/configuration/constraints" position="25">
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <rsc_order id="bifur-eduroam-ipv4-before-tunnel-eduroam" kind="Mandatory" first="bifur-eduroam-ipv4" then="tunnel-eduroam"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <change operation="create" path="/cib/configuration/constraints" position="26">
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw <rsc_colocation id="tunnel-eduroam-on-bifur-eduroam-ipv4" score="INFINITY" rsc="tunnel-eduroam" with-rsc="bifur-eduroam-ipv4" with-rsc-role="Started"/>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:15 te_update_diff(399):0: Patch:Raw </diff>
trace May 20 13:56:15 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 20 13:56:15 te_update_diff(439):0: Handling create operation for /cib/configuration/resources matched by primitive
trace May 20 13:56:15 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:15 xml_patch_versions(1747):0: Got 590 for del[epoch]
trace May 20 13:56:15 xml_patch_versions(1747):0: Got 5 for del[num_updates]
trace May 20 13:56:15 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:15 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:15 xml_patch_versions(1758):0: Got 0 for add[num_updates]
info May 20 13:56:15 abort_transition_graph(649):0: Transition aborted by primitive.tunnel-eduroam 'create': Configuration change | cib=0.591.0 source=te_update_diff:444 path=/cib/configuration/resources complete=true
trace May 20 13:56:15 register_fsa_input_adv(113):0: abort_transition_graph appended FSA input 1350 (I_PE_CALC) (cause=C_FSA_INTERNAL) without data
trace May 20 13:56:15 register_fsa_input_adv(175):0: Queue len: 1
trace May 20 13:56:15 register_fsa_input_adv(184):0: Triggering FSA: register_fsa_input_adv
trace May 20 13:56:15 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:15 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 20 13:56:15 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 20 13:56:15 crm_fsa_trigger(312):0: Invoked (queue len: 1)
trace May 20 13:56:15 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_IDLE
trace May 20 13:56:15 s_crmd_fsa(175):0: Checking messages (1 remaining)
trace May 20 13:56:15 get_message(275):0: Processing input 1350
trace May 20 13:56:15 log_fsa_input(455):0: Processing queued input 1350
trace May 20 13:56:15 log_fsa_input(463):0: FSA processing input from abort_transition_graph
trace May 20 13:56:15 fsa_dump_actions(904):0: Action 0002000000000000 (A_PE_INVOKE) New actions
debug May 20 13:56:15 s_crmd_fsa(197):0: Processing I_PE_CALC: [ state=S_IDLE cause=C_FSA_INTERNAL origin=abort_transition_graph ]
trace May 20 13:56:15 do_state_transition(492):0: actions:trace: S_IDLE -> S_POLICY_ENGINE [ label=I_PE_CALC cause=C_FSA_INTERNAL origin=abort_transition_graph ]
notice May 20 13:56:15 do_state_transition(509):0: State transition S_IDLE -> S_POLICY_ENGINE | input=I_PE_CALC cause=C_FSA_INTERNAL origin=abort_transition_graph
trace May 20 13:56:15 crm_set_bit(185):0: Bit 0x00000020 set by do_state
trace May 20 13:56:15 crm_set_bit(185):0: Bit 0x00000080 set by do_state
trace May 20 13:56:15 crm_set_bit(185):0: Bit 0x00000200 set by do_state
trace May 20 13:56:15 crm_timer_stop(219):0: Stopping PEngine Recheck Timer (I_PE_CALC:900000ms), src=7197
trace May 20 13:56:15 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:15 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
debug May 20 13:56:15 do_state_transition(606):0: All 2 cluster nodes are eligible to run resources.
trace May 20 13:56:15 do_fsa_action(142):0: actions:trace: // A_DC_TIMER_STOP
trace May 20 13:56:15 crm_timer_stop(225):0: Election Trigger (I_DC_TIMEOUT:20000ms) already stopped
trace May 20 13:56:15 do_fsa_action(142):0: actions:trace: // A_INTEGRATE_TIMER_STOP
trace May 20 13:56:15 crm_timer_stop(225):0: Integration Timer (I_INTEGRATED:180000ms) already stopped
trace May 20 13:56:15 do_fsa_action(142):0: actions:trace: // A_FINALIZE_TIMER_STOP
trace May 20 13:56:15 crm_timer_stop(225):0: Finalization Timer (I_ELECTION:1800000ms) already stopped
trace May 20 13:56:15 do_fsa_action(142):0: actions:trace: // A_PE_INVOKE
trace May 20 13:56:15 cib_create_op(609):0: Sending call options: 00000100, 256
trace May 20 13:56:15 cib_native_perform_op_delegate(384):0: Sending cib_query message to CIB service (timeout=120s)
trace May 20 13:56:15 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 8746 bytes: 193 timeout:120000 msg...
trace May 20 13:56:15 crm_ipc_send(1202):0: Message sent, not waiting for reply to 8746 from cib_shm to 193 bytes...
trace May 20 13:56:15 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 20 13:56:15 cib_native_perform_op_delegate(398):0: Async call, returning 3827
debug May 20 13:56:15 do_pe_invoke(233):0: Query 3827: Requesting the current CIB: S_POLICY_ENGINE
trace May 20 13:56:15 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:15 cib_client_register_callback_full(632):0: Adding callback do_pe_invoke_callback for call 3827
trace May 20 13:56:15 delete_fsa_input(236):0: About to free C_FSA_INTERNAL data
trace May 20 13:56:15 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:15 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:15 crm_ipc_read(1003):0: Received cib_shm event 16860, size=71777, rc=71777, text: <cib-reply t="cib" cib_op="cib_query" cib_callid="3827" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740c
trace May 20 13:56:15 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 71737 (I/O condition=1)
trace May 20 13:56:15 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:15 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 20 13:56:15 cib_native_callback(649):0: Invoking callback do_pe_invoke_callback for call 3827
trace May 20 13:56:15 pcmk_locate_sbd(231):0: SBD detected at pid=0 (proc)
trace May 20 13:56:15 force_local_option(262):0: Forcing cib-bootstrap-options-have-watchdog/have-watchdog = false
trace May 20 13:56:15 crm_ipc_send(1189):0: Sending from client: pengine request id: 8747 bytes: 71828 timeout:5000 msg...
trace May 20 13:56:15 crm_ipc_send(1202):0: Message sent, not waiting for reply to 8747 from pengine to 71828 bytes...
debug May 20 13:56:15 do_pe_invoke_callback(365):0: Invoking the PE: query=3827, ref=pe_calc-dc-1558353375-3170, seq=1652, quorate=1
trace May 20 13:56:15 cib_native_callback(663):0: Invoking global callback for call 3827
trace May 20 13:56:15 cib_native_callback(666):0: OP callback activated for 3827
trace May 20 13:56:15 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 20 13:56:15 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 20 13:56:15 crm_ipc_read(1003):0: Received pengine event 437, size=5613, rc=5613, text: <create_reply_adv origin="process_pe_message" t="crmd" version="3.0.11" subt="response" reference="p
trace May 20 13:56:15 mainloop_gio_callback(663):0: New message from pengine[0x5626d0a2f9d0] = 5573 (I/O condition=1)
trace May 20 13:56:15 relay_message(375):0: Routing message pe_calc-dc-1558353375-3170
trace May 20 13:56:15 relay_message(431):0: Router result: Message result: DC/CRMd process
trace May 20 13:56:15 register_fsa_input_adv(113):0: handle_response appended FSA input 1351 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
trace May 20 13:56:15 register_fsa_input_adv(135):0: Copying C_IPC_MESSAGE data from handle_response as a HA msg
trace May 20 13:56:15 copy_ha_msg_input(214):0: Copy msg
trace May 20 13:56:15 register_fsa_input_adv(164):0: C_IPC_MESSAGE data copied
trace May 20 13:56:15 register_fsa_input_adv(175):0: Queue len: 1
trace May 20 13:56:15 register_fsa_input_adv(184):0: Triggering FSA: register_fsa_input_adv
trace May 20 13:56:15 handle_response(899):0: Completed: pe_calc-dc-1558353375-3170...
trace May 20 13:56:15 crm_ipc_read(1006):0: No message from pengine received: Resource temporarily unavailable
trace May 20 13:56:15 mainloop_gio_callback(658):0: Message acquisition from pengine[0x5626d0a2f9d0] failed: No message of desired type (-42)
trace May 20 13:56:15 crm_fsa_trigger(312):0: Invoked (queue len: 1)
trace May 20 13:56:15 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_POLICY_ENGINE
trace May 20 13:56:15 s_crmd_fsa(175):0: Checking messages (1 remaining)
trace May 20 13:56:15 get_message(275):0: Processing input 1351
trace May 20 13:56:15 log_fsa_input(455):0: Processing queued input 1351
trace May 20 13:56:15 log_fsa_input(468):0: FSA processing XML message from handle_response
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <transition_graph cluster-delay="60s" stonith-timeout="60s" failed-stop-offset="INFINITY" failed-start-offset="INFINITY" batch-limit="0" transition_id="436">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <synapse id="0">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="66" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <primitive id="tunnel-wigner-guest" class="ocf" provider="local" type="tunnel"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <attributes CRM_meta_name="stop" CRM_meta_timeout="300000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <inputs/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </synapse>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <synapse id="1">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="23" operation="start" operation_key="tunnel-wigner-guest_start_0" on_node="bifur1" on_node_uuid="1084762125">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <primitive id="tunnel-wigner-guest" class="ocf" provider="local" type="tunnel"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <attributes CRM_meta_name="start" CRM_meta_timeout="120000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="66" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </synapse>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <synapse id="2">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="21" operation="monitor" operation_key="tunnel-wigner-guest_monitor_30000" on_node="bifur1" on_node_uuid="1084762125">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <primitive id="tunnel-wigner-guest" class="ocf" provider="local" type="tunnel"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <attributes CRM_meta_interval="30000" CRM_meta_name="monitor" CRM_meta_timeout="30000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="23" operation="start" operation_key="tunnel-wigner-guest_start_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </synapse>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <synapse id="3">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="68" operation="monitor" operation_key="tunnel-eduroam_monitor_30000" on_node="bifur1" on_node_uuid="1084762125">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <primitive id="tunnel-eduroam" class="ocf" provider="local" type="tunnel"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <attributes CRM_meta_interval="30000" CRM_meta_name="monitor" CRM_meta_timeout="30000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="67" operation="start" operation_key="tunnel-eduroam_start_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </synapse>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <synapse id="4">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="67" operation="start" operation_key="tunnel-eduroam_start_0" on_node="bifur1" on_node_uuid="1084762125">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <primitive id="tunnel-eduroam" class="ocf" provider="local" type="tunnel"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <attributes CRM_meta_name="start" CRM_meta_timeout="120000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="24" operation="monitor" operation_key="tunnel-eduroam_monitor_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="25" operation="monitor" operation_key="tunnel-eduroam_monitor_0" on_node="bifur2" on_node_uuid="1084762126"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </synapse>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <synapse id="5">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="25" operation="monitor" operation_key="tunnel-eduroam_monitor_0" on_node="bifur2" on_node_uuid="1084762126">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <primitive id="tunnel-eduroam" class="ocf" provider="local" type="tunnel"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <attributes CRM_meta_op_target_rc="7" CRM_meta_timeout="30000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <inputs/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </synapse>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <synapse id="6">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="24" operation="monitor" operation_key="tunnel-eduroam_monitor_0" on_node="bifur1" on_node_uuid="1084762125">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <primitive id="tunnel-eduroam" class="ocf" provider="local" type="tunnel"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <attributes CRM_meta_op_target_rc="7" CRM_meta_timeout="30000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <inputs/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </synapse>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <synapse id="7">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <pseudo_event id="22" operation="all_stopped" operation_key="all_stopped">
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <attributes crm_feature_set="3.0.11"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </pseudo_event>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </action_set>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data <rsc_op id="66" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </trigger>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </inputs>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </synapse>
trace May 20 13:56:15 log_fsa_input(469):0: FSA message data </transition_graph>
trace May 20 13:56:15 fsa_dump_actions(892):0: Action 0000100000000000 (A_TE_INVOKE) New actions
debug May 20 13:56:15 s_crmd_fsa(197):0: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=handle_response ]
trace May 20 13:56:16 do_state_transition(492):0: actions:trace: S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ label=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
info May 20 13:56:16 do_state_transition(509):0: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE | input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response
trace May 20 13:56:16 crm_set_bit(185):0: Bit 0x00000020 set by do_state
trace May 20 13:56:16 crm_set_bit(185):0: Bit 0x00000080 set by do_state
trace May 20 13:56:16 crm_set_bit(185):0: Bit 0x00000200 set by do_state
trace May 20 13:56:16 crm_timer_stop(225):0: PEngine Recheck Timer (I_PE_CALC:900000ms) already stopped
trace May 20 13:56:16 do_fsa_action(142):0: actions:trace: // A_DC_TIMER_STOP
trace May 20 13:56:16 crm_timer_stop(225):0: Election Trigger (I_DC_TIMEOUT:20000ms) already stopped
trace May 20 13:56:16 do_fsa_action(142):0: actions:trace: // A_INTEGRATE_TIMER_STOP
trace May 20 13:56:16 crm_timer_stop(225):0: Integration Timer (I_INTEGRATED:180000ms) already stopped
trace May 20 13:56:16 do_fsa_action(142):0: actions:trace: // A_FINALIZE_TIMER_STOP
trace May 20 13:56:16 crm_timer_stop(225):0: Finalization Timer (I_ELECTION:1800000ms) already stopped
trace May 20 13:56:16 do_fsa_action(142):0: actions:trace: // A_TE_INVOKE
trace May 20 13:56:16 unpack_synapse(102):0: looking in synapse 0
trace May 20 13:56:16 unpack_synapse(116):0: look for actions in synapse 0
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_name="stop" CRM_meta_timeout="300000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=stop
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 20 13:56:16 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=1
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 unpack_action(88):0: Action 66 has timer set to 300000ms
trace May 20 13:56:16 unpack_synapse(132):0: Adding action 66 to synapse 0
trace May 20 13:56:16 unpack_synapse(139):0: look for inputs in synapse 0
trace May 20 13:56:16 unpack_synapse(102):0: looking in synapse 1
trace May 20 13:56:16 unpack_synapse(116):0: look for actions in synapse 1
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_name="start" CRM_meta_timeout="120000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=start
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 20 13:56:16 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=1
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 unpack_action(88):0: Action 23 has timer set to 120000ms
trace May 20 13:56:16 unpack_synapse(132):0: Adding action 23 to synapse 1
trace May 20 13:56:16 unpack_synapse(139):0: look for inputs in synapse 1
trace May 20 13:56:16 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 20 13:56:16 xml2list(4788):0: No attributes in rsc_op
trace May 20 13:56:16 xml2list(4789):0: No attributes for resource op <rsc_op id="66" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:16 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 20 13:56:16 unpack_action(88):0: Action 66 has timer set to 0ms
trace May 20 13:56:16 unpack_synapse(156):0: Adding input 66 to synapse 1
trace May 20 13:56:16 unpack_synapse(102):0: looking in synapse 2
trace May 20 13:56:16 unpack_synapse(116):0: look for actions in synapse 2
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_interval="30000" CRM_meta_name="monitor" CRM_meta_timeout="30000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_interval=30000
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:16 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=1
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 unpack_action(88):0: Action 21 has timer set to 30000ms
trace May 20 13:56:16 unpack_synapse(132):0: Adding action 21 to synapse 2
trace May 20 13:56:16 unpack_synapse(139):0: look for inputs in synapse 2
trace May 20 13:56:16 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 20 13:56:16 xml2list(4788):0: No attributes in rsc_op
trace May 20 13:56:16 xml2list(4789):0: No attributes for resource op <rsc_op id="23" operation="start" operation_key="tunnel-wigner-guest_start_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:16 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 20 13:56:16 unpack_action(88):0: Action 23 has timer set to 0ms
trace May 20 13:56:16 unpack_synapse(156):0: Adding input 23 to synapse 2
trace May 20 13:56:16 unpack_synapse(102):0: looking in synapse 3
trace May 20 13:56:16 unpack_synapse(116):0: look for actions in synapse 3
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_interval="30000" CRM_meta_name="monitor" CRM_meta_timeout="30000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_interval=30000
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=0
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 unpack_action(88):0: Action 68 has timer set to 30000ms
trace May 20 13:56:16 unpack_synapse(132):0: Adding action 68 to synapse 3
trace May 20 13:56:16 unpack_synapse(139):0: look for inputs in synapse 3
trace May 20 13:56:16 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 20 13:56:16 xml2list(4788):0: No attributes in rsc_op
trace May 20 13:56:16 xml2list(4789):0: No attributes for resource op <rsc_op id="67" operation="start" operation_key="tunnel-eduroam_start_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:16 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 20 13:56:16 unpack_action(88):0: Action 67 has timer set to 0ms
trace May 20 13:56:16 unpack_synapse(156):0: Adding input 67 to synapse 3
trace May 20 13:56:16 unpack_synapse(102):0: looking in synapse 4
trace May 20 13:56:16 unpack_synapse(116):0: look for actions in synapse 4
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_name="start" CRM_meta_timeout="120000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=start
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=0
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 unpack_action(88):0: Action 67 has timer set to 120000ms
trace May 20 13:56:16 unpack_synapse(132):0: Adding action 67 to synapse 4
trace May 20 13:56:16 unpack_synapse(139):0: look for inputs in synapse 4
trace May 20 13:56:16 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 20 13:56:16 xml2list(4788):0: No attributes in rsc_op
trace May 20 13:56:16 xml2list(4789):0: No attributes for resource op <rsc_op id="24" operation="monitor" operation_key="tunnel-eduroam_monitor_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:16 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 20 13:56:16 unpack_action(88):0: Action 24 has timer set to 0ms
trace May 20 13:56:16 unpack_synapse(156):0: Adding input 24 to synapse 4
trace May 20 13:56:16 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 20 13:56:16 xml2list(4788):0: No attributes in rsc_op
trace May 20 13:56:16 xml2list(4789):0: No attributes for resource op <rsc_op id="25" operation="monitor" operation_key="tunnel-eduroam_monitor_0" on_node="bifur2" on_node_uuid="1084762126"/>
trace May 20 13:56:16 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 20 13:56:16 unpack_action(88):0: Action 25 has timer set to 0ms
trace May 20 13:56:16 unpack_synapse(156):0: Adding input 25 to synapse 4
trace May 20 13:56:16 unpack_synapse(102):0: looking in synapse 5
trace May 20 13:56:16 unpack_synapse(116):0: look for actions in synapse 5
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_op_target_rc="7" CRM_meta_timeout="30000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_op_target_rc=7
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=0
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 unpack_action(88):0: Action 25 has timer set to 30000ms
trace May 20 13:56:16 unpack_synapse(132):0: Adding action 25 to synapse 5
trace May 20 13:56:16 unpack_synapse(139):0: look for inputs in synapse 5
trace May 20 13:56:16 unpack_synapse(102):0: looking in synapse 6
trace May 20 13:56:16 unpack_synapse(116):0: look for actions in synapse 6
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_op_target_rc="7" CRM_meta_timeout="30000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_op_target_rc=7
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=0
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 unpack_action(88):0: Action 24 has timer set to 30000ms
trace May 20 13:56:16 unpack_synapse(132):0: Adding action 24 to synapse 6
trace May 20 13:56:16 unpack_synapse(139):0: look for inputs in synapse 6
trace May 20 13:56:16 unpack_synapse(102):0: looking in synapse 7
trace May 20 13:56:16 unpack_synapse(116):0: look for actions in synapse 7
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes crm_feature_set="3.0.11"/>
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 unpack_action(88):0: Action 22 has timer set to 0ms
trace May 20 13:56:16 unpack_synapse(132):0: Adding action 22 to synapse 7
trace May 20 13:56:16 unpack_synapse(139):0: look for inputs in synapse 7
trace May 20 13:56:16 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 20 13:56:16 xml2list(4788):0: No attributes in rsc_op
trace May 20 13:56:16 xml2list(4789):0: No attributes for resource op <rsc_op id="66" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 20 13:56:16 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 20 13:56:16 unpack_action(88):0: Action 66 has timer set to 0ms
trace May 20 13:56:16 unpack_synapse(156):0: Adding input 66 to synapse 7
debug May 20 13:56:16 unpack_graph(236):0: Unpacked transition 436: 8 actions in 8 synapses
info May 20 13:56:16 do_te_invoke(218):0: Processing graph 436 (ref=pe_calc-dc-1558353375-3170) derived from /var/lib/pacemaker/pengine/pe-input-2550.bz2
trace May 20 13:56:16 trigger_graph_processing(511):0: do_te_invoke:233 - Triggered graph processing
trace May 20 13:56:16 print_graph(237):0: Graph 436 with 8 actions: batch-limit=0 jobs, network-delay=60000ms
trace May 20 13:56:16 print_synapse(190):0: [Action 66]: Pending rsc op tunnel-wigner-guest_stop_0 on bifur1 (priority: 0, waiting: none)
trace May 20 13:56:16 print_synapse(190):0: [Action 23]: Pending rsc op tunnel-wigner-guest_start_0 on bifur1 (priority: 0, waiting: 66)
trace May 20 13:56:16 print_synapse(190):0: [Action 21]: Pending rsc op tunnel-wigner-guest_monitor_30000 on bifur1 (priority: 0, waiting: 23)
trace May 20 13:56:16 print_synapse(190):0: [Action 68]: Pending rsc op tunnel-eduroam_monitor_30000 on bifur1 (priority: 0, waiting: 67)
trace May 20 13:56:16 print_synapse(190):0: [Action 67]: Pending rsc op tunnel-eduroam_start_0 on bifur1 (priority: 0, waiting: 24 25)
trace May 20 13:56:16 print_synapse(190):0: [Action 25]: Pending rsc op tunnel-eduroam_monitor_0 on bifur2 (priority: 0, waiting: none)
trace May 20 13:56:16 print_synapse(190):0: [Action 24]: Pending rsc op tunnel-eduroam_monitor_0 on bifur1 (priority: 0, waiting: none)
trace May 20 13:56:16 print_synapse(190):0: [Action 22]: Pending pseudo op all_stopped on N/A (priority: 0, waiting: 66)
trace May 20 13:56:16 delete_fsa_input(236):0: About to free C_IPC_MESSAGE data
trace May 20 13:56:16 delete_fsa_input(262):0: C_IPC_MESSAGE data freed
trace May 20 13:56:16 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:16 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:16 te_graph_trigger(460):0: Invoking graph 436 in state S_TRANSITION_ENGINE
trace May 20 13:56:16 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:16 run_graph(267):0: Entering graph 436 callback
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 0
trace May 20 13:56:16 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 0 limit= 8 limit
trace May 20 13:56:16 run_graph(300):0: Synapse 0 fired
trace May 20 13:56:16 fire_synapse(223):0: Synapse 0 fired
trace May 20 13:56:16 initiate_action(192):0: Executing rsc-event: 66 (66)
notice May 20 13:56:16 te_rsc_command(436):0: Initiating stop operation tunnel-wigner-guest_stop_0 locally on bifur1 | action 66
trace May 20 13:56:16 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 20 13:56:16 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 20 13:56:16 get_lrm_resource(1253):0: Retrieving tunnel-wigner-guest from the LRM.
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_name="stop" CRM_meta_timeout="300000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=stop
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 20 13:56:16 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=1
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 construct_op(1882):0: Constructed stop op for tunnel-wigner-guest: interval=0
debug May 20 13:56:16 stop_recurring_action_by_rsc(1966):0: Cancelling op 4456 for tunnel-wigner-guest (tunnel-wigner-guest:4456)
debug May 20 13:56:16 cancel_op(1178):0: Cancelling op 4456 for tunnel-wigner-guest (tunnel-wigner-guest:4456)
trace May 20 13:56:16 lrmd_send_command(818):0: sending lrmd_rsc_cancel op to lrmd
trace May 20 13:56:16 lrmd_create_op(489):0: Sending call options: 00000000, 0
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8748 bytes: 374 timeout:5000 msg...
trace May 20 13:56:16 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8748
trace May 20 13:56:16 crm_ipc_send(1227):0: Received response 8748, size=110, rc=110, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="0" lrmd_callid="4457"/>
trace May 20 13:56:16 lrmd_send_command(847):0: lrmd_rsc_cancel op reply received
trace May 20 13:56:16 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="0" lrmd_callid="4457"/>
debug May 20 13:56:16 cancel_op(1181):0: Op 4456 for tunnel-wigner-guest (tunnel-wigner-guest:4456): cancelled
info May 20 13:56:16 do_lrm_rsc_op(2086):0: Performing key=66:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-wigner-guest_stop_0
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: iface_in=publ-br0.24
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: id=1
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: network=m.n.o.p/25
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: chain=nfcp-check
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: dst_ip=e.f.g.h
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: src_ip=q.r.s.t
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: CRM_meta_name=stop
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: CRM_meta_timeout=300000
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 20 13:56:16 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8749 bytes: 801 timeout:300000 msg...
trace May 20 13:56:16 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8749
trace May 20 13:56:16 crm_ipc_send(1227):0: Received response 8749, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4458" lrmd_callid="4458"/>
trace May 20 13:56:16 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 20 13:56:16 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4458" lrmd_callid="4458"/>
trace May 20 13:56:16 do_lrm_rsc_op(2160):0: Recording pending op: 4458 - tunnel-wigner-guest_stop_0 tunnel-wigner-guest:4458
trace May 20 13:56:16 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 1
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 66
trace May 20 13:56:16 should_fire_synapse(146):0: Input 66 for synapse 1 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 1 cannot fire
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 23
trace May 20 13:56:16 should_fire_synapse(146):0: Input 23 for synapse 2 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 2 cannot fire
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 3
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 67
trace May 20 13:56:16 should_fire_synapse(146):0: Input 67 for synapse 3 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 3 cannot fire
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 4
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 24
trace May 20 13:56:16 should_fire_synapse(146):0: Input 24 for synapse 4 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 4 cannot fire
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 5
trace May 20 13:56:16 te_should_perform_action_on(622):0: Peer bifur2 has not hit their limit yet. current jobs = 0 limit= 8 limit
trace May 20 13:56:16 run_graph(300):0: Synapse 5 fired
trace May 20 13:56:16 fire_synapse(223):0: Synapse 5 fired
trace May 20 13:56:16 initiate_action(192):0: Executing rsc-event: 25 (25)
notice May 20 13:56:16 te_rsc_command(436):0: Initiating monitor operation tunnel-eduroam_monitor_0 on bifur2 | action 25
trace May 20 13:56:16 crm_find_peer(553):0: Name match: bifur2 = 0x5626d0989560
trace May 20 13:56:16 crm_find_peer(577):0: Only one: 0x5626d0989560 for 0/bifur2
trace May 20 13:56:16 send_cluster_text(635):0: Queueing CPG message 242 to bifur2 (1400 bytes, 808 bytes payload): <create_request_adv origin="te_rsc_command" t="crmd" version="3.0.11" subt="request" reference="lrm_invoke-tengine-1558353376-3172" crm_task="lrm_invoke" crm_sys_to="lrmd" crm_sys_from="tengine" crm_h
trace May 20 13:56:16 send_cpg_iov(207):0: Queueing CPG message 242 (1400 bytes)
trace May 20 13:56:16 crm_cs_flush(170):0: CPG message sent, size=1400
trace May 20 13:56:16 crm_cs_flush(185):0: Sent 1 CPG messages (0 remaining, last=242): OK (1)
trace May 20 13:56:16 te_update_job_count_on(548):0: jobs[bifur2] = 1
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 6
trace May 20 13:56:16 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 1 limit= 8 limit
trace May 20 13:56:16 run_graph(300):0: Synapse 6 fired
trace May 20 13:56:16 fire_synapse(223):0: Synapse 6 fired
trace May 20 13:56:16 initiate_action(192):0: Executing rsc-event: 24 (24)
notice May 20 13:56:16 te_rsc_command(436):0: Initiating monitor operation tunnel-eduroam_monitor_0 locally on bifur1 | action 24
trace May 20 13:56:16 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 20 13:56:16 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 20 13:56:16 get_lrm_resource(1253):0: Retrieving tunnel-eduroam from the LRM.
trace May 20 13:56:16 lrmd_send_command(818):0: sending lrmd_rsc_info op to lrmd
trace May 20 13:56:16 lrmd_create_op(489):0: Sending call options: 00000000, 0
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8750 bytes: 321 timeout:5000 msg...
trace May 20 13:56:16 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8750
trace May 20 13:56:16 crm_ipc_send(1227):0: Received response 8750, size=127, rc=127, text: <lrmd_reply lrmd_origin="process_lrmd_get_rsc_info" lrmd_rc="-19" lrmd_callid="4459"/>
trace May 20 13:56:16 lrmd_send_command(847):0: lrmd_rsc_info op reply received
trace May 20 13:56:16 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="process_lrmd_get_rsc_info" lrmd_rc="-19" lrmd_callid="4459"/>
trace May 20 13:56:16 get_lrm_resource(1266):0: Adding rsc tunnel-eduroam before operation
trace May 20 13:56:16 lrmd_send_command(818):0: sending lrmd_rsc_register op to lrmd
trace May 20 13:56:16 lrmd_create_op(489):0: Sending call options: 00000003, 3
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8751 bytes: 383 timeout:5000 msg...
trace May 20 13:56:16 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8751
trace May 20 13:56:16 crm_ipc_send(1227):0: Received response 8751, size=110, rc=110, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="0" lrmd_callid="4460"/>
trace May 20 13:56:16 lrmd_send_command(847):0: lrmd_rsc_register op reply received
trace May 20 13:56:16 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="0" lrmd_callid="4460"/>
trace May 20 13:56:16 lrmd_send_command(818):0: sending lrmd_rsc_info op to lrmd
trace May 20 13:56:16 lrmd_create_op(489):0: Sending call options: 00000000, 0
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8752 bytes: 321 timeout:5000 msg...
trace May 20 13:56:16 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8752
trace May 20 13:56:16 crm_ipc_send(1227):0: Received response 8752, size=212, rc=212, text: <lrmd_reply lrmd_origin="process_lrmd_get_rsc_info" lrmd_rc="0" lrmd_callid="4461" lrmd_rsc_id="tunnel-eduroam" lrmd_class="ocf" lrmd_provider="local" lrmd_type="tunnel"/>
trace May 20 13:56:16 lrmd_send_command(847):0: lrmd_rsc_info op reply received
trace May 20 13:56:16 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="process_lrmd_get_rsc_info" lrmd_rc="0" lrmd_callid="4461" lrmd_rsc_id="tunnel-eduroam" lrmd_class="ocf" lrmd_provider="local" lrmd_type="tunnel"/>
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_op_target_rc="7" CRM_meta_timeout="30000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_op_target_rc=7
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=0
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 construct_op(1882):0: Constructed monitor op for tunnel-eduroam: interval=0
info May 20 13:56:16 do_lrm_rsc_op(2086):0: Performing key=24:436:7:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-eduroam_monitor_0
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: iface_in=publ-br0.18
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: id=0
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: name=eduroam IPv4 tunnel
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: network=i.j.k.l/24
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: dst_ip=e.f.g.h
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: src_ip=a.b.c.d
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: CRM_meta_timeout=30000
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 20 13:56:16 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8753 bytes: 749 timeout:30000 msg...
trace May 20 13:56:16 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8753
trace May 20 13:56:16 crm_ipc_send(1227):0: Received response 8753, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4462" lrmd_callid="4462"/>
trace May 20 13:56:16 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 20 13:56:16 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4462" lrmd_callid="4462"/>
trace May 20 13:56:16 do_lrm_rsc_op(2160):0: Recording pending op: 4462 - tunnel-eduroam_monitor_0 tunnel-eduroam:4462
trace May 20 13:56:16 te_update_job_count_on(548):0: jobs[bifur1] = 2
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 7
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 66
trace May 20 13:56:16 should_fire_synapse(146):0: Input 66 for synapse 7 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 7 cannot fire
debug May 20 13:56:16 run_graph(343):0: Transition 436 (Complete=0, Pending=3, Fired=3, Skipped=0, Incomplete=5, Source=/var/lib/pacemaker/pengine/pe-input-2550.bz2): In-progress
trace May 20 13:56:16 te_graph_trigger(487):0: Transition not yet complete
trace May 20 13:56:16 crm_ipc_read(1003):0: Received cib_shm event 16861, size=2725, rc=2725, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 2685 (I/O condition=1)
trace May 20 13:56:16 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:16 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 20 13:56:16 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 20 13:56:16 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 20 13:56:16 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:16 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 591 for del[epoch]
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 0 for del[num_updates]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 1 for add[num_updates]
debug May 20 13:56:16 te_update_diff(390):0: Processing (cib_modify) diff: 0.591.0 -> 0.591.1 (S_TRANSITION_ENGINE)
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <version>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="591" num_updates="0"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="591" num_updates="1"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </version>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="1"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="591" num_updates="1" admin_epoch="0" cib-last-written="Mon May 20 13:56:15 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:16 crm_xml_escape(3177):0: Dumped '/cib/status/node_state[@id='1084762126']/lrm[@id='1084762126']/lrm_resources'
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change operation="create" path="/cib/status/node_state[@id='1084762126']/lrm[@id='1084762126']/lrm_resources" position="21">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <lrm_resource id="tunnel-eduroam" type="tunnel" class="ocf" provider="local">
trace May 20 13:56:16 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </lrm_resource>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </diff>
trace May 20 13:56:16 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 20 13:56:16 te_update_diff(439):0: Handling create operation for /cib/status/node_state[@id='1084762126']/lrm[@id='1084762126']/lrm_resources matched by lrm_resource
trace May 20 13:56:16 status_from_rc(232):0: Target rc: == 7
trace May 20 13:56:16 stop_te_timer(438):0: Stopping action timer
trace May 20 13:56:16 te_update_job_count_on(548):0: jobs[bifur2] = 0
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 66
trace May 20 13:56:16 update_synapse_confirmed(85):0: Synapse 0 still not confirmed after action 25
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 66
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 23
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 67
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 24
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 25
trace May 20 13:56:16 update_synapse_ready(46):0: Marking input 25 of synapse 4 confirmed
trace May 20 13:56:16 update_synapse_ready(57):0: Updated synapse 4
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 25
trace May 20 13:56:16 update_synapse_confirmed(79):0: Confirmed: Action 25 of Synapse 5
trace May 20 13:56:16 update_synapse_confirmed(90):0: Confirmed: Synapse 5
trace May 20 13:56:16 update_synapse_confirmed(96):0: Updated synapse 5
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 24
trace May 20 13:56:16 update_synapse_confirmed(85):0: Synapse 6 still not confirmed after action 25
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 66
trace May 20 13:56:16 update_graph(125):0: Updated graph with completed action 25
trace May 20 13:56:16 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 20 13:56:16 match_graph_event(316):0: Action tunnel-eduroam_monitor_0 (25) confirmed on bifur2 (rc=7)
trace May 20 13:56:16 process_graph_event(520):0: Processed update to tunnel-eduroam_monitor_0: 25:436:7:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 20 13:56:16 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:16 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 20 13:56:16 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 20 13:56:16 crm_ipc_read(1003):0: Received lrmd event 4394, size=828, rc=828, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="30000" lrmd_rsc_interval="30000" l
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 788 (I/O condition=1)
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.24" CRM_meta_timeout="30000" CRM_meta_interval="30000" id="1" name="Wigner guest IPv4 tunnel" iface_out="publ-br1" network="m.n.o.p/25" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" src_ip="q.r.s.t" CRM_meta_name="monitor" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_interval=30000
trace May 20 13:56:16 xml2list(4798):0: Added id=1
trace May 20 13:56:16 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:16 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 20 13:56:16 process_lrm_event(2403):0: Op tunnel-wigner-guest_monitor_30000 (call=4456): no delete event required
info May 20 13:56:16 process_lrm_event(2427):0: Result of monitor operation for tunnel-wigner-guest on bifur1: Cancelled | call=4456 key=tunnel-wigner-guest_monitor_30000 confirmed=true
debug May 20 13:56:16 update_history_cache(196):0: Updating history for 'tunnel-wigner-guest' with monitor op
trace May 20 13:56:16 update_history_cache(223):0: Removing cancelled recurring op: tunnel-wigner-guest_monitor_30000
trace May 20 13:56:16 crm_ipc_read(1003):0: Received lrmd event 4395, size=177, rc=177, text: <lrmd_notify lrmd_origin="send_generic_notify" lrmd_rc="0" lrmd_callid="4460" lrmd_op="lrmd_rsc_regi
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 137 (I/O condition=1)
trace May 20 13:56:16 lrmd_dispatch_internal(301):0: op lrmd_rsc_register notify event received
trace May 20 13:56:16 crm_ipc_read(1003):0: Received lrmd event 4396, size=762, rc=762, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="30000" lrmd_rsc_interval="0" lrmd_
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 722 (I/O condition=1)
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.18" tunnel_dst_ip="10.10.0.1" id="0" name="eduroam IPv4 tunnel" iface_out="publ-br1" network="i.j.k.l/24" dst_ip="e.f.g.h" crm_feature_set="3.0.11" src_ip="a.b.c.d" tunnel_src_ip="10.10.1.1" CRM_meta_timeout="30000"/>
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 xml2list(4798):0: Added id=0
trace May 20 13:56:16 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:16 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 20 13:56:16 build_operation_update(763):0: Building tunnel-eduroam operation update with originator version: 3.0.11
trace May 20 13:56:16 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 20 13:56:16 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 20 13:56:16 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-eduroam after monitor op complete (interval=0)
trace May 20 13:56:16 create_operation_update(1775):0: DC version: 3.0.11
trace May 20 13:56:16 find_entity(2226):0: node <lrm_rsc_op id=tunnel-eduroam_last_0> not found in lrm_resource.
trace May 20 13:56:16 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 20 13:56:16 create_operation_update(1870):0: Timing data (tunnel-eduroam_monitor_0): last=1558353376 change=1558353376 exec=41 queue=0
trace May 20 13:56:16 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:16 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:16 crm_md5sum(2102):0: Beginning digest of 203 bytes
trace May 20 13:56:16 crm_md5sum(2110):0: Digest 9a80239c380f1eafa208100c3c658458.
trace May 20 13:56:16 calculate_xml_digest_v1(83):0: digest:source <parameters dst_ip="e.f.g.h" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:16 get_rsc_metadata(532):0: Retrieved cached metadata for ocf::local:tunnel
trace May 20 13:56:16 build_operation_update(787):0: Including additional digests for ocf::local:tunnel
trace May 20 13:56:16 build_parameter_list(614):0: Attr name is unique
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr name=eduroam IPv4 tunnel to the xml result
trace May 20 13:56:16 build_parameter_list(614):0: Attr id is unique
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr id=0 to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting src_ip for unique
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting dst_ip for unique
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting tunnel_src_ip for unique
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting tunnel_dst_ip for unique
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting network for unique
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting iface_out for unique
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting iface_in for unique
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting chain for unique
trace May 20 13:56:16 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:16 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:16 crm_md5sum(2102):0: Beginning digest of 49 bytes
trace May 20 13:56:16 crm_md5sum(2110):0: Digest 8ec3fbe5d133432ead850c50a36f516c.
trace May 20 13:56:16 calculate_xml_digest_v1(83):0: digest:source <parameters id="0" name="eduroam IPv4 tunnel"/>
trace May 20 13:56:16 append_restart_list(693):0: tunnel-eduroam: 8ec3fbe5d133432ead850c50a36f516c, name id
trace May 20 13:56:16 append_restart_list(694):0: restart digest source <parameters name="eduroam IPv4 tunnel" id="0"/>
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting name for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting name match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr name=eduroam IPv4 tunnel to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting id for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting id match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr id=0 to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting src_ip for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr src_ip=a.b.c.d to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr dst_ip=e.f.g.h to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.1 to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.1 to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting network for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting network match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr network=i.j.k.l/24 to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting iface_out for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting iface_in for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 20 13:56:16 build_parameter_list(632):0: Adding attr iface_in=publ-br0.18 to the xml result
trace May 20 13:56:16 build_parameter_list(621):0: Rejecting chain for private
trace May 20 13:56:16 build_parameter_list(625):0: Inverting chain match for private xml
trace May 20 13:56:16 append_secure_list(726):0: tunnel-eduroam: no secure parameters
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <status>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-eduroam" type="tunnel" class="ocf" provider="local">
trace May 20 13:56:16 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </lrm>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </node_state>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </status>
trace May 20 13:56:16 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 20 13:56:16 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 8754 bytes: 1097 timeout:120000 msg...
trace May 20 13:56:16 crm_ipc_send(1202):0: Message sent, not waiting for reply to 8754 from cib_shm to 1097 bytes...
trace May 20 13:56:16 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 20 13:56:16 cib_native_perform_op_delegate(398):0: Async call, returning 3828
trace May 20 13:56:16 do_update_resource(2313):0: Sent resource state update message: 3828 for monitor=0 on tunnel-eduroam
trace May 20 13:56:16 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:16 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 3828
trace May 20 13:56:16 process_lrm_event(2413):0: Op tunnel-eduroam_monitor_0 (call=4462, stop-id=tunnel-eduroam:4462, remaining=10): Confirmed
notice May 20 13:56:16 process_lrm_event(2438):0: Result of probe operation for tunnel-eduroam on bifur1: 7 (not running) | call=4462 key=tunnel-eduroam_monitor_0 confirmed=true cib-update=3828
debug May 20 13:56:16 update_history_cache(196):0: Updating history for 'tunnel-eduroam' with monitor op
trace May 20 13:56:16 crm_ipc_read(1003):0: Received lrmd event 4397, size=805, rc=805, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="300000" lrmd_rsc_interval="0" lrmd
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 765 (I/O condition=1)
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.24" tunnel_dst_ip="10.10.0.3" id="1" name="Wigner guest IPv4 tunnel" iface_out="publ-br1" network="m.n.o.p/25" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" src_ip="q.r.s.t" CRM_meta_name="stop" tunnel_src_ip="10.10.1.3" CRM_meta_timeout="300000"/>
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 xml2list(4798):0: Added id=1
trace May 20 13:56:16 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:16 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=stop
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 20 13:56:16 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 20 13:56:16 build_operation_update(763):0: Building tunnel-wigner-guest operation update with originator version: 3.0.11
trace May 20 13:56:16 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 20 13:56:16 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 20 13:56:16 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-wigner-guest after stop op complete (interval=0)
trace May 20 13:56:16 create_operation_update(1775):0: DC version: 3.0.11
trace May 20 13:56:16 find_entity(2226):0: node <lrm_rsc_op id=tunnel-wigner-guest_last_0> not found in lrm_resource.
trace May 20 13:56:16 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 20 13:56:16 create_operation_update(1870):0: Timing data (tunnel-wigner-guest_stop_0): last=1558353376 change=0 exec=190 queue=0
trace May 20 13:56:16 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:16 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:16 crm_md5sum(2102):0: Beginning digest of 229 bytes
trace May 20 13:56:16 crm_md5sum(2110):0: Digest 540db6b587fc94bd9b5bfab7f5cd5685.
trace May 20 13:56:16 calculate_xml_digest_v1(83):0: digest:source <parameters chain="nfcp-check" dst_ip="e.f.g.h" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:16 build_operation_update(771):0: No digests needed for tunnel-wigner-guest 0x5626d0a22a40 0x5626d0a20b80 stop
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <status>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-wigner-guest" type="tunnel" class="ocf" provider="local">
trace May 20 13:56:16 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </lrm>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </node_state>
trace May 20 13:56:16 do_update_resource(2286):0: do_update_resource </status>
trace May 20 13:56:16 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 20 13:56:16 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 8755 bytes: 1024 timeout:120000 msg...
trace May 20 13:56:16 crm_ipc_send(1202):0: Message sent, not waiting for reply to 8755 from cib_shm to 1024 bytes...
trace May 20 13:56:16 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 20 13:56:16 cib_native_perform_op_delegate(398):0: Async call, returning 3829
trace May 20 13:56:16 do_update_resource(2313):0: Sent resource state update message: 3829 for stop=0 on tunnel-wigner-guest
trace May 20 13:56:16 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:16 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 3829
trace May 20 13:56:16 process_lrm_event(2413):0: Op tunnel-wigner-guest_stop_0 (call=4458, stop-id=tunnel-wigner-guest:4458, remaining=9): Confirmed
notice May 20 13:56:16 process_lrm_event(2438):0: Result of stop operation for tunnel-wigner-guest on bifur1: 0 (ok) | call=4458 key=tunnel-wigner-guest_stop_0 confirmed=true cib-update=3829
debug May 20 13:56:16 update_history_cache(196):0: Updating history for 'tunnel-wigner-guest' with stop op
trace May 20 13:56:16 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 20 13:56:16 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 20 13:56:16 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:16 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:16 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:16 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:16 crm_ipc_read(1003):0: Received cib_shm event 16863, size=2739, rc=2739, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 2699 (I/O condition=1)
trace May 20 13:56:16 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:16 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 20 13:56:16 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 20 13:56:16 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 20 13:56:16 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:16 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 591 for del[epoch]
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 1 for del[num_updates]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 2 for add[num_updates]
debug May 20 13:56:16 te_update_diff(390):0: Processing (cib_modify) diff: 0.591.1 -> 0.591.2 (S_TRANSITION_ENGINE)
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <version>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="591" num_updates="1"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="591" num_updates="2"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </version>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="2"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="591" num_updates="2" admin_epoch="0" cib-last-written="Mon May 20 13:56:15 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:16 crm_xml_escape(3177):0: Dumped '/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources'
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change operation="create" path="/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources" position="21">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <lrm_resource id="tunnel-eduroam" type="tunnel" class="ocf" provider="local">
trace May 20 13:56:16 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </lrm_resource>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </diff>
trace May 20 13:56:16 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 20 13:56:16 te_update_diff(439):0: Handling create operation for /cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources matched by lrm_resource
trace May 20 13:56:16 status_from_rc(232):0: Target rc: == 7
trace May 20 13:56:16 stop_te_timer(438):0: Stopping action timer
trace May 20 13:56:16 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 66
trace May 20 13:56:16 update_synapse_confirmed(85):0: Synapse 0 still not confirmed after action 24
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 66
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 23
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 67
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 24
trace May 20 13:56:16 update_synapse_ready(46):0: Marking input 24 of synapse 4 confirmed
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 25
trace May 20 13:56:16 update_synapse_ready(57):0: Updated synapse 4
trace May 20 13:56:16 update_graph(112):0: Synapse complete
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 24
trace May 20 13:56:16 update_synapse_confirmed(79):0: Confirmed: Action 24 of Synapse 6
trace May 20 13:56:16 update_synapse_confirmed(90):0: Confirmed: Synapse 6
trace May 20 13:56:16 update_synapse_confirmed(96):0: Updated synapse 6
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 66
trace May 20 13:56:16 update_graph(125):0: Updated graph with completed action 24
trace May 20 13:56:16 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 20 13:56:16 match_graph_event(316):0: Action tunnel-eduroam_monitor_0 (24) confirmed on bifur1 (rc=7)
trace May 20 13:56:16 process_graph_event(520):0: Processed update to tunnel-eduroam_monitor_0: 24:436:7:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 20 13:56:16 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:16 crm_ipc_read(1003):0: Received cib_shm event 16865, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="3828" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 20 13:56:16 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:16 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 20 13:56:16 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 3828
trace May 20 13:56:16 cib_rsc_callback(2203):0: Resource update 3828 complete: rc=0
trace May 20 13:56:16 cib_native_callback(663):0: Invoking global callback for call 3828
trace May 20 13:56:16 cib_native_callback(666):0: OP callback activated for 3828
trace May 20 13:56:16 crm_ipc_read(1003):0: Received cib_shm event 16866, size=3345, rc=3345, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3305 (I/O condition=1)
trace May 20 13:56:16 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:16 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 20 13:56:16 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 20 13:56:16 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 20 13:56:16 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:16 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 591 for del[epoch]
trace May 20 13:56:16 xml_patch_versions(1747):0: Got 2 for del[num_updates]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:16 xml_patch_versions(1758):0: Got 3 for add[num_updates]
debug May 20 13:56:16 te_update_diff(390):0: Processing (cib_modify) diff: 0.591.2 -> 0.591.3 (S_TRANSITION_ENGINE)
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <version>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="591" num_updates="2"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="591" num_updates="3"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </version>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="3"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="591" num_updates="3" admin_epoch="0" cib-last-written="Mon May 20 13:56:15 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:16 crm_xml_escape(3177):0: Dumped '/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_last_0']'
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_last_0']">
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="operation_key" operation="set" value="tunnel-wigner-guest_stop_0"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="operation" operation="set" value="stop"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="66:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;66:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="4458"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="last-run" operation="set" value="1558353376"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="last-rc-change" operation="set" value="1558353376"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="190"/>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:16 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:16 te_update_diff(399):0: Patch:Raw </diff>
trace May 20 13:56:16 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 20 13:56:16 te_update_diff(439):0: Handling modify operation for /cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_last_0'] matched by lrm_rsc_op
trace May 20 13:56:16 status_from_rc(232):0: Target rc: == 0
trace May 20 13:56:16 stop_te_timer(438):0: Stopping action timer
trace May 20 13:56:16 te_update_job_count_on(548):0: jobs[bifur1] = 0
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 66
trace May 20 13:56:16 update_synapse_confirmed(79):0: Confirmed: Action 66 of Synapse 0
trace May 20 13:56:16 update_synapse_confirmed(90):0: Confirmed: Synapse 0
trace May 20 13:56:16 update_synapse_confirmed(96):0: Updated synapse 0
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 66
trace May 20 13:56:16 update_synapse_ready(46):0: Marking input 66 of synapse 1 confirmed
trace May 20 13:56:16 update_synapse_ready(57):0: Updated synapse 1
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 23
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 67
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 24
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 25
trace May 20 13:56:16 update_graph(112):0: Synapse complete
trace May 20 13:56:16 update_graph(112):0: Synapse complete
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 66
trace May 20 13:56:16 update_synapse_ready(46):0: Marking input 66 of synapse 7 confirmed
trace May 20 13:56:16 update_synapse_ready(57):0: Updated synapse 7
trace May 20 13:56:16 update_graph(125):0: Updated graph with completed action 66
trace May 20 13:56:16 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 20 13:56:16 match_graph_event(316):0: Action tunnel-wigner-guest_stop_0 (66) confirmed on bifur1 (rc=0)
trace May 20 13:56:16 process_graph_event(520):0: Processed update to tunnel-wigner-guest_stop_0: 66:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 20 13:56:16 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:16 crm_ipc_read(1003):0: Received cib_shm event 16868, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="3829" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 20 13:56:16 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 20 13:56:16 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:16 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 20 13:56:16 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 3829
trace May 20 13:56:16 cib_rsc_callback(2203):0: Resource update 3829 complete: rc=0
trace May 20 13:56:16 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 20 13:56:16 cib_native_callback(663):0: Invoking global callback for call 3829
trace May 20 13:56:16 cib_native_callback(666):0: OP callback activated for 3829
trace May 20 13:56:16 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 20 13:56:16 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 20 13:56:16 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:16 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:16 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:16 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:16 mainloop_gio_callback(673):0: New message from corosync-cpg[0x5626d08407a0] 1
trace May 20 13:56:16 pcmk_message_common_cs(252):0: Not for us: 1084762126 != 1084762125
trace May 20 13:56:16 te_graph_trigger(460):0: Invoking graph 436 in state S_TRANSITION_ENGINE
trace May 20 13:56:16 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:16 run_graph(267):0: Entering graph 436 callback
trace May 20 13:56:16 run_graph(274):0: Synapse 0 complete
trace May 20 13:56:16 run_graph(274):0: Synapse 5 complete
trace May 20 13:56:16 run_graph(274):0: Synapse 6 complete
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 1
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 66
trace May 20 13:56:16 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 0 limit= 8 limit
trace May 20 13:56:16 run_graph(300):0: Synapse 1 fired
trace May 20 13:56:16 fire_synapse(223):0: Synapse 1 fired
trace May 20 13:56:16 initiate_action(192):0: Executing rsc-event: 23 (23)
notice May 20 13:56:16 te_rsc_command(436):0: Initiating start operation tunnel-wigner-guest_start_0 locally on bifur1 | action 23
trace May 20 13:56:16 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 20 13:56:16 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 20 13:56:16 get_lrm_resource(1253):0: Retrieving tunnel-wigner-guest from the LRM.
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_name="start" CRM_meta_timeout="120000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=start
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 20 13:56:16 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=1
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 construct_op(1882):0: Constructed start op for tunnel-wigner-guest: interval=0
info May 20 13:56:16 do_lrm_rsc_op(2086):0: Performing key=23:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-wigner-guest_start_0
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: iface_in=publ-br0.24
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.3
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: id=1
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: name=Wigner guest IPv4 tunnel
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: network=m.n.o.p/25
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: chain=nfcp-check
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: dst_ip=e.f.g.h
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: src_ip=q.r.s.t
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: CRM_meta_name=start
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: CRM_meta_timeout=120000
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.3
trace May 20 13:56:16 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 20 13:56:16 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8756 bytes: 803 timeout:120000 msg...
trace May 20 13:56:16 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8756
trace May 20 13:56:16 crm_ipc_send(1227):0: Received response 8756, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4463" lrmd_callid="4463"/>
trace May 20 13:56:16 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 20 13:56:16 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4463" lrmd_callid="4463"/>
trace May 20 13:56:16 do_lrm_rsc_op(2160):0: Recording pending op: 4463 - tunnel-wigner-guest_start_0 tunnel-wigner-guest:4463
trace May 20 13:56:16 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 23
trace May 20 13:56:16 should_fire_synapse(146):0: Input 23 for synapse 2 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 2 cannot fire
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 3
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 67
trace May 20 13:56:16 should_fire_synapse(146):0: Input 67 for synapse 3 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 3 cannot fire
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 4
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 24
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 25
trace May 20 13:56:16 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 1 limit= 8 limit
trace May 20 13:56:16 run_graph(300):0: Synapse 4 fired
trace May 20 13:56:16 fire_synapse(223):0: Synapse 4 fired
trace May 20 13:56:16 initiate_action(192):0: Executing rsc-event: 67 (67)
notice May 20 13:56:16 te_rsc_command(436):0: Initiating start operation tunnel-eduroam_start_0 locally on bifur1 | action 67
trace May 20 13:56:16 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 20 13:56:16 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 20 13:56:16 get_lrm_resource(1253):0: Retrieving tunnel-eduroam from the LRM.
trace May 20 13:56:16 xml2list(4792):0: Unpacking <attributes CRM_meta_name="start" CRM_meta_timeout="120000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_name=start
trace May 20 13:56:16 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 20 13:56:16 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:16 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:16 xml2list(4798):0: Added id=0
trace May 20 13:56:16 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:16 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:16 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:16 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:16 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 construct_op(1882):0: Constructed start op for tunnel-eduroam: interval=0
info May 20 13:56:16 do_lrm_rsc_op(2086):0: Performing key=67:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-eduroam_start_0
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: iface_in=publ-br0.18
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.1
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: id=0
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: name=eduroam IPv4 tunnel
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: network=i.j.k.l/24
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: dst_ip=e.f.g.h
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: src_ip=a.b.c.d
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: CRM_meta_name=start
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: CRM_meta_timeout=120000
trace May 20 13:56:16 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.1
trace May 20 13:56:16 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 20 13:56:16 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 20 13:56:16 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8757 bytes: 772 timeout:120000 msg...
trace May 20 13:56:16 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8757
trace May 20 13:56:16 crm_ipc_send(1227):0: Received response 8757, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4464" lrmd_callid="4464"/>
trace May 20 13:56:16 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 20 13:56:16 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4464" lrmd_callid="4464"/>
trace May 20 13:56:16 do_lrm_rsc_op(2160):0: Recording pending op: 4464 - tunnel-eduroam_start_0 tunnel-eduroam:4464
trace May 20 13:56:16 te_update_job_count_on(548):0: jobs[bifur1] = 2
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 7
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 66
trace May 20 13:56:16 run_graph(300):0: Synapse 7 fired
trace May 20 13:56:16 fire_synapse(223):0: Synapse 7 fired
trace May 20 13:56:16 initiate_action(188):0: Executing pseudo-event: 22 (22)
debug May 20 13:56:16 te_pseudo_action(56):0: Pseudo-action 22 (all_stopped) fired and confirmed
trace May 20 13:56:16 update_graph(112):0: Synapse complete
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 23
trace May 20 13:56:16 update_synapse_confirmed(85):0: Synapse 1 still not confirmed after action 22
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 23
trace May 20 13:56:16 update_synapse_ready(43):0: Processing input 67
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 67
trace May 20 13:56:16 update_synapse_confirmed(85):0: Synapse 4 still not confirmed after action 22
trace May 20 13:56:16 update_graph(112):0: Synapse complete
trace May 20 13:56:16 update_graph(112):0: Synapse complete
trace May 20 13:56:16 update_graph(115):0: Synapse executed
trace May 20 13:56:16 update_synapse_confirmed(76):0: Processing action 22
trace May 20 13:56:16 update_synapse_confirmed(79):0: Confirmed: Action 22 of Synapse 7
trace May 20 13:56:16 update_synapse_confirmed(90):0: Confirmed: Synapse 7
trace May 20 13:56:16 update_synapse_confirmed(96):0: Updated synapse 7
trace May 20 13:56:16 update_graph(125):0: Updated graph with completed action 22
trace May 20 13:56:16 trigger_graph_processing(511):0: te_pseudo_action:59 - Triggered graph processing
debug May 20 13:56:16 run_graph(343):0: Transition 436 (Complete=3, Pending=2, Fired=3, Skipped=0, Incomplete=2, Source=/var/lib/pacemaker/pengine/pe-input-2550.bz2): In-progress
trace May 20 13:56:16 te_graph_trigger(487):0: Transition not yet complete
trace May 20 13:56:16 te_graph_trigger(460):0: Invoking graph 436 in state S_TRANSITION_ENGINE
trace May 20 13:56:16 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:16 run_graph(267):0: Entering graph 436 callback
trace May 20 13:56:16 run_graph(274):0: Synapse 0 complete
trace May 20 13:56:16 run_graph(278):0: Synapse 1: confirmation pending
trace May 20 13:56:16 run_graph(278):0: Synapse 4: confirmation pending
trace May 20 13:56:16 run_graph(274):0: Synapse 5 complete
trace May 20 13:56:16 run_graph(274):0: Synapse 6 complete
trace May 20 13:56:16 run_graph(274):0: Synapse 7 complete
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 23
trace May 20 13:56:16 should_fire_synapse(146):0: Input 23 for synapse 2 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 2 cannot fire
trace May 20 13:56:16 should_fire_synapse(138):0: Checking pre-reqs for synapse 3
trace May 20 13:56:16 should_fire_synapse(144):0: Processing input 67
trace May 20 13:56:16 should_fire_synapse(146):0: Input 67 for synapse 3 not satisfied: not confirmed
trace May 20 13:56:16 run_graph(315):0: Synapse 3 cannot fire
debug May 20 13:56:16 run_graph(343):0: Transition 436 (Complete=4, Pending=2, Fired=0, Skipped=0, Incomplete=2, Source=/var/lib/pacemaker/pengine/pe-input-2550.bz2): In-progress
trace May 20 13:56:16 te_graph_trigger(491):0: Transition not yet complete - no actions fired
trace May 20 13:56:17 crm_ipc_read(1003):0: Received lrmd event 4398, size=776, rc=776, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="120000" lrmd_rsc_interval="0" lrmd
trace May 20 13:56:17 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 736 (I/O condition=1)
trace May 20 13:56:17 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.18" tunnel_dst_ip="10.10.0.1" id="0" name="eduroam IPv4 tunnel" iface_out="publ-br1" network="i.j.k.l/24" dst_ip="e.f.g.h" crm_feature_set="3.0.11" src_ip="a.b.c.d" CRM_meta_name="start" tunnel_src_ip="10.10.1.1" CRM_meta_timeout="120000"/>
trace May 20 13:56:17 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:17 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:17 xml2list(4798):0: Added id=0
trace May 20 13:56:17 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:17 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:17 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:17 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:17 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:17 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:17 xml2list(4798):0: Added CRM_meta_name=start
trace May 20 13:56:17 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:17 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 20 13:56:17 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 20 13:56:17 build_operation_update(763):0: Building tunnel-eduroam operation update with originator version: 3.0.11
trace May 20 13:56:17 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 20 13:56:17 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 20 13:56:17 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-eduroam after start op complete (interval=0)
trace May 20 13:56:17 create_operation_update(1775):0: DC version: 3.0.11
trace May 20 13:56:17 find_entity(2226):0: node <lrm_rsc_op id=tunnel-eduroam_last_0> not found in lrm_resource.
trace May 20 13:56:17 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 20 13:56:17 create_operation_update(1870):0: Timing data (tunnel-eduroam_start_0): last=1558353376 change=0 exec=314 queue=0
trace May 20 13:56:17 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:17 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:17 crm_md5sum(2102):0: Beginning digest of 203 bytes
trace May 20 13:56:17 crm_md5sum(2110):0: Digest 9a80239c380f1eafa208100c3c658458.
trace May 20 13:56:17 calculate_xml_digest_v1(83):0: digest:source <parameters dst_ip="e.f.g.h" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:17 action_synced_wait(492):0: Waiting for 12690
trace May 20 13:56:17 svc_read_output(81):0: Reading tunnel_meta-data_0 stdout into offset 0
trace May 20 13:56:17 svc_read_output(87):0: Got 499 chars: <?xml version="1.0"?>
<!DOCTYPE resource-agent SYSTEM "ra-api-1.dtd">
<resource-
trace May 20 13:56:17 svc_read_output(87):0: Got 499 chars: <parameter name="id" unique="1" required="1">
<longdesc lang="en">
Unique identi
trace May 20 13:56:17 svc_read_output(87):0: Got 499 chars: ongdesc lang="en">
Destination IP address for the tunnel packets.
</longdesc>
<s
trace May 20 13:56:17 svc_read_output(87):0: Got 499 chars: esc lang="en">
The destination address in the tunnel packets.
</longdesc>
<short
trace May 20 13:56:17 svc_read_output(87):0: Got 499 chars: he interface name of the tunnel.
</longdesc>
<shortdesc lang="en">Outgoing tunne
trace May 20 13:56:17 svc_read_output(87):0: Got 477 chars: <shortdesc lang="en">Optional iptables chain</shortdesc>
<content type="string"
trace May 20 13:56:17 action_synced_wait(548):0: Child done: 12690
info May 20 13:56:17 action_synced_wait(575):0: Managed tunnel_meta-data_0 process 12690 exited with rc=0
trace May 20 13:56:17 svc_read_output(78):0: Reading tunnel_meta-data_0 stdout into offset 2972
trace May 20 13:56:17 svc_read_output(81):0: Reading tunnel_meta-data_0 stderr into offset 0
trace May 20 13:56:17 services_action_sync(713):0: > tunnel_meta-data_0: /usr/lib/ocf/resource.d/local/tunnel = 0
trace May 20 13:56:17 services_action_sync(715):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:17 get_rsc_metadata(539):0: Retrieved live metadata for ocf::local:tunnel
trace May 20 13:56:17 build_operation_update(787):0: Including additional digests for ocf::local:tunnel
trace May 20 13:56:17 build_parameter_list(614):0: Attr name is ouniques for %s::%s:%s
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr name=eduroam IPv4 tunnel to the xml result
trace May 20 13:56:17 build_parameter_list(614):0: Attr id is unique
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr id=0 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting src_ip for unique
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting dst_ip for unique
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting tunnel_src_ip for unique
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting tunnel_dst_ip for unique
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting network for unique
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting iface_out for unique
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting iface_in for unique
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting chain for unique
trace May 20 13:56:17 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:17 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:17 crm_md5sum(2102):0: Beginning digest of 49 bytes
trace May 20 13:56:17 crm_md5sum(2110):0: Digest 8ec3fbe5d133432ead850c50a36f516c.
trace May 20 13:56:17 calculate_xml_digest_v1(83):0: digest:source <parameters id="0" name="eduroam IPv4 tunnel"/>
trace May 20 13:56:17 append_restart_list(693):0: tunnel-eduroam: 8ec3fbe5d133432ead850c50a36f516c, name id
trace May 20 13:56:17 append_restart_list(694):0: restart digest source <parameters name="eduroam IPv4 tunnel" id="0"/>
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting name for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting name match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr name=eduroam IPv4 tunnel to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting id for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting id match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr id=0 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting src_ip for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr src_ip=a.b.c.d to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr dst_ip=e.f.g.h to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.1 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.1 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting network for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting network match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr network=i.j.k.l/24 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting iface_out for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting iface_in for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr iface_in=publ-br0.18 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting chain for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting chain match for private xml
trace May 20 13:56:17 append_secure_list(726):0: tunnel-eduroam: no secure parameters
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <status>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-eduroam" type="tunnel" class="ocf" provider="local">
trace May 20 13:56:17 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </lrm>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </node_state>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </status>
trace May 20 13:56:17 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 20 13:56:17 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 20 13:56:17 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 8758 bytes: 1094 timeout:120000 msg...
trace May 20 13:56:17 crm_ipc_send(1202):0: Message sent, not waiting for reply to 8758 from cib_shm to 1094 bytes...
trace May 20 13:56:17 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 20 13:56:17 cib_native_perform_op_delegate(398):0: Async call, returning 3830
trace May 20 13:56:17 do_update_resource(2313):0: Sent resource state update message: 3830 for start=0 on tunnel-eduroam
trace May 20 13:56:17 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:17 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 3830
trace May 20 13:56:17 process_lrm_event(2413):0: Op tunnel-eduroam_start_0 (call=4464, stop-id=tunnel-eduroam:4464, remaining=10): Confirmed
notice May 20 13:56:17 process_lrm_event(2438):0: Result of start operation for tunnel-eduroam on bifur1: 0 (ok) | call=4464 key=tunnel-eduroam_start_0 confirmed=true cib-update=3830
debug May 20 13:56:17 update_history_cache(196):0: Updating history for 'tunnel-eduroam' with start op
trace May 20 13:56:17 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 20 13:56:17 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 20 13:56:17 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:17 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:17 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:17 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:17 crm_ipc_read(1003):0: Received cib_shm event 16869, size=3313, rc=3313, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 20 13:56:17 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3273 (I/O condition=1)
trace May 20 13:56:17 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:17 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 20 13:56:17 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 20 13:56:17 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 20 13:56:17 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:17 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 20 13:56:17 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:17 xml_patch_versions(1747):0: Got 591 for del[epoch]
trace May 20 13:56:17 xml_patch_versions(1747):0: Got 3 for del[num_updates]
trace May 20 13:56:17 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:17 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:17 xml_patch_versions(1758):0: Got 4 for add[num_updates]
debug May 20 13:56:17 te_update_diff(390):0: Processing (cib_modify) diff: 0.591.3 -> 0.591.4 (S_TRANSITION_ENGINE)
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <version>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="591" num_updates="3"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="591" num_updates="4"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </version>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="4"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="591" num_updates="4" admin_epoch="0" cib-last-written="Mon May 20 13:56:15 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:17 crm_xml_escape(3177):0: Dumped '/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-eduroam']/lrm_rsc_op[@id='tunnel-eduroam_last_0']'
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-eduroam']/lrm_rsc_op[@id='tunnel-eduroam_last_0']">
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="operation_key" operation="set" value="tunnel-eduroam_start_0"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="operation" operation="set" value="start"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="67:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;67:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="4464"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="rc-code" operation="set" value="0"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="314"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:17 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </diff>
trace May 20 13:56:17 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 20 13:56:17 te_update_diff(439):0: Handling modify operation for /cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-eduroam']/lrm_rsc_op[@id='tunnel-eduroam_last_0'] matched by lrm_rsc_op
trace May 20 13:56:17 status_from_rc(232):0: Target rc: == 0
trace May 20 13:56:17 stop_te_timer(438):0: Stopping action timer
trace May 20 13:56:17 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(115):0: Synapse executed
trace May 20 13:56:17 update_synapse_confirmed(76):0: Processing action 23
trace May 20 13:56:17 update_synapse_confirmed(85):0: Synapse 1 still not confirmed after action 67
trace May 20 13:56:17 update_synapse_ready(43):0: Processing input 23
trace May 20 13:56:17 update_synapse_ready(43):0: Processing input 67
trace May 20 13:56:17 update_synapse_ready(46):0: Marking input 67 of synapse 3 confirmed
trace May 20 13:56:17 update_synapse_ready(57):0: Updated synapse 3
trace May 20 13:56:17 update_graph(115):0: Synapse executed
trace May 20 13:56:17 update_synapse_confirmed(76):0: Processing action 67
trace May 20 13:56:17 update_synapse_confirmed(79):0: Confirmed: Action 67 of Synapse 4
trace May 20 13:56:17 update_synapse_confirmed(90):0: Confirmed: Synapse 4
trace May 20 13:56:17 update_synapse_confirmed(96):0: Updated synapse 4
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(125):0: Updated graph with completed action 67
trace May 20 13:56:17 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 20 13:56:17 match_graph_event(316):0: Action tunnel-eduroam_start_0 (67) confirmed on bifur1 (rc=0)
trace May 20 13:56:17 process_graph_event(520):0: Processed update to tunnel-eduroam_start_0: 67:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 20 13:56:17 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:17 crm_ipc_read(1003):0: Received cib_shm event 16871, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="3830" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 20 13:56:17 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 20 13:56:17 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:17 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 20 13:56:17 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 3830
trace May 20 13:56:17 cib_rsc_callback(2203):0: Resource update 3830 complete: rc=0
trace May 20 13:56:17 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 20 13:56:17 cib_native_callback(663):0: Invoking global callback for call 3830
trace May 20 13:56:17 cib_native_callback(666):0: OP callback activated for 3830
trace May 20 13:56:17 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 20 13:56:17 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 20 13:56:17 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:17 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:17 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:17 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:17 te_graph_trigger(460):0: Invoking graph 436 in state S_TRANSITION_ENGINE
trace May 20 13:56:17 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:17 run_graph(267):0: Entering graph 436 callback
trace May 20 13:56:17 run_graph(274):0: Synapse 0 complete
trace May 20 13:56:17 run_graph(278):0: Synapse 1: confirmation pending
trace May 20 13:56:17 run_graph(274):0: Synapse 4 complete
trace May 20 13:56:17 run_graph(274):0: Synapse 5 complete
trace May 20 13:56:17 run_graph(274):0: Synapse 6 complete
trace May 20 13:56:17 run_graph(274):0: Synapse 7 complete
trace May 20 13:56:17 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 20 13:56:17 should_fire_synapse(144):0: Processing input 23
trace May 20 13:56:17 should_fire_synapse(146):0: Input 23 for synapse 2 not satisfied: not confirmed
trace May 20 13:56:17 run_graph(315):0: Synapse 2 cannot fire
trace May 20 13:56:17 should_fire_synapse(138):0: Checking pre-reqs for synapse 3
trace May 20 13:56:17 should_fire_synapse(144):0: Processing input 67
trace May 20 13:56:17 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 1 limit= 8 limit
trace May 20 13:56:17 run_graph(300):0: Synapse 3 fired
trace May 20 13:56:17 fire_synapse(223):0: Synapse 3 fired
trace May 20 13:56:17 initiate_action(192):0: Executing rsc-event: 68 (68)
notice May 20 13:56:17 te_rsc_command(436):0: Initiating monitor operation tunnel-eduroam_monitor_30000 locally on bifur1 | action 68
trace May 20 13:56:17 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 20 13:56:17 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 20 13:56:17 get_lrm_resource(1253):0: Retrieving tunnel-eduroam from the LRM.
trace May 20 13:56:17 xml2list(4792):0: Unpacking <attributes CRM_meta_interval="30000" CRM_meta_name="monitor" CRM_meta_timeout="30000" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:17 xml2list(4798):0: Added CRM_meta_interval=30000
trace May 20 13:56:17 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 20 13:56:17 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:17 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:17 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:17 xml2list(4798):0: Added id=0
trace May 20 13:56:17 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:17 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:17 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:17 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:17 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:17 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:17 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:17 construct_op(1882):0: Constructed monitor op for tunnel-eduroam: interval=30000
info May 20 13:56:17 do_lrm_rsc_op(2086):0: Performing key=68:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-eduroam_monitor_30000
trace May 20 13:56:17 cancel_op_key(1239):0: Removed 0 op cache entries, new size: 10
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: iface_in=publ-br0.18
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.1
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.1
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: id=0
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: name=eduroam IPv4 tunnel
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: network=i.j.k.l/24
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: dst_ip=e.f.g.h
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: src_ip=a.b.c.d
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: CRM_meta_name=monitor
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: CRM_meta_timeout=30000
trace May 20 13:56:17 hash2smartfield(4734):0: dumped: CRM_meta_interval=30000
trace May 20 13:56:17 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 20 13:56:17 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 20 13:56:17 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8759 bytes: 803 timeout:30000 msg...
trace May 20 13:56:17 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8759
trace May 20 13:56:17 crm_ipc_send(1227):0: Received response 8759, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4465" lrmd_callid="4465"/>
trace May 20 13:56:17 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 20 13:56:17 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4465" lrmd_callid="4465"/>
trace May 20 13:56:17 do_lrm_rsc_op(2160):0: Recording pending op: 4465 - tunnel-eduroam_monitor_30000 tunnel-eduroam:4465
trace May 20 13:56:17 te_update_job_count_on(548):0: jobs[bifur1] = 2
debug May 20 13:56:17 run_graph(343):0: Transition 436 (Complete=5, Pending=2, Fired=1, Skipped=0, Incomplete=1, Source=/var/lib/pacemaker/pengine/pe-input-2550.bz2): In-progress
trace May 20 13:56:17 te_graph_trigger(487):0: Transition not yet complete
trace May 20 13:56:17 crm_ipc_read(1003):0: Received lrmd event 4399, size=807, rc=807, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="30000" lrmd_rsc_interval="30000" l
trace May 20 13:56:17 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 767 (I/O condition=1)
trace May 20 13:56:17 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.18" CRM_meta_timeout="30000" CRM_meta_interval="30000" id="0" name="eduroam IPv4 tunnel" iface_out="publ-br1" network="i.j.k.l/24" crm_feature_set="3.0.11" dst_ip="e.f.g.h" src_ip="a.b.c.d" CRM_meta_name="monitor" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:17 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 20 13:56:17 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:17 xml2list(4798):0: Added CRM_meta_interval=30000
trace May 20 13:56:17 xml2list(4798):0: Added id=0
trace May 20 13:56:17 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 20 13:56:17 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:17 xml2list(4798):0: Added network=i.j.k.l/24
trace May 20 13:56:17 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:17 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:17 xml2list(4798):0: Added src_ip=a.b.c.d
trace May 20 13:56:17 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 20 13:56:17 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 20 13:56:17 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 20 13:56:17 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 20 13:56:17 build_operation_update(763):0: Building tunnel-eduroam operation update with originator version: 3.0.11
trace May 20 13:56:17 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 20 13:56:17 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 20 13:56:17 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-eduroam after monitor op complete (interval=30000)
trace May 20 13:56:17 create_operation_update(1775):0: DC version: 3.0.11
trace May 20 13:56:17 find_entity(2226):0: node <lrm_rsc_op id=tunnel-eduroam_monitor_30000> not found in lrm_resource.
trace May 20 13:56:17 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 20 13:56:17 create_operation_update(1870):0: Timing data (tunnel-eduroam_monitor_30000): last=1558353377 change=0 exec=44 queue=0
trace May 20 13:56:17 compare_version(536):0: 3.0.11 > 1.0.8 (1)
trace May 20 13:56:17 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:17 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:17 crm_md5sum(2102):0: Beginning digest of 228 bytes
trace May 20 13:56:17 crm_md5sum(2110):0: Digest 17540760c41f6fbc6ee7ef5278bddf6a.
trace May 20 13:56:17 calculate_xml_digest_v1(83):0: digest:source <parameters CRM_meta_timeout="30000" dst_ip="e.f.g.h" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="i.j.k.l/24" src_ip="a.b.c.d" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 20 13:56:17 get_rsc_metadata(532):0: Retrieved cached metadata for ocf::local:tunnel
trace May 20 13:56:17 build_operation_update(787):0: Including additional digests for ocf::local:tunnel
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting name for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting name match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr name=eduroam IPv4 tunnel to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting id for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting id match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr id=0 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting src_ip for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr src_ip=a.b.c.d to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr dst_ip=e.f.g.h to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.1 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.1 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting network for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting network match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr network=i.j.k.l/24 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting iface_out for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting iface_in for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 20 13:56:17 build_parameter_list(632):0: Adding attr iface_in=publ-br0.18 to the xml result
trace May 20 13:56:17 build_parameter_list(621):0: Rejecting chain for private
trace May 20 13:56:17 build_parameter_list(625):0: Inverting chain match for private xml
trace May 20 13:56:17 append_secure_list(726):0: tunnel-eduroam: no secure parameters
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <status>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-eduroam" type="tunnel" class="ocf" provider="local">
trace May 20 13:56:17 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </lrm>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </node_state>
trace May 20 13:56:17 do_update_resource(2286):0: do_update_resource </status>
trace May 20 13:56:17 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 20 13:56:17 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 20 13:56:17 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 8760 bytes: 1007 timeout:120000 msg...
trace May 20 13:56:17 crm_ipc_send(1202):0: Message sent, not waiting for reply to 8760 from cib_shm to 1007 bytes...
trace May 20 13:56:17 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 20 13:56:17 cib_native_perform_op_delegate(398):0: Async call, returning 3831
trace May 20 13:56:17 do_update_resource(2313):0: Sent resource state update message: 3831 for monitor=30000 on tunnel-eduroam
trace May 20 13:56:17 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:17 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 3831
info May 20 13:56:17 process_lrm_event(2438):0: Result of monitor operation for tunnel-eduroam on bifur1: 0 (ok) | call=4465 key=tunnel-eduroam_monitor_30000 confirmed=false cib-update=3831
debug May 20 13:56:17 update_history_cache(196):0: Updating history for 'tunnel-eduroam' with monitor op
trace May 20 13:56:17 update_history_cache(266):0: Adding recurring op: tunnel-eduroam_monitor_30000
trace May 20 13:56:17 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 20 13:56:17 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 20 13:56:17 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:17 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:17 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:17 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:17 crm_ipc_read(1003):0: Received cib_shm event 16872, size=2511, rc=2511, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 20 13:56:17 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 2471 (I/O condition=1)
trace May 20 13:56:17 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:17 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 20 13:56:17 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 20 13:56:17 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 20 13:56:17 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:17 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 20 13:56:17 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:17 xml_patch_versions(1747):0: Got 591 for del[epoch]
trace May 20 13:56:17 xml_patch_versions(1747):0: Got 4 for del[num_updates]
trace May 20 13:56:17 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:17 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:17 xml_patch_versions(1758):0: Got 5 for add[num_updates]
debug May 20 13:56:17 te_update_diff(390):0: Processing (cib_modify) diff: 0.591.4 -> 0.591.5 (S_TRANSITION_ENGINE)
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <version>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="591" num_updates="4"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="591" num_updates="5"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </version>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="5"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="591" num_updates="5" admin_epoch="0" cib-last-written="Mon May 20 13:56:15 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:17 crm_xml_escape(3177):0: Dumped '/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-eduroam']'
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <change operation="create" path="/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-eduroam']" position="1">
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw <lrm_rsc_op id="tunnel-eduroam_monitor_30000" operation_key="tunnel-eduroam_monitor_30000" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.11" transition-key="68:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32" transition-magic="0:0;68:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32" on_node="bifur1" call-id="4465" rc-code="0" op-status="0" interval="30000" last-rc-change="1558353377" exec-time="44" queue-time="0" op-digest="17540760c41f6fbc6ee7ef5278bddf6a"/>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:17 te_update_diff(399):0: Patch:Raw </diff>
trace May 20 13:56:17 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 20 13:56:17 te_update_diff(439):0: Handling create operation for /cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-eduroam'] matched by lrm_rsc_op
trace May 20 13:56:17 status_from_rc(232):0: Target rc: == 0
trace May 20 13:56:17 stop_te_timer(438):0: Stopping action timer
trace May 20 13:56:17 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(115):0: Synapse executed
trace May 20 13:56:17 update_synapse_confirmed(76):0: Processing action 23
trace May 20 13:56:17 update_synapse_confirmed(85):0: Synapse 1 still not confirmed after action 68
trace May 20 13:56:17 update_synapse_ready(43):0: Processing input 23
trace May 20 13:56:17 update_graph(115):0: Synapse executed
trace May 20 13:56:17 update_synapse_confirmed(76):0: Processing action 68
trace May 20 13:56:17 update_synapse_confirmed(79):0: Confirmed: Action 68 of Synapse 3
trace May 20 13:56:17 update_synapse_confirmed(90):0: Confirmed: Synapse 3
trace May 20 13:56:17 update_synapse_confirmed(96):0: Updated synapse 3
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(112):0: Synapse complete
trace May 20 13:56:17 update_graph(125):0: Updated graph with completed action 68
trace May 20 13:56:17 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 20 13:56:17 match_graph_event(316):0: Action tunnel-eduroam_monitor_30000 (68) confirmed on bifur1 (rc=0)
trace May 20 13:56:17 process_graph_event(520):0: Processed update to tunnel-eduroam_monitor_30000: 68:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 20 13:56:17 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:17 crm_ipc_read(1003):0: Received cib_shm event 16874, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="3831" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 20 13:56:17 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 20 13:56:17 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:17 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 20 13:56:17 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 3831
trace May 20 13:56:17 cib_rsc_callback(2203):0: Resource update 3831 complete: rc=0
trace May 20 13:56:17 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 20 13:56:17 cib_native_callback(663):0: Invoking global callback for call 3831
trace May 20 13:56:17 cib_native_callback(666):0: OP callback activated for 3831
trace May 20 13:56:17 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 20 13:56:17 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 20 13:56:17 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:17 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:17 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:17 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:17 te_graph_trigger(460):0: Invoking graph 436 in state S_TRANSITION_ENGINE
trace May 20 13:56:17 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:17 run_graph(267):0: Entering graph 436 callback
trace May 20 13:56:17 run_graph(274):0: Synapse 0 complete
trace May 20 13:56:17 run_graph(278):0: Synapse 1: confirmation pending
trace May 20 13:56:17 run_graph(274):0: Synapse 3 complete
trace May 20 13:56:17 run_graph(274):0: Synapse 4 complete
trace May 20 13:56:17 run_graph(274):0: Synapse 5 complete
trace May 20 13:56:17 run_graph(274):0: Synapse 6 complete
trace May 20 13:56:17 run_graph(274):0: Synapse 7 complete
trace May 20 13:56:17 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 20 13:56:17 should_fire_synapse(144):0: Processing input 23
trace May 20 13:56:17 should_fire_synapse(146):0: Input 23 for synapse 2 not satisfied: not confirmed
trace May 20 13:56:17 run_graph(315):0: Synapse 2 cannot fire
debug May 20 13:56:17 run_graph(343):0: Transition 436 (Complete=6, Pending=1, Fired=0, Skipped=0, Incomplete=1, Source=/var/lib/pacemaker/pengine/pe-input-2550.bz2): In-progress
trace May 20 13:56:17 te_graph_trigger(491):0: Transition not yet complete - no actions fired
trace May 20 13:56:18 crm_ipc_read(1003):0: Received lrmd event 4400, size=808, rc=808, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="120000" lrmd_rsc_interval="0" lrmd
trace May 20 13:56:18 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 768 (I/O condition=1)
trace May 20 13:56:18 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.24" tunnel_dst_ip="10.10.0.3" id="1" name="Wigner guest IPv4 tunnel" iface_out="publ-br1" network="m.n.o.p/25" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" src_ip="q.r.s.t" CRM_meta_name="start" tunnel_src_ip="10.10.1.3" CRM_meta_timeout="120000"/>
trace May 20 13:56:18 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:18 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:18 xml2list(4798):0: Added id=1
trace May 20 13:56:18 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:18 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:18 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:18 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:18 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:18 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:18 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:18 xml2list(4798):0: Added CRM_meta_name=start
trace May 20 13:56:18 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:18 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 20 13:56:18 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 20 13:56:18 build_operation_update(763):0: Building tunnel-wigner-guest operation update with originator version: 3.0.11
trace May 20 13:56:18 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 20 13:56:18 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 20 13:56:18 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-wigner-guest after start op complete (interval=0)
trace May 20 13:56:18 create_operation_update(1775):0: DC version: 3.0.11
trace May 20 13:56:18 find_entity(2226):0: node <lrm_rsc_op id=tunnel-wigner-guest_last_0> not found in lrm_resource.
trace May 20 13:56:18 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 20 13:56:18 create_operation_update(1870):0: Timing data (tunnel-wigner-guest_start_0): last=1558353376 change=0 exec=1239 queue=0
trace May 20 13:56:18 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:18 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:18 crm_md5sum(2102):0: Beginning digest of 229 bytes
trace May 20 13:56:18 crm_md5sum(2110):0: Digest 540db6b587fc94bd9b5bfab7f5cd5685.
trace May 20 13:56:18 calculate_xml_digest_v1(83):0: digest:source <parameters chain="nfcp-check" dst_ip="e.f.g.h" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:18 action_synced_wait(492):0: Waiting for 12872
trace May 20 13:56:18 svc_read_output(81):0: Reading tunnel_meta-data_0 stdout into offset 0
trace May 20 13:56:18 svc_read_output(87):0: Got 499 chars: <?xml version="1.0"?>
<!DOCTYPE resource-agent SYSTEM "ra-api-1.dtd">
<resource-
trace May 20 13:56:18 svc_read_output(87):0: Got 499 chars: <parameter name="id" unique="1" required="1">
<longdesc lang="en">
Unique identi
trace May 20 13:56:18 svc_read_output(87):0: Got 499 chars: ongdesc lang="en">
Destination IP address for the tunnel packets.
</longdesc>
<s
trace May 20 13:56:18 svc_read_output(87):0: Got 499 chars: esc lang="en">
The destination address in the tunnel packets.
</longdesc>
<short
trace May 20 13:56:18 svc_read_output(87):0: Got 499 chars: he interface name of the tunnel.
</longdesc>
<shortdesc lang="en">Outgoing tunne
trace May 20 13:56:18 svc_read_output(87):0: Got 477 chars: <shortdesc lang="en">Optional iptables chain</shortdesc>
<content type="string"
trace May 20 13:56:18 action_synced_wait(548):0: Child done: 12872
info May 20 13:56:18 action_synced_wait(575):0: Managed tunnel_meta-data_0 process 12872 exited with rc=0
trace May 20 13:56:18 svc_read_output(78):0: Reading tunnel_meta-data_0 stdout into offset 2972
trace May 20 13:56:18 svc_read_output(81):0: Reading tunnel_meta-data_0 stderr into offset 0
trace May 20 13:56:18 services_action_sync(713):0: > tunnel_meta-data_0: /usr/lib/ocf/resource.d/local/tunnel = 0
trace May 20 13:56:18 services_action_sync(715):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:18 get_rsc_metadata(539):0: Retrieved live metadata for ocf::local:tunnel
trace May 20 13:56:18 build_operation_update(787):0: Including additional digests for ocf::local:tunnel
trace May 20 13:56:18 build_parameter_list(614):0: Attr name is ouniques for %s::%s:%s
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr name=Wigner guest IPv4 tunnel to the xml result
trace May 20 13:56:18 build_parameter_list(614):0: Attr id is unique
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr id=1 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting src_ip for unique
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting dst_ip for unique
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting tunnel_src_ip for unique
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting tunnel_dst_ip for unique
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting network for unique
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting iface_out for unique
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting iface_in for unique
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting chain for unique
trace May 20 13:56:18 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:18 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:18 crm_md5sum(2102):0: Beginning digest of 54 bytes
trace May 20 13:56:18 crm_md5sum(2110):0: Digest a81356b66867aacd0853c28318c5b47b.
trace May 20 13:56:18 calculate_xml_digest_v1(83):0: digest:source <parameters id="1" name="Wigner guest IPv4 tunnel"/>
trace May 20 13:56:18 append_restart_list(693):0: tunnel-wigner-guest: a81356b66867aacd0853c28318c5b47b, name id
trace May 20 13:56:18 append_restart_list(694):0: restart digest source <parameters name="Wigner guest IPv4 tunnel" id="1"/>
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting name for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting name match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr name=Wigner guest IPv4 tunnel to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting id for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting id match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr id=1 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting src_ip for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr src_ip=q.r.s.t to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr dst_ip=e.f.g.h to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.3 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.3 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting network for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting network match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr network=m.n.o.p/25 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting iface_out for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting iface_in for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr iface_in=publ-br0.24 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting chain for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting chain match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr chain=nfcp-check to the xml result
trace May 20 13:56:18 append_secure_list(726):0: tunnel-wigner-guest: no secure parameters
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <status>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-wigner-guest" type="tunnel" class="ocf" provider="local">
trace May 20 13:56:18 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </lrm>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </node_state>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </status>
trace May 20 13:56:18 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 20 13:56:18 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 20 13:56:18 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 8761 bytes: 1110 timeout:120000 msg...
trace May 20 13:56:18 crm_ipc_send(1202):0: Message sent, not waiting for reply to 8761 from cib_shm to 1110 bytes...
trace May 20 13:56:18 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 20 13:56:18 cib_native_perform_op_delegate(398):0: Async call, returning 3832
trace May 20 13:56:18 do_update_resource(2313):0: Sent resource state update message: 3832 for start=0 on tunnel-wigner-guest
trace May 20 13:56:18 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:18 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 3832
trace May 20 13:56:18 process_lrm_event(2413):0: Op tunnel-wigner-guest_start_0 (call=4463, stop-id=tunnel-wigner-guest:4463, remaining=10): Confirmed
notice May 20 13:56:18 process_lrm_event(2438):0: Result of start operation for tunnel-wigner-guest on bifur1: 0 (ok) | call=4463 key=tunnel-wigner-guest_start_0 confirmed=true cib-update=3832
debug May 20 13:56:18 update_history_cache(196):0: Updating history for 'tunnel-wigner-guest' with start op
trace May 20 13:56:18 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 20 13:56:18 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 20 13:56:18 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:18 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:18 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:18 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:18 crm_ipc_read(1003):0: Received cib_shm event 16875, size=3301, rc=3301, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 20 13:56:18 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3261 (I/O condition=1)
trace May 20 13:56:18 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:18 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 20 13:56:18 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 20 13:56:18 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 20 13:56:18 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:18 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 20 13:56:18 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:18 xml_patch_versions(1747):0: Got 591 for del[epoch]
trace May 20 13:56:18 xml_patch_versions(1747):0: Got 5 for del[num_updates]
trace May 20 13:56:18 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:18 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:18 xml_patch_versions(1758):0: Got 6 for add[num_updates]
debug May 20 13:56:18 te_update_diff(390):0: Processing (cib_modify) diff: 0.591.5 -> 0.591.6 (S_TRANSITION_ENGINE)
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <version>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="591" num_updates="5"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="591" num_updates="6"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </version>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="6"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="591" num_updates="6" admin_epoch="0" cib-last-written="Mon May 20 13:56:15 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:18 crm_xml_escape(3177):0: Dumped '/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_last_0']'
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_last_0']">
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="operation_key" operation="set" value="tunnel-wigner-guest_start_0"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="operation" operation="set" value="start"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="23:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;23:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="4463"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="1239"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:18 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </diff>
trace May 20 13:56:18 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 20 13:56:18 te_update_diff(439):0: Handling modify operation for /cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_last_0'] matched by lrm_rsc_op
trace May 20 13:56:18 status_from_rc(232):0: Target rc: == 0
trace May 20 13:56:18 stop_te_timer(438):0: Stopping action timer
trace May 20 13:56:18 te_update_job_count_on(548):0: jobs[bifur1] = 0
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(115):0: Synapse executed
trace May 20 13:56:18 update_synapse_confirmed(76):0: Processing action 23
trace May 20 13:56:18 update_synapse_confirmed(79):0: Confirmed: Action 23 of Synapse 1
trace May 20 13:56:18 update_synapse_confirmed(90):0: Confirmed: Synapse 1
trace May 20 13:56:18 update_synapse_confirmed(96):0: Updated synapse 1
trace May 20 13:56:18 update_synapse_ready(43):0: Processing input 23
trace May 20 13:56:18 update_synapse_ready(46):0: Marking input 23 of synapse 2 confirmed
trace May 20 13:56:18 update_synapse_ready(57):0: Updated synapse 2
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(125):0: Updated graph with completed action 23
trace May 20 13:56:18 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 20 13:56:18 match_graph_event(316):0: Action tunnel-wigner-guest_start_0 (23) confirmed on bifur1 (rc=0)
trace May 20 13:56:18 process_graph_event(520):0: Processed update to tunnel-wigner-guest_start_0: 23:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 20 13:56:18 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:18 crm_ipc_read(1003):0: Received cib_shm event 16877, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="3832" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 20 13:56:18 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 20 13:56:18 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:18 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 20 13:56:18 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 3832
trace May 20 13:56:18 cib_rsc_callback(2203):0: Resource update 3832 complete: rc=0
trace May 20 13:56:18 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 20 13:56:18 cib_native_callback(663):0: Invoking global callback for call 3832
trace May 20 13:56:18 cib_native_callback(666):0: OP callback activated for 3832
trace May 20 13:56:18 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 20 13:56:18 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 20 13:56:18 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:18 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:18 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:18 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:18 te_graph_trigger(460):0: Invoking graph 436 in state S_TRANSITION_ENGINE
trace May 20 13:56:18 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:18 run_graph(267):0: Entering graph 436 callback
trace May 20 13:56:18 run_graph(274):0: Synapse 0 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 1 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 3 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 4 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 5 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 6 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 7 complete
trace May 20 13:56:18 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 20 13:56:18 should_fire_synapse(144):0: Processing input 23
trace May 20 13:56:18 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 0 limit= 8 limit
trace May 20 13:56:18 run_graph(300):0: Synapse 2 fired
trace May 20 13:56:18 fire_synapse(223):0: Synapse 2 fired
trace May 20 13:56:18 initiate_action(192):0: Executing rsc-event: 21 (21)
notice May 20 13:56:18 te_rsc_command(436):0: Initiating monitor operation tunnel-wigner-guest_monitor_30000 locally on bifur1 | action 21
trace May 20 13:56:18 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 20 13:56:18 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 20 13:56:18 get_lrm_resource(1253):0: Retrieving tunnel-wigner-guest from the LRM.
trace May 20 13:56:18 xml2list(4792):0: Unpacking <attributes CRM_meta_interval="30000" CRM_meta_name="monitor" CRM_meta_timeout="30000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:18 xml2list(4798):0: Added CRM_meta_interval=30000
trace May 20 13:56:18 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 20 13:56:18 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:18 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:18 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:18 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:18 xml2list(4798):0: Added id=1
trace May 20 13:56:18 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:18 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:18 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:18 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:18 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:18 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:18 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:18 construct_op(1882):0: Constructed monitor op for tunnel-wigner-guest: interval=30000
info May 20 13:56:18 do_lrm_rsc_op(2086):0: Performing key=21:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-wigner-guest_monitor_30000
trace May 20 13:56:18 cancel_op_key(1239):0: Removed 0 op cache entries, new size: 10
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: iface_in=publ-br0.24
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.3
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.3
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: id=1
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: name=Wigner guest IPv4 tunnel
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: network=m.n.o.p/25
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: chain=nfcp-check
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: dst_ip=e.f.g.h
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: src_ip=q.r.s.t
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: CRM_meta_name=monitor
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: CRM_meta_timeout=30000
trace May 20 13:56:18 hash2smartfield(4734):0: dumped: CRM_meta_interval=30000
trace May 20 13:56:18 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 20 13:56:18 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 20 13:56:18 crm_ipc_send(1189):0: Sending from client: lrmd request id: 8762 bytes: 834 timeout:30000 msg...
trace May 20 13:56:18 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 8762
trace May 20 13:56:18 crm_ipc_send(1227):0: Received response 8762, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4466" lrmd_callid="4466"/>
trace May 20 13:56:18 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 20 13:56:18 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="4466" lrmd_callid="4466"/>
trace May 20 13:56:18 do_lrm_rsc_op(2160):0: Recording pending op: 4466 - tunnel-wigner-guest_monitor_30000 tunnel-wigner-guest:4466
trace May 20 13:56:18 te_update_job_count_on(548):0: jobs[bifur1] = 1
debug May 20 13:56:18 run_graph(343):0: Transition 436 (Complete=7, Pending=1, Fired=1, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-2550.bz2): In-progress
trace May 20 13:56:18 te_graph_trigger(487):0: Transition not yet complete
trace May 20 13:56:18 crm_ipc_read(1003):0: Received lrmd event 4401, size=838, rc=838, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="30000" lrmd_rsc_interval="30000" l
trace May 20 13:56:18 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 798 (I/O condition=1)
trace May 20 13:56:18 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.24" CRM_meta_timeout="30000" CRM_meta_interval="30000" id="1" name="Wigner guest IPv4 tunnel" iface_out="publ-br1" network="m.n.o.p/25" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="e.f.g.h" src_ip="q.r.s.t" CRM_meta_name="monitor" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:18 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 20 13:56:18 xml2list(4798):0: Added CRM_meta_timeout=30000
trace May 20 13:56:18 xml2list(4798):0: Added CRM_meta_interval=30000
trace May 20 13:56:18 xml2list(4798):0: Added id=1
trace May 20 13:56:18 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 20 13:56:18 xml2list(4798):0: Added iface_out=publ-br1
trace May 20 13:56:18 xml2list(4798):0: Added network=m.n.o.p/25
trace May 20 13:56:18 xml2list(4798):0: Added chain=nfcp-check
trace May 20 13:56:18 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 20 13:56:18 xml2list(4798):0: Added dst_ip=e.f.g.h
trace May 20 13:56:18 xml2list(4798):0: Added src_ip=q.r.s.t
trace May 20 13:56:18 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 20 13:56:18 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 20 13:56:18 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 20 13:56:18 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 20 13:56:18 build_operation_update(763):0: Building tunnel-wigner-guest operation update with originator version: 3.0.11
trace May 20 13:56:18 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 20 13:56:18 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 20 13:56:18 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-wigner-guest after monitor op complete (interval=30000)
trace May 20 13:56:18 create_operation_update(1775):0: DC version: 3.0.11
trace May 20 13:56:18 find_entity(2226):0: node <lrm_rsc_op id=tunnel-wigner-guest_monitor_30000> not found in lrm_resource.
trace May 20 13:56:18 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 20 13:56:18 create_operation_update(1870):0: Timing data (tunnel-wigner-guest_monitor_30000): last=1558353378 change=0 exec=51 queue=0
trace May 20 13:56:18 compare_version(536):0: 3.0.11 > 1.0.8 (1)
trace May 20 13:56:18 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 20 13:56:18 calculate_xml_digest_v1(73):0: Done
trace May 20 13:56:18 crm_md5sum(2102):0: Beginning digest of 254 bytes
trace May 20 13:56:18 crm_md5sum(2110):0: Digest ce9cbe34f2d4c5c5fa60875022a32e3b.
trace May 20 13:56:18 calculate_xml_digest_v1(83):0: digest:source <parameters CRM_meta_timeout="30000" chain="nfcp-check" dst_ip="e.f.g.h" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="m.n.o.p/25" src_ip="q.r.s.t" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 20 13:56:18 get_rsc_metadata(532):0: Retrieved cached metadata for ocf::local:tunnel
trace May 20 13:56:18 build_operation_update(787):0: Including additional digests for ocf::local:tunnel
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting name for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting name match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr name=Wigner guest IPv4 tunnel to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting id for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting id match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr id=1 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting src_ip for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr src_ip=q.r.s.t to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr dst_ip=e.f.g.h to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.3 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.3 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting network for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting network match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr network=m.n.o.p/25 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting iface_out for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting iface_in for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr iface_in=publ-br0.24 to the xml result
trace May 20 13:56:18 build_parameter_list(621):0: Rejecting chain for private
trace May 20 13:56:18 build_parameter_list(625):0: Inverting chain match for private xml
trace May 20 13:56:18 build_parameter_list(632):0: Adding attr chain=nfcp-check to the xml result
trace May 20 13:56:18 append_secure_list(726):0: tunnel-wigner-guest: no secure parameters
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <status>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-wigner-guest" type="tunnel" class="ocf" provider="local">
trace May 20 13:56:18 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </lrm>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </node_state>
trace May 20 13:56:18 do_update_resource(2286):0: do_update_resource </status>
trace May 20 13:56:18 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 20 13:56:18 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 20 13:56:18 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 8763 bytes: 1022 timeout:120000 msg...
trace May 20 13:56:18 crm_ipc_send(1202):0: Message sent, not waiting for reply to 8763 from cib_shm to 1022 bytes...
trace May 20 13:56:18 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 20 13:56:18 cib_native_perform_op_delegate(398):0: Async call, returning 3833
trace May 20 13:56:18 do_update_resource(2313):0: Sent resource state update message: 3833 for monitor=30000 on tunnel-wigner-guest
trace May 20 13:56:18 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:18 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 3833
info May 20 13:56:18 process_lrm_event(2438):0: Result of monitor operation for tunnel-wigner-guest on bifur1: 0 (ok) | call=4466 key=tunnel-wigner-guest_monitor_30000 confirmed=false cib-update=3833
debug May 20 13:56:18 update_history_cache(196):0: Updating history for 'tunnel-wigner-guest' with monitor op
trace May 20 13:56:18 update_history_cache(266):0: Adding recurring op: tunnel-wigner-guest_monitor_30000
trace May 20 13:56:18 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 20 13:56:18 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 20 13:56:18 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:18 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:18 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:18 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:18 crm_ipc_read(1003):0: Received cib_shm event 16878, size=3053, rc=3053, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 20 13:56:18 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3013 (I/O condition=1)
trace May 20 13:56:18 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:18 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 20 13:56:18 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 20 13:56:18 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 20 13:56:18 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:18 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 20 13:56:18 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 20 13:56:18 xml_patch_versions(1747):0: Got 591 for del[epoch]
trace May 20 13:56:18 xml_patch_versions(1747):0: Got 6 for del[num_updates]
trace May 20 13:56:18 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 20 13:56:18 xml_patch_versions(1758):0: Got 591 for add[epoch]
trace May 20 13:56:18 xml_patch_versions(1758):0: Got 7 for add[num_updates]
debug May 20 13:56:18 te_update_diff(390):0: Processing (cib_modify) diff: 0.591.6 -> 0.591.7 (S_TRANSITION_ENGINE)
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <version>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="591" num_updates="6"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="591" num_updates="7"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </version>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="7"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="591" num_updates="7" admin_epoch="0" cib-last-written="Mon May 20 13:56:15 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:18 crm_xml_escape(3177):0: Dumped '/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_monitor_30000']'
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_monitor_30000']">
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-list>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="21:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;21:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="4466"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="last-rc-change" operation="set" value="1558353378"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="51"/>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change-list>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw <change-result>
trace May 20 13:56:18 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change-result>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </change>
trace May 20 13:56:18 te_update_diff(399):0: Patch:Raw </diff>
trace May 20 13:56:18 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 20 13:56:18 te_update_diff(439):0: Handling modify operation for /cib/status/node_state[@id='1084762125']/lrm[@id='1084762125']/lrm_resources/lrm_resource[@id='tunnel-wigner-guest']/lrm_rsc_op[@id='tunnel-wigner-guest_monitor_30000'] matched by lrm_rsc_op
trace May 20 13:56:18 status_from_rc(232):0: Target rc: == 0
trace May 20 13:56:18 stop_te_timer(438):0: Stopping action timer
trace May 20 13:56:18 te_update_job_count_on(548):0: jobs[bifur1] = 0
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(115):0: Synapse executed
trace May 20 13:56:18 update_synapse_confirmed(76):0: Processing action 21
trace May 20 13:56:18 update_synapse_confirmed(79):0: Confirmed: Action 21 of Synapse 2
trace May 20 13:56:18 update_synapse_confirmed(90):0: Confirmed: Synapse 2
trace May 20 13:56:18 update_synapse_confirmed(96):0: Updated synapse 2
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(112):0: Synapse complete
trace May 20 13:56:18 update_graph(125):0: Updated graph with completed action 21
trace May 20 13:56:18 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 20 13:56:18 match_graph_event(316):0: Action tunnel-wigner-guest_monitor_30000 (21) confirmed on bifur1 (rc=0)
trace May 20 13:56:18 process_graph_event(520):0: Processed update to tunnel-wigner-guest_monitor_30000: 21:436:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 20 13:56:18 cib_native_notify(698):0: Callback invoked...
trace May 20 13:56:18 crm_ipc_read(1003):0: Received cib_shm event 16880, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="3833" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 20 13:56:18 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 20 13:56:18 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 20 13:56:18 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 20 13:56:18 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 3833
trace May 20 13:56:18 cib_rsc_callback(2203):0: Resource update 3833 complete: rc=0
trace May 20 13:56:18 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 20 13:56:18 cib_native_callback(663):0: Invoking global callback for call 3833
trace May 20 13:56:18 cib_native_callback(666):0: OP callback activated for 3833
trace May 20 13:56:18 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 20 13:56:18 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 20 13:56:18 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 20 13:56:18 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:18 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:18 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 20 13:56:18 te_graph_trigger(460):0: Invoking graph 436 in state S_TRANSITION_ENGINE
trace May 20 13:56:18 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 20 13:56:18 run_graph(267):0: Entering graph 436 callback
trace May 20 13:56:18 run_graph(274):0: Synapse 0 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 1 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 2 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 3 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 4 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 5 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 6 complete
trace May 20 13:56:18 run_graph(274):0: Synapse 7 complete
notice May 20 13:56:18 run_graph(343):0: Transition 436 (Complete=8, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-2550.bz2): Complete
debug May 20 13:56:18 te_graph_trigger(501):0: Transition 436 is now complete
debug May 20 13:56:18 notify_crmd(687):0: Processing transition completion in state S_TRANSITION_ENGINE
debug May 20 13:56:18 notify_crmd(735):0: Transition 436 status: done - <null>
trace May 20 13:56:18 register_fsa_input_adv(113):0: notify_crmd appended FSA input 1352 (I_TE_SUCCESS) (cause=C_FSA_INTERNAL) without data
trace May 20 13:56:18 register_fsa_input_adv(175):0: Queue len: 1
trace May 20 13:56:18 register_fsa_input_adv(184):0: Triggering FSA: register_fsa_input_adv
trace May 20 13:56:18 crm_fsa_trigger(312):0: Invoked (queue len: 1)
trace May 20 13:56:18 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 20 13:56:18 s_crmd_fsa(175):0: Checking messages (1 remaining)
trace May 20 13:56:18 get_message(275):0: Processing input 1352
trace May 20 13:56:18 log_fsa_input(455):0: Processing queued input 1352
trace May 20 13:56:18 log_fsa_input(463):0: FSA processing input from notify_crmd
trace May 20 13:56:18 fsa_dump_actions(919):0: Action 1000000000000000 (A_LOG ) New actions
debug May 20 13:56:18 s_crmd_fsa(197):0: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_FSA_INTERNAL origin=notify_crmd ]
trace May 20 13:56:18 do_fsa_action(142):0: actions:trace: // A_LOG
info May 20 13:56:18 do_log(46):0: Input I_TE_SUCCESS received in state S_TRANSITION_ENGINE from notify_crmd
trace May 20 13:56:18 do_state_transition(492):0: actions:trace: S_TRANSITION_ENGINE -> S_IDLE [ label=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ]
notice May 20 13:56:18 do_state_transition(509):0: State transition S_TRANSITION_ENGINE -> S_IDLE | input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd
trace May 20 13:56:18 crm_set_bit(185):0: Bit 0x00000020 set by do_state
trace May 20 13:56:18 crm_set_bit(185):0: Bit 0x00000080 set by do_state
trace May 20 13:56:18 crm_set_bit(185):0: Bit 0x00000200 set by do_state
debug May 20 13:56:18 do_state_transition(641):0: Starting PEngine Recheck Timer
debug May 20 13:56:18 crm_timer_start(192):0: Started PEngine Recheck Timer (I_PE_CALC:900000ms), src=7212
trace May 20 13:56:18 do_fsa_action(142):0: actions:trace: // A_DC_TIMER_STOP
trace May 20 13:56:18 crm_timer_stop(225):0: Election Trigger (I_DC_TIMEOUT:20000ms) already stopped
trace May 20 13:56:18 do_fsa_action(142):0: actions:trace: // A_INTEGRATE_TIMER_STOP
trace May 20 13:56:18 crm_timer_stop(225):0: Integration Timer (I_INTEGRATED:180000ms) already stopped
trace May 20 13:56:18 do_fsa_action(142):0: actions:trace: // A_FINALIZE_TIMER_STOP
trace May 20 13:56:18 crm_timer_stop(225):0: Finalization Timer (I_ELECTION:1800000ms) already stopped
trace May 20 13:56:18 delete_fsa_input(236):0: About to free C_FSA_INTERNAL data
trace May 20 13:56:18 s_crmd_fsa(246):0: Exiting the FSA
trace May 20 13:56:18 crm_fsa_trigger(314):0: Exited (queue len: 0)
notice May 20 13:56:29 crm_signal_dispatch(276):0: Caught 'Trace/breakpoint trap' signal | 5 (invoking handler)
notice May 20 13:56:30 crm_write_blackbox(443):0: Blackbox dump requested, please see /var/lib/pacemaker/blackbox/crmd-3055.10 for contents
More information about the Users
mailing list