[ClusterLabs] Constant stop/start of resource in spite of interval=0
Kadlecsik József
kadlecsik.jozsef at wigner.mta.hu
Sun May 19 06:20:30 EDT 2019
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:
> > > >
> > > > May 16 14:20:35 [3052] bifur1 lrmd: debug: recurring_action_timer:
> > > > Scheduling another invocation of tunnel-eduroam_monitor_30000
> > > > May 16 14:20:35 [3052] bifur1 lrmd: debug: operation_finished:
> > > > tunnel-eduroam_monitor_30000:62066 - exited with rc=0
> > > > May 16 14:20:35 [3052] bifur1 lrmd: debug: operation_finished:
> > > > tunnel-eduroam_monitor_30000:62066:stderr [ -- empty -- ]
> > > > May 16 14:20:35 [3052] bifur1 lrmd: debug: operation_finished:
> > > > tunnel-eduroam_monitor_30000:62066:stdout [ -- empty -- ]
> > > > May 16 14:20:35 [3052] bifur1 lrmd: debug: log_finished:
> > > > finished - rsc:tunnel-eduroam action:monitor call_id:1045 pid:62066
> > > > exit-code:0 exec-time:0ms queue-time:0ms
> > > > May 16 14:21:04 [3054] bifur1 pengine: info: native_print:
> > > > tunnel-eduroam (ocf::local:tunnel): Started bifur1
> > > > May 16 14:21:04 [3054] bifur1 pengine: info:
> > > > check_action_definition:
> > > > 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.
Any help is really appreciated!
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.5
Ringbuffer:
->NORMAL
->write_pt [52523]
->read_pt [0]
->size [1311744 words]
=>free [5036880 bytes]
=>used [210092 bytes]
trace May 18 23:01:29 mainloop_timer_cb(1162):0: Invoking callbacks for timer throttle-30000-1
debug May 18 23:01:29 throttle_cib_load(218):0: cib load: 0.000000 (0 ticks in 30s)
trace May 18 23:01:29 throttle_mode(436):0: Negligible CIB load detected: 0.000000
debug May 18 23:01:29 throttle_load_avg(260):0: Current load is 0.080000 (full: 0.08 0.08 0.08 1/181 36651)
trace May 18 23:01:29 throttle_handle_load(380):0: Negligible CPU load detected: 0.020000
debug May 18 23:01:29 throttle_io_load(340):0: Current IO load is 0.000000
trace May 18 23:01:29 throttle_handle_load(380):0: Negligible IO load detected: 0.000000
trace May 18 23:01:29 throttle_handle_load(380):0: Negligible blocked IO ratio detected: 0.000000
trace May 18 23:01:59 mainloop_timer_cb(1162):0: Invoking callbacks for timer throttle-30000-1
debug May 18 23:01:59 throttle_cib_load(218):0: cib load: 0.000000 (0 ticks in 30s)
trace May 18 23:01:59 throttle_mode(436):0: Negligible CIB load detected: 0.000000
debug May 18 23:01:59 throttle_load_avg(260):0: Current load is 0.050000 (full: 0.05 0.07 0.08 1/181 37047)
trace May 18 23:01:59 throttle_handle_load(380):0: Negligible CPU load detected: 0.012500
debug May 18 23:01:59 throttle_io_load(340):0: Current IO load is 0.000000
trace May 18 23:01:59 throttle_handle_load(380):0: Negligible IO load detected: 0.000000
trace May 18 23:01:59 throttle_handle_load(380):0: Negligible blocked IO ratio detected: 0.000000
trace May 18 23:02:29 mainloop_timer_cb(1162):0: Invoking callbacks for timer throttle-30000-1
debug May 18 23:02:29 throttle_cib_load(218):0: cib load: 0.000000 (0 ticks in 30s)
trace May 18 23:02:29 throttle_mode(436):0: Negligible CIB load detected: 0.000000
debug May 18 23:02:29 throttle_load_avg(260):0: Current load is 0.030000 (full: 0.03 0.06 0.07 1/181 37305)
trace May 18 23:02:29 throttle_handle_load(380):0: Negligible CPU load detected: 0.007500
debug May 18 23:02:29 throttle_io_load(340):0: Current IO load is 0.000000
trace May 18 23:02:29 throttle_handle_load(380):0: Negligible IO load detected: 0.000000
trace May 18 23:02:29 throttle_handle_load(380):0: Negligible blocked IO ratio detected: 0.000000
info May 18 23:02:47 crm_timer_popped(120):0: PEngine Recheck Timer (I_PE_CALC) just popped (900000ms)
trace May 18 23:02:47 crm_timer_stop(219):0: Stopping PEngine Recheck Timer (I_PE_CALC:900000ms), src=4698
trace May 18 23:02:47 register_fsa_input_adv(113):0: crm_timer_popped appended FSA input 796 (I_PE_CALC) (cause=C_TIMER_POPPED) without data
trace May 18 23:02:47 register_fsa_input_adv(175):0: Queue len: 1
trace May 18 23:02:47 register_fsa_input_adv(184):0: Triggering FSA: register_fsa_input_adv
trace May 18 23:02:47 crm_timer_popped(163):0: Triggering FSA: crm_timer_popped
trace May 18 23:02:47 crm_fsa_trigger(312):0: Invoked (queue len: 1)
trace May 18 23:02:47 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_IDLE
trace May 18 23:02:47 s_crmd_fsa(175):0: Checking messages (1 remaining)
trace May 18 23:02:47 get_message(275):0: Processing input 796
trace May 18 23:02:47 log_fsa_input(455):0: Processing queued input 796
trace May 18 23:02:47 log_fsa_input(463):0: FSA processing input from crm_timer_popped
trace May 18 23:02:47 fsa_dump_actions(904):0: Action 0002000000000000 (A_PE_INVOKE) New actions
debug May 18 23:02:47 s_crmd_fsa(197):0: Processing I_PE_CALC: [ state=S_IDLE cause=C_TIMER_POPPED origin=crm_timer_popped ]
trace May 18 23:02:47 do_state_transition(492):0: actions:trace: S_IDLE -> S_POLICY_ENGINE [ label=I_PE_CALC cause=C_TIMER_POPPED origin=crm_timer_popped ]
notice May 18 23:02:47 do_state_transition(509):0: State transition S_IDLE -> S_POLICY_ENGINE | input=I_PE_CALC cause=C_TIMER_POPPED origin=crm_timer_popped
trace May 18 23:02:47 crm_set_bit(185):0: Bit 0x00000020 set by do_state
trace May 18 23:02:47 crm_set_bit(185):0: Bit 0x00000080 set by do_state
trace May 18 23:02:47 crm_set_bit(185):0: Bit 0x00000200 set by do_state
trace May 18 23:02:47 crm_timer_stop(225):0: PEngine Recheck Timer (I_PE_CALC:900000ms) already stopped
info May 18 23:02:47 do_state_transition(595):0: Progressed to state S_POLICY_ENGINE after C_TIMER_POPPED
trace May 18 23:02:47 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:47 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
debug May 18 23:02:47 do_state_transition(606):0: All 2 cluster nodes are eligible to run resources.
trace May 18 23:02:47 do_fsa_action(142):0: actions:trace: // A_DC_TIMER_STOP
trace May 18 23:02:47 crm_timer_stop(225):0: Election Trigger (I_DC_TIMEOUT:20000ms) already stopped
trace May 18 23:02:47 do_fsa_action(142):0: actions:trace: // A_INTEGRATE_TIMER_STOP
trace May 18 23:02:47 crm_timer_stop(225):0: Integration Timer (I_INTEGRATED:180000ms) already stopped
trace May 18 23:02:47 do_fsa_action(142):0: actions:trace: // A_FINALIZE_TIMER_STOP
trace May 18 23:02:47 crm_timer_stop(225):0: Finalization Timer (I_ELECTION:1800000ms) already stopped
trace May 18 23:02:47 do_fsa_action(142):0: actions:trace: // A_PE_INVOKE
trace May 18 23:02:47 cib_create_op(609):0: Sending call options: 00000100, 256
trace May 18 23:02:47 cib_native_perform_op_delegate(384):0: Sending cib_query message to CIB service (timeout=120s)
trace May 18 23:02:47 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 5880 bytes: 193 timeout:120000 msg...
trace May 18 23:02:47 crm_ipc_send(1202):0: Message sent, not waiting for reply to 5880 from cib_shm to 193 bytes...
trace May 18 23:02:47 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 18 23:02:47 cib_native_perform_op_delegate(398):0: Async call, returning 2574
debug May 18 23:02:47 do_pe_invoke(233):0: Query 2574: Requesting the current CIB: S_POLICY_ENGINE
trace May 18 23:02:47 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:47 cib_client_register_callback_full(632):0: Adding callback do_pe_invoke_callback for call 2574
trace May 18 23:02:47 delete_fsa_input(236):0: About to free C_TIMER_POPPED data
trace May 18 23:02:47 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:47 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:47 crm_ipc_read(1003):0: Received cib_shm event 13251, size=74832, rc=74832, text: <cib-reply t="cib" cib_op="cib_query" cib_callid="2574" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740c
trace May 18 23:02:47 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 74792 (I/O condition=1)
trace May 18 23:02:47 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:47 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 18 23:02:47 cib_native_callback(649):0: Invoking callback do_pe_invoke_callback for call 2574
trace May 18 23:02:47 pcmk_locate_sbd(231):0: SBD detected at pid=0 (proc)
trace May 18 23:02:47 force_local_option(262):0: Forcing cib-bootstrap-options-have-watchdog/have-watchdog = false
trace May 18 23:02:47 crm_ipc_send(1189):0: Sending from client: pengine request id: 5881 bytes: 74883 timeout:5000 msg...
trace May 18 23:02:47 crm_ipc_send(1202):0: Message sent, not waiting for reply to 5881 from pengine to 74883 bytes...
debug May 18 23:02:47 do_pe_invoke_callback(365):0: Invoking the PE: query=2574, ref=pe_calc-dc-1558213367-1908, seq=1652, quorate=1
trace May 18 23:02:47 cib_native_callback(663):0: Invoking global callback for call 2574
trace May 18 23:02:47 cib_native_callback(666):0: OP callback activated for 2574
trace May 18 23:02:47 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 18 23:02:47 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 18 23:02:47 crm_ipc_read(1003):0: Received pengine event 251, size=5045, rc=5045, text: <create_reply_adv origin="process_pe_message" t="crmd" version="3.0.11" subt="response" reference="p
trace May 18 23:02:47 mainloop_gio_callback(663):0: New message from pengine[0x5626d0a2f9d0] = 5005 (I/O condition=1)
trace May 18 23:02:47 relay_message(375):0: Routing message pe_calc-dc-1558213367-1908
trace May 18 23:02:47 relay_message(431):0: Router result: Message result: DC/CRMd process
trace May 18 23:02:47 register_fsa_input_adv(113):0: handle_response appended FSA input 797 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
trace May 18 23:02:47 register_fsa_input_adv(135):0: Copying C_IPC_MESSAGE data from handle_response as a HA msg
trace May 18 23:02:47 copy_ha_msg_input(214):0: Copy msg
trace May 18 23:02:47 register_fsa_input_adv(164):0: C_IPC_MESSAGE data copied
trace May 18 23:02:47 register_fsa_input_adv(175):0: Queue len: 1
trace May 18 23:02:47 register_fsa_input_adv(184):0: Triggering FSA: register_fsa_input_adv
trace May 18 23:02:47 handle_response(899):0: Completed: pe_calc-dc-1558213367-1908...
trace May 18 23:02:47 crm_ipc_read(1006):0: No message from pengine received: Resource temporarily unavailable
trace May 18 23:02:47 mainloop_gio_callback(658):0: Message acquisition from pengine[0x5626d0a2f9d0] failed: No message of desired type (-42)
trace May 18 23:02:47 crm_fsa_trigger(312):0: Invoked (queue len: 1)
trace May 18 23:02:47 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_POLICY_ENGINE
trace May 18 23:02:47 s_crmd_fsa(175):0: Checking messages (1 remaining)
trace May 18 23:02:47 get_message(275):0: Processing input 797
trace May 18 23:02:47 log_fsa_input(455):0: Processing queued input 797
trace May 18 23:02:47 log_fsa_input(468):0: FSA processing XML message from handle_response
trace May 18 23:02:47 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="250">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <synapse id="0">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="50" operation="stop" operation_key="tunnel-eduroam_stop_0" on_node="bifur1" on_node_uuid="1084762125">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <primitive id="tunnel-eduroam" class="ocf" provider="local" type="tunnel"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <attributes CRM_meta_name="stop" CRM_meta_timeout="300000" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <inputs/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </synapse>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <synapse id="1">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="24" operation="start" operation_key="tunnel-eduroam_start_0" on_node="bifur1" on_node_uuid="1084762125">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <primitive id="tunnel-eduroam" class="ocf" provider="local" type="tunnel"/>
trace May 18 23:02:47 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="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="50" operation="stop" operation_key="tunnel-eduroam_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </synapse>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <synapse id="2">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="21" operation="monitor" operation_key="tunnel-eduroam_monitor_60000" on_node="bifur1" on_node_uuid="1084762125">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <primitive id="tunnel-eduroam" class="ocf" provider="local" type="tunnel"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <attributes CRM_meta_interval="60000" CRM_meta_name="monitor" CRM_meta_timeout="120000" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="24" operation="start" operation_key="tunnel-eduroam_start_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </synapse>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <synapse id="3">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="51" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <primitive id="tunnel-wigner-guest" class="ocf" provider="local" type="tunnel"/>
trace May 18 23:02:47 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="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <inputs/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </synapse>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <synapse id="4">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="25" operation="start" operation_key="tunnel-wigner-guest_start_0" on_node="bifur1" on_node_uuid="1084762125">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <primitive id="tunnel-wigner-guest" class="ocf" provider="local" type="tunnel"/>
trace May 18 23:02:47 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="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="51" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </synapse>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <synapse id="5">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="22" operation="monitor" operation_key="tunnel-wigner-guest_monitor_60000" on_node="bifur1" on_node_uuid="1084762125">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <primitive id="tunnel-wigner-guest" class="ocf" provider="local" type="tunnel"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <attributes CRM_meta_interval="60000" CRM_meta_name="monitor" CRM_meta_timeout="120000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </rsc_op>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="25" operation="start" operation_key="tunnel-wigner-guest_start_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </synapse>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <synapse id="6">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <pseudo_event id="23" operation="all_stopped" operation_key="all_stopped">
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <attributes crm_feature_set="3.0.11"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </pseudo_event>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </action_set>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="50" operation="stop" operation_key="tunnel-eduroam_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data <rsc_op id="51" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </trigger>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </inputs>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </synapse>
trace May 18 23:02:47 log_fsa_input(469):0: FSA message data </transition_graph>
trace May 18 23:02:47 fsa_dump_actions(892):0: Action 0000100000000000 (A_TE_INVOKE) New actions
debug May 18 23:02:47 s_crmd_fsa(197):0: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=handle_response ]
trace May 18 23:02:47 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 18 23:02:47 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 18 23:02:47 crm_set_bit(185):0: Bit 0x00000020 set by do_state
trace May 18 23:02:47 crm_set_bit(185):0: Bit 0x00000080 set by do_state
trace May 18 23:02:47 crm_set_bit(185):0: Bit 0x00000200 set by do_state
trace May 18 23:02:47 crm_timer_stop(225):0: PEngine Recheck Timer (I_PE_CALC:900000ms) already stopped
trace May 18 23:02:47 do_fsa_action(142):0: actions:trace: // A_DC_TIMER_STOP
trace May 18 23:02:47 crm_timer_stop(225):0: Election Trigger (I_DC_TIMEOUT:20000ms) already stopped
trace May 18 23:02:47 do_fsa_action(142):0: actions:trace: // A_INTEGRATE_TIMER_STOP
trace May 18 23:02:47 crm_timer_stop(225):0: Integration Timer (I_INTEGRATED:180000ms) already stopped
trace May 18 23:02:47 do_fsa_action(142):0: actions:trace: // A_FINALIZE_TIMER_STOP
trace May 18 23:02:47 crm_timer_stop(225):0: Finalization Timer (I_ELECTION:1800000ms) already stopped
trace May 18 23:02:47 do_fsa_action(142):0: actions:trace: // A_TE_INVOKE
trace May 18 23:02:47 unpack_synapse(102):0: looking in synapse 0
trace May 18 23:02:47 unpack_synapse(116):0: look for actions in synapse 0
trace May 18 23:02:47 xml2list(4792):0: Unpacking <attributes CRM_meta_name="stop" CRM_meta_timeout="300000" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_name=stop
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 18 23:02:47 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:47 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:47 xml2list(4798):0: Added id=0
trace May 18 23:02:47 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:47 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:47 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:47 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:47 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:47 unpack_action(88):0: Action 50 has timer set to 300000ms
trace May 18 23:02:47 unpack_synapse(132):0: Adding action 50 to synapse 0
trace May 18 23:02:47 unpack_synapse(139):0: look for inputs in synapse 0
trace May 18 23:02:47 unpack_synapse(102):0: looking in synapse 1
trace May 18 23:02:47 unpack_synapse(116):0: look for actions in synapse 1
trace May 18 23:02:47 xml2list(4792):0: Unpacking <attributes CRM_meta_name="start" CRM_meta_timeout="120000" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_name=start
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:47 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:47 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:47 xml2list(4798):0: Added id=0
trace May 18 23:02:47 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:47 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:47 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:47 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:47 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:47 unpack_action(88):0: Action 24 has timer set to 120000ms
trace May 18 23:02:47 unpack_synapse(132):0: Adding action 24 to synapse 1
trace May 18 23:02:47 unpack_synapse(139):0: look for inputs in synapse 1
trace May 18 23:02:47 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 18 23:02:47 xml2list(4788):0: No attributes in rsc_op
trace May 18 23:02:47 xml2list(4789):0: No attributes for resource op <rsc_op id="50" operation="stop" operation_key="tunnel-eduroam_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 18 23:02:47 unpack_action(88):0: Action 50 has timer set to 0ms
trace May 18 23:02:47 unpack_synapse(156):0: Adding input 50 to synapse 1
trace May 18 23:02:47 unpack_synapse(102):0: looking in synapse 2
trace May 18 23:02:47 unpack_synapse(116):0: look for actions in synapse 2
trace May 18 23:02:47 xml2list(4792):0: Unpacking <attributes CRM_meta_interval="60000" CRM_meta_name="monitor" CRM_meta_timeout="120000" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_interval=60000
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:47 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:47 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:47 xml2list(4798):0: Added id=0
trace May 18 23:02:47 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:47 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:47 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:47 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:47 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:47 unpack_action(88):0: Action 21 has timer set to 120000ms
trace May 18 23:02:47 unpack_synapse(132):0: Adding action 21 to synapse 2
trace May 18 23:02:47 unpack_synapse(139):0: look for inputs in synapse 2
trace May 18 23:02:47 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 18 23:02:47 xml2list(4788):0: No attributes in rsc_op
trace May 18 23:02:47 xml2list(4789):0: No attributes for resource op <rsc_op id="24" operation="start" operation_key="tunnel-eduroam_start_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 18 23:02:47 unpack_action(88):0: Action 24 has timer set to 0ms
trace May 18 23:02:47 unpack_synapse(156):0: Adding input 24 to synapse 2
trace May 18 23:02:47 unpack_synapse(102):0: looking in synapse 3
trace May 18 23:02:47 unpack_synapse(116):0: look for actions in synapse 3
trace May 18 23:02:47 xml2list(4792):0: Unpacking <attributes CRM_meta_name="stop" CRM_meta_timeout="300000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_name=stop
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 18 23:02:47 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:47 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:47 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:47 xml2list(4798):0: Added id=1
trace May 18 23:02:47 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:47 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:47 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:47 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:47 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:47 unpack_action(88):0: Action 51 has timer set to 300000ms
trace May 18 23:02:47 unpack_synapse(132):0: Adding action 51 to synapse 3
trace May 18 23:02:47 unpack_synapse(139):0: look for inputs in synapse 3
trace May 18 23:02:47 unpack_synapse(102):0: looking in synapse 4
trace May 18 23:02:47 unpack_synapse(116):0: look for actions in synapse 4
trace May 18 23:02:47 xml2list(4792):0: Unpacking <attributes CRM_meta_name="start" CRM_meta_timeout="120000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_name=start
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:47 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:47 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:47 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:47 xml2list(4798):0: Added id=1
trace May 18 23:02:47 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:47 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:47 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:47 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:47 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:47 unpack_action(88):0: Action 25 has timer set to 120000ms
trace May 18 23:02:47 unpack_synapse(132):0: Adding action 25 to synapse 4
trace May 18 23:02:47 unpack_synapse(139):0: look for inputs in synapse 4
trace May 18 23:02:47 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 18 23:02:47 xml2list(4788):0: No attributes in rsc_op
trace May 18 23:02:47 xml2list(4789):0: No attributes for resource op <rsc_op id="51" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 18 23:02:47 unpack_action(88):0: Action 51 has timer set to 0ms
trace May 18 23:02:47 unpack_synapse(156):0: Adding input 51 to synapse 4
trace May 18 23:02:47 unpack_synapse(102):0: looking in synapse 5
trace May 18 23:02:47 unpack_synapse(116):0: look for actions in synapse 5
trace May 18 23:02:47 xml2list(4792):0: Unpacking <attributes CRM_meta_interval="60000" CRM_meta_name="monitor" CRM_meta_timeout="120000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_interval=60000
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:47 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:47 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:47 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:47 xml2list(4798):0: Added id=1
trace May 18 23:02:47 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:47 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:47 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:47 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:47 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:47 unpack_action(88):0: Action 22 has timer set to 120000ms
trace May 18 23:02:47 unpack_synapse(132):0: Adding action 22 to synapse 5
trace May 18 23:02:47 unpack_synapse(139):0: look for inputs in synapse 5
trace May 18 23:02:47 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 18 23:02:47 xml2list(4788):0: No attributes in rsc_op
trace May 18 23:02:47 xml2list(4789):0: No attributes for resource op <rsc_op id="25" operation="start" operation_key="tunnel-wigner-guest_start_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 18 23:02:47 unpack_action(88):0: Action 25 has timer set to 0ms
trace May 18 23:02:47 unpack_synapse(156):0: Adding input 25 to synapse 5
trace May 18 23:02:47 unpack_synapse(102):0: looking in synapse 6
trace May 18 23:02:47 unpack_synapse(116):0: look for actions in synapse 6
trace May 18 23:02:47 xml2list(4792):0: Unpacking <attributes crm_feature_set="3.0.11"/>
trace May 18 23:02:47 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:47 unpack_action(88):0: Action 23 has timer set to 0ms
trace May 18 23:02:47 unpack_synapse(132):0: Adding action 23 to synapse 6
trace May 18 23:02:47 unpack_synapse(139):0: look for inputs in synapse 6
trace May 18 23:02:47 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 18 23:02:47 xml2list(4788):0: No attributes in rsc_op
trace May 18 23:02:47 xml2list(4789):0: No attributes for resource op <rsc_op id="50" operation="stop" operation_key="tunnel-eduroam_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 18 23:02:47 unpack_action(88):0: Action 50 has timer set to 0ms
trace May 18 23:02:47 unpack_synapse(156):0: Adding input 50 to synapse 6
trace May 18 23:02:47 find_xml_node(2203):0: Could not find attributes in rsc_op.
trace May 18 23:02:47 xml2list(4788):0: No attributes in rsc_op
trace May 18 23:02:47 xml2list(4789):0: No attributes for resource op <rsc_op id="51" operation="stop" operation_key="tunnel-wigner-guest_stop_0" on_node="bifur1" on_node_uuid="1084762125"/>
trace May 18 23:02:47 xml2list(4792):0: Unpacking: No data to dump as XML
trace May 18 23:02:47 unpack_action(88):0: Action 51 has timer set to 0ms
trace May 18 23:02:47 unpack_synapse(156):0: Adding input 51 to synapse 6
debug May 18 23:02:47 unpack_graph(236):0: Unpacked transition 250: 7 actions in 7 synapses
info May 18 23:02:47 do_te_invoke(218):0: Processing graph 250 (ref=pe_calc-dc-1558213367-1908) derived from /var/lib/pacemaker/pengine/pe-input-2364.bz2
trace May 18 23:02:47 trigger_graph_processing(511):0: do_te_invoke:233 - Triggered graph processing
trace May 18 23:02:47 print_graph(237):0: Graph 250 with 7 actions: batch-limit=0 jobs, network-delay=60000ms
trace May 18 23:02:47 print_synapse(190):0: [Action 50]: Pending rsc op tunnel-eduroam_stop_0 on bifur1 (priority: 0, waiting: none)
trace May 18 23:02:47 print_synapse(190):0: [Action 24]: Pending rsc op tunnel-eduroam_start_0 on bifur1 (priority: 0, waiting: 50)
trace May 18 23:02:47 print_synapse(190):0: [Action 21]: Pending rsc op tunnel-eduroam_monitor_60000 on bifur1 (priority: 0, waiting: 24)
trace May 18 23:02:47 print_synapse(190):0: [Action 51]: Pending rsc op tunnel-wigner-guest_stop_0 on bifur1 (priority: 0, waiting: none)
trace May 18 23:02:47 print_synapse(190):0: [Action 25]: Pending rsc op tunnel-wigner-guest_start_0 on bifur1 (priority: 0, waiting: 51)
trace May 18 23:02:47 print_synapse(190):0: [Action 22]: Pending rsc op tunnel-wigner-guest_monitor_60000 on bifur1 (priority: 0, waiting: 25)
trace May 18 23:02:47 print_synapse(190):0: [Action 23]: Pending pseudo op all_stopped on N/A (priority: 0, waiting: 50 51)
trace May 18 23:02:47 delete_fsa_input(236):0: About to free C_IPC_MESSAGE data
trace May 18 23:02:47 delete_fsa_input(262):0: C_IPC_MESSAGE data freed
trace May 18 23:02:47 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:47 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:47 te_graph_trigger(460):0: Invoking graph 250 in state S_TRANSITION_ENGINE
trace May 18 23:02:47 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:47 run_graph(267):0: Entering graph 250 callback
trace May 18 23:02:47 should_fire_synapse(138):0: Checking pre-reqs for synapse 0
trace May 18 23:02:47 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 0 limit= 8 limit
trace May 18 23:02:47 run_graph(300):0: Synapse 0 fired
trace May 18 23:02:47 fire_synapse(223):0: Synapse 0 fired
trace May 18 23:02:47 initiate_action(192):0: Executing rsc-event: 50 (50)
notice May 18 23:02:47 te_rsc_command(436):0: Initiating stop operation tunnel-eduroam_stop_0 locally on bifur1 | action 50
trace May 18 23:02:47 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 18 23:02:47 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 18 23:02:47 get_lrm_resource(1253):0: Retrieving tunnel-eduroam from the LRM.
trace May 18 23:02:47 xml2list(4792):0: Unpacking <attributes CRM_meta_name="stop" CRM_meta_timeout="300000" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_name=stop
trace May 18 23:02:47 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 18 23:02:47 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:47 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:47 xml2list(4798):0: Added id=0
trace May 18 23:02:47 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:47 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:47 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:47 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:47 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:47 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:47 construct_op(1882):0: Constructed stop op for tunnel-eduroam: interval=0
debug May 18 23:02:47 stop_recurring_action_by_rsc(1966):0: Cancelling op 3033 for tunnel-eduroam (tunnel-eduroam:3033)
debug May 18 23:02:48 cancel_op(1178):0: Cancelling op 3033 for tunnel-eduroam (tunnel-eduroam:3033)
trace May 18 23:02:48 lrmd_send_command(818):0: sending lrmd_rsc_cancel op to lrmd
trace May 18 23:02:48 lrmd_create_op(489):0: Sending call options: 00000000, 0
trace May 18 23:02:48 crm_ipc_send(1189):0: Sending from client: lrmd request id: 5882 bytes: 369 timeout:5000 msg...
trace May 18 23:02:48 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 5882
trace May 18 23:02:48 crm_ipc_send(1227):0: Received response 5882, size=110, rc=110, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="0" lrmd_callid="3034"/>
trace May 18 23:02:48 lrmd_send_command(847):0: lrmd_rsc_cancel op reply received
trace May 18 23:02:48 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="0" lrmd_callid="3034"/>
debug May 18 23:02:48 cancel_op(1181):0: Op 3033 for tunnel-eduroam (tunnel-eduroam:3033): cancelled
info May 18 23:02:48 do_lrm_rsc_op(2086):0: Performing key=50:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-eduroam_stop_0
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: iface_in=publ-br0.18
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.1
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: id=0
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: name=eduroam IPv4 tunnel
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: network=e.f.g.h/24
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: src_ip=x.y.z.w
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: dst_ip=a.b.c.d
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: CRM_meta_name=stop
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: CRM_meta_timeout=300000
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.1
trace May 18 23:02:48 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 18 23:02:48 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 18 23:02:48 crm_ipc_send(1189):0: Sending from client: lrmd request id: 5883 bytes: 770 timeout:300000 msg...
trace May 18 23:02:48 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 5883
trace May 18 23:02:48 crm_ipc_send(1227):0: Received response 5883, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3035" lrmd_callid="3035"/>
trace May 18 23:02:48 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 18 23:02:48 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3035" lrmd_callid="3035"/>
trace May 18 23:02:48 do_lrm_rsc_op(2160):0: Recording pending op: 3035 - tunnel-eduroam_stop_0 tunnel-eduroam:3035
trace May 18 23:02:48 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 1
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 50
trace May 18 23:02:48 should_fire_synapse(146):0: Input 50 for synapse 1 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 1 cannot fire
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 24
trace May 18 23:02:48 should_fire_synapse(146):0: Input 24 for synapse 2 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 2 cannot fire
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 3
trace May 18 23:02:48 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 1 limit= 8 limit
trace May 18 23:02:48 run_graph(300):0: Synapse 3 fired
trace May 18 23:02:48 fire_synapse(223):0: Synapse 3 fired
trace May 18 23:02:48 initiate_action(192):0: Executing rsc-event: 51 (51)
notice May 18 23:02:48 te_rsc_command(436):0: Initiating stop operation tunnel-wigner-guest_stop_0 locally on bifur1 | action 51
trace May 18 23:02:48 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 18 23:02:48 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 18 23:02:48 get_lrm_resource(1253):0: Retrieving tunnel-wigner-guest from the LRM.
trace May 18 23:02:48 xml2list(4792):0: Unpacking <attributes CRM_meta_name="stop" CRM_meta_timeout="300000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_name=stop
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 18 23:02:48 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:48 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:48 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:48 xml2list(4798):0: Added id=1
trace May 18 23:02:48 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:48 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:48 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:48 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:48 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:48 construct_op(1882):0: Constructed stop op for tunnel-wigner-guest: interval=0
debug May 18 23:02:48 stop_recurring_action_by_rsc(1966):0: Cancelling op 3032 for tunnel-wigner-guest (tunnel-wigner-guest:3032)
debug May 18 23:02:48 cancel_op(1178):0: Cancelling op 3032 for tunnel-wigner-guest (tunnel-wigner-guest:3032)
trace May 18 23:02:48 lrmd_send_command(818):0: sending lrmd_rsc_cancel op to lrmd
trace May 18 23:02:48 lrmd_create_op(489):0: Sending call options: 00000000, 0
trace May 18 23:02:48 crm_ipc_send(1189):0: Sending from client: lrmd request id: 5884 bytes: 374 timeout:5000 msg...
trace May 18 23:02:48 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 5884
trace May 18 23:02:48 crm_ipc_send(1227):0: Received response 5884, size=110, rc=110, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="0" lrmd_callid="3036"/>
trace May 18 23:02:48 lrmd_send_command(847):0: lrmd_rsc_cancel op reply received
trace May 18 23:02:48 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="0" lrmd_callid="3036"/>
debug May 18 23:02:48 cancel_op(1181):0: Op 3032 for tunnel-wigner-guest (tunnel-wigner-guest:3032): cancelled
info May 18 23:02:48 do_lrm_rsc_op(2086):0: Performing key=51:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-wigner-guest_stop_0
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: iface_in=publ-br0.24
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.3
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: id=1
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: name=Wigner guest IPv4 tunnel
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: network=i.j.k.f/25
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: chain=nfcp-check
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: dst_ip=a.b.c.d
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: src_ip=r.s.t.v
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: CRM_meta_name=stop
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: CRM_meta_timeout=300000
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.3
trace May 18 23:02:48 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 18 23:02:48 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 18 23:02:48 crm_ipc_send(1189):0: Sending from client: lrmd request id: 5885 bytes: 801 timeout:300000 msg...
trace May 18 23:02:48 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 5885
trace May 18 23:02:48 crm_ipc_send(1227):0: Received response 5885, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3037" lrmd_callid="3037"/>
trace May 18 23:02:48 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 18 23:02:48 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3037" lrmd_callid="3037"/>
trace May 18 23:02:48 do_lrm_rsc_op(2160):0: Recording pending op: 3037 - tunnel-wigner-guest_stop_0 tunnel-wigner-guest:3037
trace May 18 23:02:48 te_update_job_count_on(548):0: jobs[bifur1] = 2
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 4
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 51
trace May 18 23:02:48 should_fire_synapse(146):0: Input 51 for synapse 4 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 4 cannot fire
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 5
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 25
trace May 18 23:02:48 should_fire_synapse(146):0: Input 25 for synapse 5 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 5 cannot fire
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 6
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 50
trace May 18 23:02:48 should_fire_synapse(146):0: Input 50 for synapse 6 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 6 cannot fire
debug May 18 23:02:48 run_graph(343):0: Transition 250 (Complete=0, Pending=2, Fired=2, Skipped=0, Incomplete=5, Source=/var/lib/pacemaker/pengine/pe-input-2364.bz2): In-progress
trace May 18 23:02:48 te_graph_trigger(487):0: Transition not yet complete
trace May 18 23:02:48 crm_ipc_read(1003):0: Received lrmd event 2979, size=799, rc=799, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="120000" lrmd_rsc_interval="60000"
trace May 18 23:02:48 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 759 (I/O condition=1)
trace May 18 23:02:48 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.18" CRM_meta_timeout="120000" CRM_meta_interval="60000" id="0" name="eduroam IPv4 tunnel" iface_out="publ-br1" network="e.f.g.h/24" crm_feature_set="3.0.11" dst_ip="a.b.c.d" src_ip="x.y.z.w" CRM_meta_name="monitor" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:48 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_interval=60000
trace May 18 23:02:48 xml2list(4798):0: Added id=0
trace May 18 23:02:48 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:48 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:48 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:48 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:48 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:48 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:48 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 18 23:02:48 process_lrm_event(2403):0: Op tunnel-eduroam_monitor_60000 (call=3033): no delete event required
info May 18 23:02:48 process_lrm_event(2427):0: Result of monitor operation for tunnel-eduroam on bifur1: Cancelled | call=3033 key=tunnel-eduroam_monitor_60000 confirmed=true
debug May 18 23:02:48 update_history_cache(196):0: Updating history for 'tunnel-eduroam' with monitor op
trace May 18 23:02:48 update_history_cache(223):0: Removing cancelled recurring op: tunnel-eduroam_monitor_60000
trace May 18 23:02:48 crm_ipc_read(1003):0: Received lrmd event 2980, size=830, rc=830, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="120000" lrmd_rsc_interval="60000"
trace May 18 23:02:48 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 790 (I/O condition=1)
trace May 18 23:02:48 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.24" CRM_meta_timeout="120000" CRM_meta_interval="60000" id="1" name="Wigner guest IPv4 tunnel" iface_out="publ-br1" network="i.j.k.f/25" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" src_ip="r.s.t.v" CRM_meta_name="monitor" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:48 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_interval=60000
trace May 18 23:02:48 xml2list(4798):0: Added id=1
trace May 18 23:02:48 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:48 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:48 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:48 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:48 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:48 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:48 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:48 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 18 23:02:48 process_lrm_event(2403):0: Op tunnel-wigner-guest_monitor_60000 (call=3032): no delete event required
info May 18 23:02:48 process_lrm_event(2427):0: Result of monitor operation for tunnel-wigner-guest on bifur1: Cancelled | call=3032 key=tunnel-wigner-guest_monitor_60000 confirmed=true
debug May 18 23:02:48 update_history_cache(196):0: Updating history for 'tunnel-wigner-guest' with monitor op
trace May 18 23:02:48 update_history_cache(223):0: Removing cancelled recurring op: tunnel-wigner-guest_monitor_60000
trace May 18 23:02:48 crm_ipc_read(1003):0: Received lrmd event 2981, size=859, rc=859, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="300000" lrmd_rsc_interval="0" lrmd
trace May 18 23:02:48 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 819 (I/O condition=1)
trace May 18 23:02:48 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="e.f.g.h/24" src_ip="x.y.z.w" dst_ip="a.b.c.d" crm_feature_set="3.0.11" CRM_meta_name="stop" tunnel_src_ip="10.10.1.1" CRM_meta_timeout="300000"/>
trace May 18 23:02:48 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:48 xml2list(4798):0: Added id=0
trace May 18 23:02:48 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:48 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:48 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:48 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:48 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:48 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_name=stop
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 18 23:02:48 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 18 23:02:48 build_operation_update(763):0: Building tunnel-eduroam operation update with originator version: 3.0.11
trace May 18 23:02:48 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 18 23:02:48 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 18 23:02:48 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-eduroam after stop op complete (interval=0)
trace May 18 23:02:48 create_operation_update(1775):0: DC version: 3.0.11
trace May 18 23:02:48 find_entity(2226):0: node <lrm_rsc_op id=tunnel-eduroam_last_0> not found in lrm_resource.
trace May 18 23:02:48 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 18 23:02:48 create_operation_update(1870):0: Timing data (tunnel-eduroam_stop_0): last=1558213368 change=0 exec=82 queue=0
trace May 18 23:02:48 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 18 23:02:48 calculate_xml_digest_v1(73):0: Done
trace May 18 23:02:48 crm_md5sum(2102):0: Beginning digest of 203 bytes
trace May 18 23:02:48 crm_md5sum(2110):0: Digest 9a80239c380f1eafa208100c3c658458.
trace May 18 23:02:48 calculate_xml_digest_v1(83):0: digest:source <parameters dst_ip="a.b.c.d" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:48 build_operation_update(771):0: No digests needed for tunnel-eduroam 0x5626d0a22aa0 0x5626d07bfb40 stop
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <status>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-eduroam" type="tunnel" class="ocf" provider="local">
trace May 18 23:02:48 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </lrm>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </node_state>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </status>
trace May 18 23:02:48 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 18 23:02:48 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 18 23:02:48 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 5886 bytes: 1008 timeout:120000 msg...
trace May 18 23:02:48 crm_ipc_send(1202):0: Message sent, not waiting for reply to 5886 from cib_shm to 1008 bytes...
trace May 18 23:02:48 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 18 23:02:48 cib_native_perform_op_delegate(398):0: Async call, returning 2575
trace May 18 23:02:48 do_update_resource(2313):0: Sent resource state update message: 2575 for stop=0 on tunnel-eduroam
trace May 18 23:02:48 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:48 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 2575
trace May 18 23:02:48 process_lrm_event(2413):0: Op tunnel-eduroam_stop_0 (call=3035, stop-id=tunnel-eduroam:3035, remaining=10): Confirmed
notice May 18 23:02:48 process_lrm_event(2438):0: Result of stop operation for tunnel-eduroam on bifur1: 0 (ok) | call=3035 key=tunnel-eduroam_stop_0 confirmed=true cib-update=2575
debug May 18 23:02:48 process_lrm_event(2466):0: bifur1-tunnel-eduroam_stop_0:3035 [ :out-0 - [0:0]\n:in-0 - [0:0]\n:accept-0 - [0:0]\n:drop-0 - [0:0]\n ]
debug May 18 23:02:48 update_history_cache(196):0: Updating history for 'tunnel-eduroam' with stop op
trace May 18 23:02:48 crm_ipc_read(1003):0: Received lrmd event 2982, size=891, rc=891, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="300000" lrmd_rsc_interval="0" lrmd
trace May 18 23:02:48 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 851 (I/O condition=1)
trace May 18 23:02:48 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="i.j.k.f/25" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" src_ip="r.s.t.v" CRM_meta_name="stop" tunnel_src_ip="10.10.1.3" CRM_meta_timeout="300000"/>
trace May 18 23:02:48 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:48 xml2list(4798):0: Added id=1
trace May 18 23:02:48 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:48 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:48 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:48 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:48 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:48 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:48 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_name=stop
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_timeout=300000
trace May 18 23:02:48 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 18 23:02:48 build_operation_update(763):0: Building tunnel-wigner-guest operation update with originator version: 3.0.11
trace May 18 23:02:48 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 18 23:02:48 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 18 23:02:48 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-wigner-guest after stop op complete (interval=0)
trace May 18 23:02:48 create_operation_update(1775):0: DC version: 3.0.11
trace May 18 23:02:48 find_entity(2226):0: node <lrm_rsc_op id=tunnel-wigner-guest_last_0> not found in lrm_resource.
trace May 18 23:02:48 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 18 23:02:48 create_operation_update(1870):0: Timing data (tunnel-wigner-guest_stop_0): last=1558213368 change=0 exec=203 queue=1
trace May 18 23:02:48 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 18 23:02:48 calculate_xml_digest_v1(73):0: Done
trace May 18 23:02:48 crm_md5sum(2102):0: Beginning digest of 229 bytes
trace May 18 23:02:48 crm_md5sum(2110):0: Digest 540db6b587fc94bd9b5bfab7f5cd5685.
trace May 18 23:02:48 calculate_xml_digest_v1(83):0: digest:source <parameters chain="nfcp-check" dst_ip="a.b.c.d" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:48 build_operation_update(771):0: No digests needed for tunnel-wigner-guest 0x5626d0a2a300 0x5626d0ac4fa0 stop
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <status>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-wigner-guest" type="tunnel" class="ocf" provider="local">
trace May 18 23:02:48 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </lrm>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </node_state>
trace May 18 23:02:48 do_update_resource(2286):0: do_update_resource </status>
trace May 18 23:02:48 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 18 23:02:48 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 18 23:02:48 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 5887 bytes: 1024 timeout:120000 msg...
trace May 18 23:02:48 crm_ipc_send(1202):0: Message sent, not waiting for reply to 5887 from cib_shm to 1024 bytes...
trace May 18 23:02:48 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 18 23:02:48 cib_native_perform_op_delegate(398):0: Async call, returning 2576
trace May 18 23:02:48 do_update_resource(2313):0: Sent resource state update message: 2576 for stop=0 on tunnel-wigner-guest
trace May 18 23:02:48 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:48 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 2576
trace May 18 23:02:48 process_lrm_event(2413):0: Op tunnel-wigner-guest_stop_0 (call=3037, stop-id=tunnel-wigner-guest:3037, remaining=9): Confirmed
notice May 18 23:02:48 process_lrm_event(2438):0: Result of stop operation for tunnel-wigner-guest on bifur1: 0 (ok) | call=3037 key=tunnel-wigner-guest_stop_0 confirmed=true cib-update=2576
debug May 18 23:02:48 process_lrm_event(2466):0: bifur1-tunnel-wigner-guest_stop_0:3037 [ :out-1 - [0:0]\n:in-1 - [0:0]\n:accept-1 - [0:0]\n:drop-1 - [0:0]\n ]
debug May 18 23:02:48 update_history_cache(196):0: Updating history for 'tunnel-wigner-guest' with stop op
trace May 18 23:02:48 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 18 23:02:48 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 18 23:02:48 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:48 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:48 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:48 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:48 crm_ipc_read(1003):0: Received cib_shm event 13252, 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 18 23:02:48 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3261 (I/O condition=1)
trace May 18 23:02:48 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:48 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 18 23:02:48 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 18 23:02:48 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 18 23:02:48 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:48 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 18 23:02:48 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 18 23:02:48 xml_patch_versions(1747):0: Got 559 for del[epoch]
trace May 18 23:02:48 xml_patch_versions(1747):0: Got 14 for del[num_updates]
trace May 18 23:02:48 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 18 23:02:48 xml_patch_versions(1758):0: Got 559 for add[epoch]
trace May 18 23:02:48 xml_patch_versions(1758):0: Got 15 for add[num_updates]
debug May 18 23:02:48 te_update_diff(390):0: Processing (cib_modify) diff: 0.559.14 -> 0.559.15 (S_TRANSITION_ENGINE)
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <version>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="559" num_updates="14"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="559" num_updates="15"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </version>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="15"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="559" num_updates="15" admin_epoch="0" cib-last-written="Sat May 18 22:32:41 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:48 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 18 23:02:48 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 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="operation_key" operation="set" value="tunnel-eduroam_stop_0"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="operation" operation="set" value="stop"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="50:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;50:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="3035"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="last-run" operation="set" value="1558213368"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="last-rc-change" operation="set" value="1558213368"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="82"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:48 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </diff>
trace May 18 23:02:48 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 18 23:02:48 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 18 23:02:48 status_from_rc(232):0: Target rc: == 0
trace May 18 23:02:48 stop_te_timer(438):0: Stopping action timer
trace May 18 23:02:48 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 18 23:02:48 update_graph(115):0: Synapse executed
trace May 18 23:02:48 update_synapse_confirmed(76):0: Processing action 50
trace May 18 23:02:48 update_synapse_confirmed(79):0: Confirmed: Action 50 of Synapse 0
trace May 18 23:02:48 update_synapse_confirmed(90):0: Confirmed: Synapse 0
trace May 18 23:02:48 update_synapse_confirmed(96):0: Updated synapse 0
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 50
trace May 18 23:02:48 update_synapse_ready(46):0: Marking input 50 of synapse 1 confirmed
trace May 18 23:02:48 update_synapse_ready(57):0: Updated synapse 1
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 24
trace May 18 23:02:48 update_graph(115):0: Synapse executed
trace May 18 23:02:48 update_synapse_confirmed(76):0: Processing action 51
trace May 18 23:02:48 update_synapse_confirmed(85):0: Synapse 3 still not confirmed after action 50
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 51
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 25
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 50
trace May 18 23:02:48 update_synapse_ready(46):0: Marking input 50 of synapse 6 confirmed
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 51
trace May 18 23:02:48 update_synapse_ready(57):0: Updated synapse 6
trace May 18 23:02:48 update_graph(125):0: Updated graph with completed action 50
trace May 18 23:02:48 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 18 23:02:48 match_graph_event(316):0: Action tunnel-eduroam_stop_0 (50) confirmed on bifur1 (rc=0)
trace May 18 23:02:48 process_graph_event(520):0: Processed update to tunnel-eduroam_stop_0: 50:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 18 23:02:48 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:48 crm_ipc_read(1003):0: Received cib_shm event 13254, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="2575" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 18 23:02:48 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 18 23:02:48 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:48 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 18 23:02:48 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 2575
trace May 18 23:02:48 cib_rsc_callback(2203):0: Resource update 2575 complete: rc=0
trace May 18 23:02:48 cib_native_callback(663):0: Invoking global callback for call 2575
trace May 18 23:02:48 cib_native_callback(666):0: OP callback activated for 2575
trace May 18 23:02:48 crm_ipc_read(1003):0: Received cib_shm event 13255, size=3344, rc=3344, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 18 23:02:48 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3304 (I/O condition=1)
trace May 18 23:02:48 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:48 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 18 23:02:48 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 18 23:02:48 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 18 23:02:48 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:48 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 18 23:02:48 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 18 23:02:48 xml_patch_versions(1747):0: Got 559 for del[epoch]
trace May 18 23:02:48 xml_patch_versions(1747):0: Got 15 for del[num_updates]
trace May 18 23:02:48 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 18 23:02:48 xml_patch_versions(1758):0: Got 559 for add[epoch]
trace May 18 23:02:48 xml_patch_versions(1758):0: Got 16 for add[num_updates]
debug May 18 23:02:48 te_update_diff(390):0: Processing (cib_modify) diff: 0.559.15 -> 0.559.16 (S_TRANSITION_ENGINE)
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <version>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="559" num_updates="15"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="559" num_updates="16"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </version>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="16"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="559" num_updates="16" admin_epoch="0" cib-last-written="Sat May 18 22:32:41 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:48 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 18 23:02:48 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 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="operation_key" operation="set" value="tunnel-wigner-guest_stop_0"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="operation" operation="set" value="stop"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="51:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;51:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="3037"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="last-run" operation="set" value="1558213368"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="last-rc-change" operation="set" value="1558213368"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="203"/>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:48 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:48 te_update_diff(399):0: Patch:Raw </diff>
trace May 18 23:02:48 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 18 23:02:48 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 18 23:02:48 status_from_rc(232):0: Target rc: == 0
trace May 18 23:02:48 stop_te_timer(438):0: Stopping action timer
trace May 18 23:02:48 te_update_job_count_on(548):0: jobs[bifur1] = 0
trace May 18 23:02:48 update_graph(112):0: Synapse complete
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 50
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 24
trace May 18 23:02:48 update_graph(115):0: Synapse executed
trace May 18 23:02:48 update_synapse_confirmed(76):0: Processing action 51
trace May 18 23:02:48 update_synapse_confirmed(79):0: Confirmed: Action 51 of Synapse 3
trace May 18 23:02:48 update_synapse_confirmed(90):0: Confirmed: Synapse 3
trace May 18 23:02:48 update_synapse_confirmed(96):0: Updated synapse 3
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 51
trace May 18 23:02:48 update_synapse_ready(46):0: Marking input 51 of synapse 4 confirmed
trace May 18 23:02:48 update_synapse_ready(57):0: Updated synapse 4
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 25
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 50
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 51
trace May 18 23:02:48 update_synapse_ready(46):0: Marking input 51 of synapse 6 confirmed
trace May 18 23:02:48 update_synapse_ready(57):0: Updated synapse 6
trace May 18 23:02:48 update_graph(125):0: Updated graph with completed action 51
trace May 18 23:02:48 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 18 23:02:48 match_graph_event(316):0: Action tunnel-wigner-guest_stop_0 (51) confirmed on bifur1 (rc=0)
trace May 18 23:02:48 process_graph_event(520):0: Processed update to tunnel-wigner-guest_stop_0: 51:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 18 23:02:48 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:48 crm_ipc_read(1003):0: Received cib_shm event 13257, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="2576" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 18 23:02:48 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 18 23:02:48 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:48 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 18 23:02:48 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 2576
trace May 18 23:02:48 cib_rsc_callback(2203):0: Resource update 2576 complete: rc=0
trace May 18 23:02:48 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 18 23:02:48 cib_native_callback(663):0: Invoking global callback for call 2576
trace May 18 23:02:48 cib_native_callback(666):0: OP callback activated for 2576
trace May 18 23:02:48 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 18 23:02:48 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 18 23:02:48 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:48 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:48 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:48 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:48 te_graph_trigger(460):0: Invoking graph 250 in state S_TRANSITION_ENGINE
trace May 18 23:02:48 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:48 run_graph(267):0: Entering graph 250 callback
trace May 18 23:02:48 run_graph(274):0: Synapse 0 complete
trace May 18 23:02:48 run_graph(274):0: Synapse 3 complete
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 1
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 50
trace May 18 23:02:48 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 0 limit= 8 limit
trace May 18 23:02:48 run_graph(300):0: Synapse 1 fired
trace May 18 23:02:48 fire_synapse(223):0: Synapse 1 fired
trace May 18 23:02:48 initiate_action(192):0: Executing rsc-event: 24 (24)
notice May 18 23:02:48 te_rsc_command(436):0: Initiating start operation tunnel-eduroam_start_0 locally on bifur1 | action 24
trace May 18 23:02:48 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 18 23:02:48 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 18 23:02:48 get_lrm_resource(1253):0: Retrieving tunnel-eduroam from the LRM.
trace May 18 23:02:48 xml2list(4792):0: Unpacking <attributes CRM_meta_name="start" CRM_meta_timeout="120000" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_name=start
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:48 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:48 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:48 xml2list(4798):0: Added id=0
trace May 18 23:02:48 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:48 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:48 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:48 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:48 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:48 construct_op(1882):0: Constructed start op for tunnel-eduroam: interval=0
info May 18 23:02:48 do_lrm_rsc_op(2086):0: Performing key=24:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-eduroam_start_0
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: iface_in=publ-br0.18
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.1
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: id=0
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: name=eduroam IPv4 tunnel
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: network=e.f.g.h/24
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: dst_ip=a.b.c.d
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: src_ip=x.y.z.w
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: CRM_meta_name=start
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: CRM_meta_timeout=120000
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.1
trace May 18 23:02:48 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 18 23:02:48 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 18 23:02:48 crm_ipc_send(1189):0: Sending from client: lrmd request id: 5888 bytes: 772 timeout:120000 msg...
trace May 18 23:02:48 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 5888
trace May 18 23:02:48 crm_ipc_send(1227):0: Received response 5888, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3038" lrmd_callid="3038"/>
trace May 18 23:02:48 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 18 23:02:48 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3038" lrmd_callid="3038"/>
trace May 18 23:02:48 do_lrm_rsc_op(2160):0: Recording pending op: 3038 - tunnel-eduroam_start_0 tunnel-eduroam:3038
trace May 18 23:02:48 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 24
trace May 18 23:02:48 should_fire_synapse(146):0: Input 24 for synapse 2 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 2 cannot fire
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 4
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 51
trace May 18 23:02:48 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 1 limit= 8 limit
trace May 18 23:02:48 run_graph(300):0: Synapse 4 fired
trace May 18 23:02:48 fire_synapse(223):0: Synapse 4 fired
trace May 18 23:02:48 initiate_action(192):0: Executing rsc-event: 25 (25)
notice May 18 23:02:48 te_rsc_command(436):0: Initiating start operation tunnel-wigner-guest_start_0 locally on bifur1 | action 25
trace May 18 23:02:48 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 18 23:02:48 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 18 23:02:48 get_lrm_resource(1253):0: Retrieving tunnel-wigner-guest from the LRM.
trace May 18 23:02:48 xml2list(4792):0: Unpacking <attributes CRM_meta_name="start" CRM_meta_timeout="120000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_name=start
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:48 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:48 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:48 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:48 xml2list(4798):0: Added id=1
trace May 18 23:02:48 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:48 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:48 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:48 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:48 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:48 construct_op(1882):0: Constructed start op for tunnel-wigner-guest: interval=0
info May 18 23:02:48 do_lrm_rsc_op(2086):0: Performing key=25:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-wigner-guest_start_0
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: iface_in=publ-br0.24
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.3
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: id=1
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: name=Wigner guest IPv4 tunnel
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: network=i.j.k.f/25
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: chain=nfcp-check
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: dst_ip=a.b.c.d
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: src_ip=r.s.t.v
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: CRM_meta_name=start
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: CRM_meta_timeout=120000
trace May 18 23:02:48 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.3
trace May 18 23:02:48 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 18 23:02:48 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 18 23:02:48 crm_ipc_send(1189):0: Sending from client: lrmd request id: 5889 bytes: 803 timeout:120000 msg...
trace May 18 23:02:48 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 5889
trace May 18 23:02:48 crm_ipc_send(1227):0: Received response 5889, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3039" lrmd_callid="3039"/>
trace May 18 23:02:48 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 18 23:02:48 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3039" lrmd_callid="3039"/>
trace May 18 23:02:48 do_lrm_rsc_op(2160):0: Recording pending op: 3039 - tunnel-wigner-guest_start_0 tunnel-wigner-guest:3039
trace May 18 23:02:48 te_update_job_count_on(548):0: jobs[bifur1] = 2
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 5
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 25
trace May 18 23:02:48 should_fire_synapse(146):0: Input 25 for synapse 5 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 5 cannot fire
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 6
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 50
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 51
trace May 18 23:02:48 run_graph(300):0: Synapse 6 fired
trace May 18 23:02:48 fire_synapse(223):0: Synapse 6 fired
trace May 18 23:02:48 initiate_action(188):0: Executing pseudo-event: 23 (23)
debug May 18 23:02:48 te_pseudo_action(56):0: Pseudo-action 23 (all_stopped) fired and confirmed
trace May 18 23:02:48 update_graph(112):0: Synapse complete
trace May 18 23:02:48 update_graph(115):0: Synapse executed
trace May 18 23:02:48 update_synapse_confirmed(76):0: Processing action 24
trace May 18 23:02:48 update_synapse_confirmed(85):0: Synapse 1 still not confirmed after action 23
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 24
trace May 18 23:02:48 update_graph(112):0: Synapse complete
trace May 18 23:02:48 update_graph(115):0: Synapse executed
trace May 18 23:02:48 update_synapse_confirmed(76):0: Processing action 25
trace May 18 23:02:48 update_synapse_confirmed(85):0: Synapse 4 still not confirmed after action 23
trace May 18 23:02:48 update_synapse_ready(43):0: Processing input 25
trace May 18 23:02:48 update_graph(115):0: Synapse executed
trace May 18 23:02:48 update_synapse_confirmed(76):0: Processing action 23
trace May 18 23:02:48 update_synapse_confirmed(79):0: Confirmed: Action 23 of Synapse 6
trace May 18 23:02:48 update_synapse_confirmed(90):0: Confirmed: Synapse 6
trace May 18 23:02:48 update_synapse_confirmed(96):0: Updated synapse 6
trace May 18 23:02:48 update_graph(125):0: Updated graph with completed action 23
trace May 18 23:02:48 trigger_graph_processing(511):0: te_pseudo_action:59 - Triggered graph processing
debug May 18 23:02:48 run_graph(343):0: Transition 250 (Complete=2, Pending=2, Fired=3, Skipped=0, Incomplete=2, Source=/var/lib/pacemaker/pengine/pe-input-2364.bz2): In-progress
trace May 18 23:02:48 te_graph_trigger(487):0: Transition not yet complete
trace May 18 23:02:48 te_graph_trigger(460):0: Invoking graph 250 in state S_TRANSITION_ENGINE
trace May 18 23:02:48 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:48 run_graph(267):0: Entering graph 250 callback
trace May 18 23:02:48 run_graph(274):0: Synapse 0 complete
trace May 18 23:02:48 run_graph(278):0: Synapse 1: confirmation pending
trace May 18 23:02:48 run_graph(274):0: Synapse 3 complete
trace May 18 23:02:48 run_graph(278):0: Synapse 4: confirmation pending
trace May 18 23:02:48 run_graph(274):0: Synapse 6 complete
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 24
trace May 18 23:02:48 should_fire_synapse(146):0: Input 24 for synapse 2 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 2 cannot fire
trace May 18 23:02:48 should_fire_synapse(138):0: Checking pre-reqs for synapse 5
trace May 18 23:02:48 should_fire_synapse(144):0: Processing input 25
trace May 18 23:02:48 should_fire_synapse(146):0: Input 25 for synapse 5 not satisfied: not confirmed
trace May 18 23:02:48 run_graph(315):0: Synapse 5 cannot fire
debug May 18 23:02:48 run_graph(343):0: Transition 250 (Complete=3, Pending=2, Fired=0, Skipped=0, Incomplete=2, Source=/var/lib/pacemaker/pengine/pe-input-2364.bz2): In-progress
trace May 18 23:02:48 te_graph_trigger(491):0: Transition not yet complete - no actions fired
trace May 18 23:02:48 crm_ipc_read(1003):0: Received lrmd event 2983, size=862, rc=862, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="120000" lrmd_rsc_interval="0" lrmd
trace May 18 23:02:48 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 822 (I/O condition=1)
trace May 18 23:02:48 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="e.f.g.h/24" dst_ip="a.b.c.d" crm_feature_set="3.0.11" src_ip="x.y.z.w" CRM_meta_name="start" tunnel_src_ip="10.10.1.1" CRM_meta_timeout="120000"/>
trace May 18 23:02:48 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:48 xml2list(4798):0: Added id=0
trace May 18 23:02:48 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:48 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:48 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:48 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:48 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:48 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_name=start
trace May 18 23:02:48 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:48 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:48 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 18 23:02:48 build_operation_update(763):0: Building tunnel-eduroam operation update with originator version: 3.0.11
trace May 18 23:02:48 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 18 23:02:48 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 18 23:02:48 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-eduroam after start op complete (interval=0)
trace May 18 23:02:49 create_operation_update(1775):0: DC version: 3.0.11
trace May 18 23:02:49 find_entity(2226):0: node <lrm_rsc_op id=tunnel-eduroam_last_0> not found in lrm_resource.
trace May 18 23:02:49 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 18 23:02:49 create_operation_update(1870):0: Timing data (tunnel-eduroam_start_0): last=1558213368 change=0 exec=311 queue=0
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 203 bytes
trace May 18 23:02:49 crm_md5sum(2110):0: Digest 9a80239c380f1eafa208100c3c658458.
trace May 18 23:02:49 calculate_xml_digest_v1(83):0: digest:source <parameters dst_ip="a.b.c.d" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:49 action_synced_wait(492):0: Waiting for 37897
trace May 18 23:02:49 svc_read_output(81):0: Reading tunnel_meta-data_0 stdout into offset 0
trace May 18 23:02:49 svc_read_output(87):0: Got 499 chars: <?xml version="1.0"?>
<!DOCTYPE resource-agent SYSTEM "ra-api-1.dtd">
<resource-
trace May 18 23:02:49 svc_read_output(87):0: Got 499 chars: <parameter name="id" unique="1" required="1">
<longdesc lang="en">
Unique identi
trace May 18 23:02:49 svc_read_output(87):0: Got 499 chars: ongdesc lang="en">
Destination IP address for the tunnel packets.
</longdesc>
<s
trace May 18 23:02:49 svc_read_output(87):0: Got 499 chars: esc lang="en">
The destination address in the tunnel packets.
</longdesc>
<short
trace May 18 23:02:49 svc_read_output(87):0: Got 499 chars: he interface name of the tunnel.
</longdesc>
<shortdesc lang="en">Outgoing tunne
trace May 18 23:02:49 svc_read_output(87):0: Got 477 chars: <shortdesc lang="en">Optional iptables chain</shortdesc>
<content type="string"
trace May 18 23:02:49 action_synced_wait(548):0: Child done: 37897
info May 18 23:02:49 action_synced_wait(575):0: Managed tunnel_meta-data_0 process 37897 exited with rc=0
trace May 18 23:02:49 svc_read_output(78):0: Reading tunnel_meta-data_0 stdout into offset 2972
trace May 18 23:02:49 svc_read_output(81):0: Reading tunnel_meta-data_0 stderr into offset 0
trace May 18 23:02:49 services_action_sync(713):0: > tunnel_meta-data_0: /usr/lib/ocf/resource.d/local/tunnel = 0
trace May 18 23:02:49 services_action_sync(715):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:49 get_rsc_metadata(539):0: Retrieved live metadata for ocf::local:tunnel
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 build_parameter_list(621):0: Rejecting tunnel_src_ip for unique
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting tunnel_dst_ip for unique
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting network for unique
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting iface_out for unique
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting iface_in for unique
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting chain 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.
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
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting src_ip for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr src_ip=x.y.z.w to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr dst_ip=a.b.c.d to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.1 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.1 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting network for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting network match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr network=e.f.g.h/24 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting iface_out for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting iface_in for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr iface_in=publ-br0.18 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting chain for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting chain match for private xml
trace May 18 23:02:49 append_secure_list(726):0: tunnel-eduroam: no secure parameters
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <status>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-eduroam" type="tunnel" class="ocf" provider="local">
trace May 18 23:02:49 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </lrm>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </node_state>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </status>
trace May 18 23:02:49 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 18 23:02:49 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 18 23:02:49 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 5890 bytes: 1088 timeout:120000 msg...
trace May 18 23:02:49 crm_ipc_send(1202):0: Message sent, not waiting for reply to 5890 from cib_shm to 1088 bytes...
trace May 18 23:02:49 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 18 23:02:49 cib_native_perform_op_delegate(398):0: Async call, returning 2577
trace May 18 23:02:49 do_update_resource(2313):0: Sent resource state update message: 2577 for start=0 on tunnel-eduroam
trace May 18 23:02:49 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:49 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 2577
trace May 18 23:02:49 process_lrm_event(2413):0: Op tunnel-eduroam_start_0 (call=3038, stop-id=tunnel-eduroam:3038, remaining=10): Confirmed
notice May 18 23:02:49 process_lrm_event(2438):0: Result of start operation for tunnel-eduroam on bifur1: 0 (ok) | call=3038 key=tunnel-eduroam_start_0 confirmed=true cib-update=2577
debug May 18 23:02:49 process_lrm_event(2466):0: bifur1-tunnel-eduroam_start_0:3038 [ :accept-0 - [0:0]\n:drop-0 - [0:0]\n:out-0 - [0:0]\n:in-0 - [0:0]\n ]
debug May 18 23:02:49 update_history_cache(196):0: Updating history for 'tunnel-eduroam' with start op
trace May 18 23:02:49 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 18 23:02:49 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 18 23:02:49 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:49 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:49 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:49 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:49 crm_ipc_read(1003):0: Received cib_shm event 13258, size=3251, rc=3251, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 18 23:02:49 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3211 (I/O condition=1)
trace May 18 23:02:49 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:49 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 18 23:02:49 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 18 23:02:49 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 18 23:02:49 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:49 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 18 23:02:49 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 18 23:02:49 xml_patch_versions(1747):0: Got 559 for del[epoch]
trace May 18 23:02:49 xml_patch_versions(1747):0: Got 16 for del[num_updates]
trace May 18 23:02:49 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 18 23:02:49 xml_patch_versions(1758):0: Got 559 for add[epoch]
trace May 18 23:02:49 xml_patch_versions(1758):0: Got 17 for add[num_updates]
debug May 18 23:02:49 te_update_diff(390):0: Processing (cib_modify) diff: 0.559.16 -> 0.559.17 (S_TRANSITION_ENGINE)
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <version>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="559" num_updates="16"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="559" num_updates="17"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </version>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="17"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="559" num_updates="17" admin_epoch="0" cib-last-written="Sat May 18 22:32:41 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:49 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 18 23:02:49 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 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="operation_key" operation="set" value="tunnel-eduroam_start_0"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="operation" operation="set" value="start"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="24:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;24:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="3038"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="311"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:49 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </diff>
trace May 18 23:02:49 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 18 23:02:49 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 18 23:02:49 status_from_rc(232):0: Target rc: == 0
trace May 18 23:02:49 stop_te_timer(438):0: Stopping action timer
trace May 18 23:02:49 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 18 23:02:49 update_graph(112):0: Synapse complete
trace May 18 23:02:49 update_graph(115):0: Synapse executed
trace May 18 23:02:49 update_synapse_confirmed(76):0: Processing action 24
trace May 18 23:02:49 update_synapse_confirmed(79):0: Confirmed: Action 24 of Synapse 1
trace May 18 23:02:49 update_synapse_confirmed(90):0: Confirmed: Synapse 1
trace May 18 23:02:49 update_synapse_confirmed(96):0: Updated synapse 1
trace May 18 23:02:49 update_synapse_ready(43):0: Processing input 24
trace May 18 23:02:49 update_synapse_ready(46):0: Marking input 24 of synapse 2 confirmed
trace May 18 23:02:49 update_synapse_ready(57):0: Updated synapse 2
trace May 18 23:02:49 update_graph(112):0: Synapse complete
trace May 18 23:02:49 update_graph(115):0: Synapse executed
trace May 18 23:02:49 update_synapse_confirmed(76):0: Processing action 25
trace May 18 23:02:49 update_synapse_confirmed(85):0: Synapse 4 still not confirmed after action 24
trace May 18 23:02:49 update_synapse_ready(43):0: Processing input 25
trace May 18 23:02:49 update_graph(112):0: Synapse complete
trace May 18 23:02:49 update_graph(125):0: Updated graph with completed action 24
trace May 18 23:02:49 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 18 23:02:49 match_graph_event(316):0: Action tunnel-eduroam_start_0 (24) confirmed on bifur1 (rc=0)
trace May 18 23:02:49 process_graph_event(520):0: Processed update to tunnel-eduroam_start_0: 24:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 18 23:02:49 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:49 crm_ipc_read(1003):0: Received cib_shm event 13260, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="2577" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 18 23:02:49 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 18 23:02:49 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:49 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 18 23:02:49 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 2577
trace May 18 23:02:49 cib_rsc_callback(2203):0: Resource update 2577 complete: rc=0
trace May 18 23:02:49 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 18 23:02:49 cib_native_callback(663):0: Invoking global callback for call 2577
trace May 18 23:02:49 cib_native_callback(666):0: OP callback activated for 2577
trace May 18 23:02:49 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 18 23:02:49 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 18 23:02:49 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:49 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:49 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:49 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:49 te_graph_trigger(460):0: Invoking graph 250 in state S_TRANSITION_ENGINE
trace May 18 23:02:49 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:49 run_graph(267):0: Entering graph 250 callback
trace May 18 23:02:49 run_graph(274):0: Synapse 0 complete
trace May 18 23:02:49 run_graph(274):0: Synapse 1 complete
trace May 18 23:02:49 run_graph(274):0: Synapse 3 complete
trace May 18 23:02:49 run_graph(278):0: Synapse 4: confirmation pending
trace May 18 23:02:49 run_graph(274):0: Synapse 6 complete
trace May 18 23:02:49 should_fire_synapse(138):0: Checking pre-reqs for synapse 2
trace May 18 23:02:49 should_fire_synapse(144):0: Processing input 24
trace May 18 23:02:49 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 1 limit= 8 limit
trace May 18 23:02:49 run_graph(300):0: Synapse 2 fired
trace May 18 23:02:49 fire_synapse(223):0: Synapse 2 fired
trace May 18 23:02:49 initiate_action(192):0: Executing rsc-event: 21 (21)
notice May 18 23:02:49 te_rsc_command(436):0: Initiating monitor operation tunnel-eduroam_monitor_60000 locally on bifur1 | action 21
trace May 18 23:02:49 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 18 23:02:49 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 18 23:02:49 get_lrm_resource(1253):0: Retrieving tunnel-eduroam from the LRM.
trace May 18 23:02:49 xml2list(4792):0: Unpacking <attributes CRM_meta_interval="60000" CRM_meta_name="monitor" CRM_meta_timeout="120000" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="0" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:49 xml2list(4798):0: Added CRM_meta_interval=60000
trace May 18 23:02:49 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 18 23:02:49 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:49 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:49 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:49 xml2list(4798):0: Added id=0
trace May 18 23:02:49 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:49 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:49 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:49 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:49 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:49 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:49 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:49 construct_op(1882):0: Constructed monitor op for tunnel-eduroam: interval=60000
info May 18 23:02:49 do_lrm_rsc_op(2086):0: Performing key=21:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-eduroam_monitor_60000
trace May 18 23:02:49 cancel_op_key(1239):0: Removed 0 op cache entries, new size: 10
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: iface_in=publ-br0.18
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.1
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.1
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: id=0
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: name=eduroam IPv4 tunnel
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: network=e.f.g.h/24
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: dst_ip=a.b.c.d
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: src_ip=x.y.z.w
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: CRM_meta_name=monitor
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: CRM_meta_timeout=120000
trace May 18 23:02:49 hash2smartfield(4734):0: dumped: CRM_meta_interval=60000
trace May 18 23:02:49 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 18 23:02:49 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 18 23:02:49 crm_ipc_send(1189):0: Sending from client: lrmd request id: 5891 bytes: 806 timeout:120000 msg...
trace May 18 23:02:49 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 5891
trace May 18 23:02:49 crm_ipc_send(1227):0: Received response 5891, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3040" lrmd_callid="3040"/>
trace May 18 23:02:49 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 18 23:02:49 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3040" lrmd_callid="3040"/>
trace May 18 23:02:49 do_lrm_rsc_op(2160):0: Recording pending op: 3040 - tunnel-eduroam_monitor_60000 tunnel-eduroam:3040
trace May 18 23:02:49 te_update_job_count_on(548):0: jobs[bifur1] = 2
trace May 18 23:02:49 should_fire_synapse(138):0: Checking pre-reqs for synapse 5
trace May 18 23:02:49 should_fire_synapse(144):0: Processing input 25
trace May 18 23:02:49 should_fire_synapse(146):0: Input 25 for synapse 5 not satisfied: not confirmed
trace May 18 23:02:49 run_graph(315):0: Synapse 5 cannot fire
debug May 18 23:02:49 run_graph(343):0: Transition 250 (Complete=4, Pending=2, Fired=1, Skipped=0, Incomplete=1, Source=/var/lib/pacemaker/pengine/pe-input-2364.bz2): In-progress
trace May 18 23:02:49 te_graph_trigger(487):0: Transition not yet complete
trace May 18 23:02:49 crm_ipc_read(1003):0: Received lrmd event 2984, size=809, rc=809, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="120000" lrmd_rsc_interval="60000"
trace May 18 23:02:49 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 769 (I/O condition=1)
trace May 18 23:02:49 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.18" CRM_meta_timeout="120000" CRM_meta_interval="60000" id="0" name="eduroam IPv4 tunnel" iface_out="publ-br1" network="e.f.g.h/24" crm_feature_set="3.0.11" dst_ip="a.b.c.d" src_ip="x.y.z.w" CRM_meta_name="monitor" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:49 xml2list(4798):0: Added iface_in=publ-br0.18
trace May 18 23:02:49 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:49 xml2list(4798):0: Added CRM_meta_interval=60000
trace May 18 23:02:49 xml2list(4798):0: Added id=0
trace May 18 23:02:49 xml2list(4798):0: Added name=eduroam IPv4 tunnel
trace May 18 23:02:49 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:49 xml2list(4798):0: Added network=e.f.g.h/24
trace May 18 23:02:49 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:49 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:49 xml2list(4798):0: Added src_ip=x.y.z.w
trace May 18 23:02:49 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 18 23:02:49 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.1
trace May 18 23:02:49 xml2list(4798):0: Added tunnel_src_ip=10.10.1.1
trace May 18 23:02:49 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 18 23:02:49 build_operation_update(763):0: Building tunnel-eduroam operation update with originator version: 3.0.11
trace May 18 23:02:49 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 18 23:02:49 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 18 23:02:49 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-eduroam after monitor op complete (interval=60000)
trace May 18 23:02:49 create_operation_update(1775):0: DC version: 3.0.11
trace May 18 23:02:49 find_entity(2226):0: node <lrm_rsc_op id=tunnel-eduroam_monitor_60000> not found in lrm_resource.
trace May 18 23:02:49 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 18 23:02:49 create_operation_update(1870):0: Timing data (tunnel-eduroam_monitor_60000): last=1558213369 change=0 exec=43 queue=1
trace May 18 23:02:49 compare_version(536):0: 3.0.11 > 1.0.8 (1)
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 229 bytes
trace May 18 23:02:49 crm_md5sum(2110):0: Digest cb568c922bdf57b1b02d2b1300200434.
trace May 18 23:02:49 calculate_xml_digest_v1(83):0: digest:source <parameters CRM_meta_timeout="120000" dst_ip="a.b.c.d" iface_in="publ-br0.18" iface_out="publ-br1" name="eduroam IPv4 tunnel" network="e.f.g.h/24" src_ip="x.y.z.w" tunnel_dst_ip="10.10.0.1" tunnel_src_ip="10.10.1.1"/>
trace May 18 23:02:49 get_rsc_metadata(532):0: Retrieved cached metadata for ocf::local:tunnel
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 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
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting src_ip for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr src_ip=x.y.z.w to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr dst_ip=a.b.c.d to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.1 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.1 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting network for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting network match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr network=e.f.g.h/24 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting iface_out for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting iface_in for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 18 23:02:49 build_parameter_list(632):0: Adding attr iface_in=publ-br0.18 to the xml result
trace May 18 23:02:49 build_parameter_list(621):0: Rejecting chain for private
trace May 18 23:02:49 build_parameter_list(625):0: Inverting chain match for private xml
trace May 18 23:02:49 append_secure_list(726):0: tunnel-eduroam: no secure parameters
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <status>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-eduroam" type="tunnel" class="ocf" provider="local">
trace May 18 23:02:49 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </lrm>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </node_state>
trace May 18 23:02:49 do_update_resource(2286):0: do_update_resource </status>
trace May 18 23:02:49 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 18 23:02:49 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 18 23:02:49 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 5892 bytes: 1007 timeout:120000 msg...
trace May 18 23:02:49 crm_ipc_send(1202):0: Message sent, not waiting for reply to 5892 from cib_shm to 1007 bytes...
trace May 18 23:02:49 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 18 23:02:49 cib_native_perform_op_delegate(398):0: Async call, returning 2578
trace May 18 23:02:49 do_update_resource(2313):0: Sent resource state update message: 2578 for monitor=60000 on tunnel-eduroam
trace May 18 23:02:49 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:49 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 2578
info May 18 23:02:49 process_lrm_event(2438):0: Result of monitor operation for tunnel-eduroam on bifur1: 0 (ok) | call=3040 key=tunnel-eduroam_monitor_60000 confirmed=false cib-update=2578
debug May 18 23:02:49 update_history_cache(196):0: Updating history for 'tunnel-eduroam' with monitor op
trace May 18 23:02:49 update_history_cache(266):0: Adding recurring op: tunnel-eduroam_monitor_60000
trace May 18 23:02:49 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 18 23:02:49 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 18 23:02:49 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:49 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:49 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:49 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:49 crm_ipc_read(1003):0: Received cib_shm event 13261, size=3081, rc=3081, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 18 23:02:49 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3041 (I/O condition=1)
trace May 18 23:02:49 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:49 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 18 23:02:49 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 18 23:02:49 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 18 23:02:49 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:49 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 18 23:02:49 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 18 23:02:49 xml_patch_versions(1747):0: Got 559 for del[epoch]
trace May 18 23:02:49 xml_patch_versions(1747):0: Got 17 for del[num_updates]
trace May 18 23:02:49 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 18 23:02:49 xml_patch_versions(1758):0: Got 559 for add[epoch]
trace May 18 23:02:49 xml_patch_versions(1758):0: Got 18 for add[num_updates]
debug May 18 23:02:49 te_update_diff(390):0: Processing (cib_modify) diff: 0.559.17 -> 0.559.18 (S_TRANSITION_ENGINE)
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <version>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="559" num_updates="17"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="559" num_updates="18"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </version>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="18"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="559" num_updates="18" admin_epoch="0" cib-last-written="Sat May 18 22:32:41 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:49 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_monitor_60000']'
trace May 18 23:02:49 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_monitor_60000']">
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="21:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;21:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="3040"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="last-rc-change" operation="set" value="1558213369"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="43"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-attr name="queue-time" operation="set" value="1"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw <lrm_rsc_op id="tunnel-eduroam_monitor_60000" operation_key="tunnel-eduroam_monitor_60000" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.11" transition-key="21:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32" transition-magic="0:0;21:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32" on_node="bifur1" call-id="3040" rc-code="0" op-status="0" interval="60000" last-rc-change="1558213369" exec-time="43" queue-time="1" op-digest="cb568c922bdf57b1b02d2b1300200434"/>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:49 te_update_diff(399):0: Patch:Raw </diff>
trace May 18 23:02:49 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 18 23:02:49 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_monitor_60000'] matched by lrm_rsc_op
trace May 18 23:02:49 status_from_rc(232):0: Target rc: == 0
trace May 18 23:02:49 stop_te_timer(438):0: Stopping action timer
trace May 18 23:02:49 te_update_job_count_on(548):0: jobs[bifur1] = 1
trace May 18 23:02:49 update_graph(112):0: Synapse complete
trace May 18 23:02:49 update_graph(112):0: Synapse complete
trace May 18 23:02:49 update_graph(115):0: Synapse executed
trace May 18 23:02:49 update_synapse_confirmed(76):0: Processing action 21
trace May 18 23:02:49 update_synapse_confirmed(79):0: Confirmed: Action 21 of Synapse 2
trace May 18 23:02:49 update_synapse_confirmed(90):0: Confirmed: Synapse 2
trace May 18 23:02:49 update_synapse_confirmed(96):0: Updated synapse 2
trace May 18 23:02:49 update_graph(112):0: Synapse complete
trace May 18 23:02:49 update_graph(115):0: Synapse executed
trace May 18 23:02:49 update_synapse_confirmed(76):0: Processing action 25
trace May 18 23:02:49 update_synapse_confirmed(85):0: Synapse 4 still not confirmed after action 21
trace May 18 23:02:49 update_synapse_ready(43):0: Processing input 25
trace May 18 23:02:49 update_graph(112):0: Synapse complete
trace May 18 23:02:49 update_graph(125):0: Updated graph with completed action 21
trace May 18 23:02:49 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 18 23:02:49 match_graph_event(316):0: Action tunnel-eduroam_monitor_60000 (21) confirmed on bifur1 (rc=0)
trace May 18 23:02:49 process_graph_event(520):0: Processed update to tunnel-eduroam_monitor_60000: 21:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 18 23:02:49 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:49 crm_ipc_read(1003):0: Received cib_shm event 13263, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="2578" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 18 23:02:49 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 18 23:02:49 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:49 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 18 23:02:49 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 2578
trace May 18 23:02:49 cib_rsc_callback(2203):0: Resource update 2578 complete: rc=0
trace May 18 23:02:49 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 18 23:02:49 cib_native_callback(663):0: Invoking global callback for call 2578
trace May 18 23:02:49 cib_native_callback(666):0: OP callback activated for 2578
trace May 18 23:02:49 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 18 23:02:49 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 18 23:02:49 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:49 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:49 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:49 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:49 te_graph_trigger(460):0: Invoking graph 250 in state S_TRANSITION_ENGINE
trace May 18 23:02:49 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:49 run_graph(267):0: Entering graph 250 callback
trace May 18 23:02:49 run_graph(274):0: Synapse 0 complete
trace May 18 23:02:49 run_graph(274):0: Synapse 1 complete
trace May 18 23:02:49 run_graph(274):0: Synapse 2 complete
trace May 18 23:02:49 run_graph(274):0: Synapse 3 complete
trace May 18 23:02:49 run_graph(278):0: Synapse 4: confirmation pending
trace May 18 23:02:49 run_graph(274):0: Synapse 6 complete
trace May 18 23:02:49 should_fire_synapse(138):0: Checking pre-reqs for synapse 5
trace May 18 23:02:49 should_fire_synapse(144):0: Processing input 25
trace May 18 23:02:49 should_fire_synapse(146):0: Input 25 for synapse 5 not satisfied: not confirmed
trace May 18 23:02:49 run_graph(315):0: Synapse 5 cannot fire
debug May 18 23:02:49 run_graph(343):0: Transition 250 (Complete=5, Pending=1, Fired=0, Skipped=0, Incomplete=1, Source=/var/lib/pacemaker/pengine/pe-input-2364.bz2): In-progress
trace May 18 23:02:49 te_graph_trigger(491):0: Transition not yet complete - no actions fired
trace May 18 23:02:49 crm_ipc_read(1003):0: Received lrmd event 2985, size=894, rc=894, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="120000" lrmd_rsc_interval="0" lrmd
trace May 18 23:02:49 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 854 (I/O condition=1)
trace May 18 23:02:49 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="i.j.k.f/25" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" src_ip="r.s.t.v" CRM_meta_name="start" tunnel_src_ip="10.10.1.3" CRM_meta_timeout="120000"/>
trace May 18 23:02:49 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:49 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:49 xml2list(4798):0: Added id=1
trace May 18 23:02:49 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:49 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:49 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:49 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:49 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:49 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:49 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:49 xml2list(4798):0: Added CRM_meta_name=start
trace May 18 23:02:49 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:49 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:49 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 18 23:02:49 build_operation_update(763):0: Building tunnel-wigner-guest operation update with originator version: 3.0.11
trace May 18 23:02:49 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 18 23:02:49 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 18 23:02:49 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-wigner-guest after start op complete (interval=0)
trace May 18 23:02:50 create_operation_update(1775):0: DC version: 3.0.11
trace May 18 23:02:50 find_entity(2226):0: node <lrm_rsc_op id=tunnel-wigner-guest_last_0> not found in lrm_resource.
trace May 18 23:02:50 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 18 23:02:50 create_operation_update(1870):0: Timing data (tunnel-wigner-guest_start_0): last=1558213368 change=0 exec=1245 queue=0
trace May 18 23:02:50 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 18 23:02:50 calculate_xml_digest_v1(73):0: Done
trace May 18 23:02:50 crm_md5sum(2102):0: Beginning digest of 229 bytes
trace May 18 23:02:50 crm_md5sum(2110):0: Digest 540db6b587fc94bd9b5bfab7f5cd5685.
trace May 18 23:02:50 calculate_xml_digest_v1(83):0: digest:source <parameters chain="nfcp-check" dst_ip="a.b.c.d" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:50 action_synced_wait(492):0: Waiting for 38056
trace May 18 23:02:50 svc_read_output(81):0: Reading tunnel_meta-data_0 stdout into offset 0
trace May 18 23:02:50 svc_read_output(87):0: Got 499 chars: <?xml version="1.0"?>
<!DOCTYPE resource-agent SYSTEM "ra-api-1.dtd">
<resource-
trace May 18 23:02:50 svc_read_output(87):0: Got 499 chars: <parameter name="id" unique="1" required="1">
<longdesc lang="en">
Unique identi
trace May 18 23:02:50 svc_read_output(87):0: Got 499 chars: ongdesc lang="en">
Destination IP address for the tunnel packets.
</longdesc>
<s
trace May 18 23:02:50 svc_read_output(87):0: Got 499 chars: esc lang="en">
The destination address in the tunnel packets.
</longdesc>
<short
trace May 18 23:02:50 svc_read_output(87):0: Got 499 chars: he interface name of the tunnel.
</longdesc>
<shortdesc lang="en">Outgoing tunne
trace May 18 23:02:50 svc_read_output(87):0: Got 477 chars: <shortdesc lang="en">Optional iptables chain</shortdesc>
<content type="string"
trace May 18 23:02:50 action_synced_wait(548):0: Child done: 38056
info May 18 23:02:50 action_synced_wait(575):0: Managed tunnel_meta-data_0 process 38056 exited with rc=0
trace May 18 23:02:50 svc_read_output(78):0: Reading tunnel_meta-data_0 stdout into offset 2972
trace May 18 23:02:50 svc_read_output(81):0: Reading tunnel_meta-data_0 stderr into offset 0
trace May 18 23:02:50 services_action_sync(713):0: > tunnel_meta-data_0: /usr/lib/ocf/resource.d/local/tunnel = 0
trace May 18 23:02:50 services_action_sync(715):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:50 get_rsc_metadata(539):0: Retrieved live metadata for ocf::local:tunnel
trace May 18 23:02:50 build_operation_update(787):0: Including additional digests for ocf::local:tunnel
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting name for unique
trace May 18 23:02:50 build_parameter_list(614):0: Attr id is unique
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr id=1 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting src_ip for unique
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting dst_ip for unique
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting tunnel_src_ip for unique
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting tunnel_dst_ip for unique
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting network for unique
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting iface_out for unique
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting iface_in for unique
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting chain for unique
trace May 18 23:02:50 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 18 23:02:50 calculate_xml_digest_v1(73):0: Done
trace May 18 23:02:50 crm_md5sum(2102):0: Beginning digest of 22 bytes
trace May 18 23:02:50 crm_md5sum(2110):0: Digest 1183e7ea1505ead635f6de4dfacd0030.
trace May 18 23:02:50 calculate_xml_digest_v1(83):0: digest:source <parameters id="1"/>
trace May 18 23:02:50 append_restart_list(693):0: tunnel-wigner-guest: 1183e7ea1505ead635f6de4dfacd0030, id
trace May 18 23:02:50 append_restart_list(694):0: restart digest source <parameters id="1"/>
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting name for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting name match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr name=Wigner guest IPv4 tunnel to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting id for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting id match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr id=1 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting src_ip for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr src_ip=r.s.t.v to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr dst_ip=a.b.c.d to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.3 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.3 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting network for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting network match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr network=i.j.k.f/25 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting iface_out for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting iface_in for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr iface_in=publ-br0.24 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting chain for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting chain match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr chain=nfcp-check to the xml result
trace May 18 23:02:50 append_secure_list(726):0: tunnel-wigner-guest: no secure parameters
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <status>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-wigner-guest" type="tunnel" class="ocf" provider="local">
trace May 18 23:02:50 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </lrm>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </node_state>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </status>
trace May 18 23:02:50 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 18 23:02:50 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 18 23:02:50 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 5893 bytes: 1104 timeout:120000 msg...
trace May 18 23:02:50 crm_ipc_send(1202):0: Message sent, not waiting for reply to 5893 from cib_shm to 1104 bytes...
trace May 18 23:02:50 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 18 23:02:50 cib_native_perform_op_delegate(398):0: Async call, returning 2579
trace May 18 23:02:50 do_update_resource(2313):0: Sent resource state update message: 2579 for start=0 on tunnel-wigner-guest
trace May 18 23:02:50 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:50 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 2579
trace May 18 23:02:50 process_lrm_event(2413):0: Op tunnel-wigner-guest_start_0 (call=3039, stop-id=tunnel-wigner-guest:3039, remaining=10): Confirmed
notice May 18 23:02:50 process_lrm_event(2438):0: Result of start operation for tunnel-wigner-guest on bifur1: 0 (ok) | call=3039 key=tunnel-wigner-guest_start_0 confirmed=true cib-update=2579
debug May 18 23:02:50 process_lrm_event(2466):0: bifur1-tunnel-wigner-guest_start_0:3039 [ :accept-1 - [0:0]\n:drop-1 - [0:0]\n:out-1 - [0:0]\n:in-1 - [0:0]\n ]
debug May 18 23:02:50 update_history_cache(196):0: Updating history for 'tunnel-wigner-guest' with start op
trace May 18 23:02:50 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 18 23:02:50 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 18 23:02:50 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:50 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:50 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:50 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:50 crm_ipc_read(1003):0: Received cib_shm event 13264, size=3352, rc=3352, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 18 23:02:50 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 3312 (I/O condition=1)
trace May 18 23:02:50 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:50 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 18 23:02:50 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 18 23:02:50 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 18 23:02:50 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:50 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 18 23:02:50 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 18 23:02:50 xml_patch_versions(1747):0: Got 559 for del[epoch]
trace May 18 23:02:50 xml_patch_versions(1747):0: Got 18 for del[num_updates]
trace May 18 23:02:50 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 18 23:02:50 xml_patch_versions(1758):0: Got 559 for add[epoch]
trace May 18 23:02:50 xml_patch_versions(1758):0: Got 19 for add[num_updates]
debug May 18 23:02:50 te_update_diff(390):0: Processing (cib_modify) diff: 0.559.18 -> 0.559.19 (S_TRANSITION_ENGINE)
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <version>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="559" num_updates="18"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="559" num_updates="19"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </version>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="19"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="559" num_updates="19" admin_epoch="0" cib-last-written="Sat May 18 22:32:41 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:50 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 18 23:02:50 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 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="operation_key" operation="set" value="tunnel-wigner-guest_start_0"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="operation" operation="set" value="start"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="25:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;25:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="3039"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="exec-time" operation="set" value="1245"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="queue-time" operation="set" value="0"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:50 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </diff>
trace May 18 23:02:50 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 18 23:02:50 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 18 23:02:50 status_from_rc(232):0: Target rc: == 0
trace May 18 23:02:50 stop_te_timer(438):0: Stopping action timer
trace May 18 23:02:50 te_update_job_count_on(548):0: jobs[bifur1] = 0
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(115):0: Synapse executed
trace May 18 23:02:50 update_synapse_confirmed(76):0: Processing action 25
trace May 18 23:02:50 update_synapse_confirmed(79):0: Confirmed: Action 25 of Synapse 4
trace May 18 23:02:50 update_synapse_confirmed(90):0: Confirmed: Synapse 4
trace May 18 23:02:50 update_synapse_confirmed(96):0: Updated synapse 4
trace May 18 23:02:50 update_synapse_ready(43):0: Processing input 25
trace May 18 23:02:50 update_synapse_ready(46):0: Marking input 25 of synapse 5 confirmed
trace May 18 23:02:50 update_synapse_ready(57):0: Updated synapse 5
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(125):0: Updated graph with completed action 25
trace May 18 23:02:50 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 18 23:02:50 match_graph_event(316):0: Action tunnel-wigner-guest_start_0 (25) confirmed on bifur1 (rc=0)
trace May 18 23:02:50 process_graph_event(520):0: Processed update to tunnel-wigner-guest_start_0: 25:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 18 23:02:50 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:50 crm_ipc_read(1003):0: Received cib_shm event 13266, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="2579" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 18 23:02:50 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 18 23:02:50 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:50 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 18 23:02:50 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 2579
trace May 18 23:02:50 cib_rsc_callback(2203):0: Resource update 2579 complete: rc=0
trace May 18 23:02:50 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 18 23:02:50 cib_native_callback(663):0: Invoking global callback for call 2579
trace May 18 23:02:50 cib_native_callback(666):0: OP callback activated for 2579
trace May 18 23:02:50 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 18 23:02:50 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 18 23:02:50 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:50 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:50 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:50 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:50 te_graph_trigger(460):0: Invoking graph 250 in state S_TRANSITION_ENGINE
trace May 18 23:02:50 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:50 run_graph(267):0: Entering graph 250 callback
trace May 18 23:02:50 run_graph(274):0: Synapse 0 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 1 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 2 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 3 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 4 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 6 complete
trace May 18 23:02:50 should_fire_synapse(138):0: Checking pre-reqs for synapse 5
trace May 18 23:02:50 should_fire_synapse(144):0: Processing input 25
trace May 18 23:02:50 te_should_perform_action_on(622):0: Peer bifur1 has not hit their limit yet. current jobs = 0 limit= 8 limit
trace May 18 23:02:50 run_graph(300):0: Synapse 5 fired
trace May 18 23:02:50 fire_synapse(223):0: Synapse 5 fired
trace May 18 23:02:50 initiate_action(192):0: Executing rsc-event: 22 (22)
notice May 18 23:02:50 te_rsc_command(436):0: Initiating monitor operation tunnel-wigner-guest_monitor_60000 locally on bifur1 | action 22
trace May 18 23:02:50 do_lrm_invoke(1495):0: LRM command from user '(null)'
trace May 18 23:02:50 do_lrm_invoke(1504):0: LRM command from: tengine
trace May 18 23:02:50 get_lrm_resource(1253):0: Retrieving tunnel-wigner-guest from the LRM.
trace May 18 23:02:50 xml2list(4792):0: Unpacking <attributes CRM_meta_interval="60000" CRM_meta_name="monitor" CRM_meta_timeout="120000" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" id="1" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:50 xml2list(4798):0: Added CRM_meta_interval=60000
trace May 18 23:02:50 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 18 23:02:50 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:50 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:50 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:50 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:50 xml2list(4798):0: Added id=1
trace May 18 23:02:50 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:50 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:50 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:50 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:50 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:50 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:50 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:50 construct_op(1882):0: Constructed monitor op for tunnel-wigner-guest: interval=60000
info May 18 23:02:50 do_lrm_rsc_op(2086):0: Performing key=22:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32 op=tunnel-wigner-guest_monitor_60000
trace May 18 23:02:50 cancel_op_key(1239):0: Removed 0 op cache entries, new size: 10
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: iface_in=publ-br0.24
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: tunnel_dst_ip=10.10.0.3
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: tunnel_src_ip=10.10.1.3
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: id=1
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: name=Wigner guest IPv4 tunnel
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: iface_out=publ-br1
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: network=i.j.k.f/25
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: chain=nfcp-check
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: crm_feature_set=3.0.11
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: dst_ip=a.b.c.d
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: src_ip=r.s.t.v
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: CRM_meta_name=monitor
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: CRM_meta_timeout=120000
trace May 18 23:02:50 hash2smartfield(4734):0: dumped: CRM_meta_interval=60000
trace May 18 23:02:50 lrmd_send_command(818):0: sending lrmd_rsc_exec op to lrmd
trace May 18 23:02:50 lrmd_create_op(489):0: Sending call options: 00000004, 4
trace May 18 23:02:50 crm_ipc_send(1189):0: Sending from client: lrmd request id: 5894 bytes: 837 timeout:120000 msg...
trace May 18 23:02:50 internal_ipc_get_reply(1082):0: client lrmd waiting on reply to msg id 5894
trace May 18 23:02:50 crm_ipc_send(1227):0: Received response 5894, size=113, rc=113, text: <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3041" lrmd_callid="3041"/>
trace May 18 23:02:50 lrmd_send_command(847):0: lrmd_rsc_exec op reply received
trace May 18 23:02:50 lrmd_send_command(853):0: Reply <lrmd_reply lrmd_origin="send_reply" lrmd_rc="3041" lrmd_callid="3041"/>
trace May 18 23:02:50 do_lrm_rsc_op(2160):0: Recording pending op: 3041 - tunnel-wigner-guest_monitor_60000 tunnel-wigner-guest:3041
trace May 18 23:02:50 te_update_job_count_on(548):0: jobs[bifur1] = 1
debug May 18 23:02:50 run_graph(343):0: Transition 250 (Complete=6, Pending=1, Fired=1, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-2364.bz2): In-progress
trace May 18 23:02:50 te_graph_trigger(487):0: Transition not yet complete
trace May 18 23:02:50 crm_ipc_read(1003):0: Received lrmd event 2986, size=840, rc=840, text: <lrmd_notify lrmd_origin="send_cmd_complete_notify" lrmd_timeout="120000" lrmd_rsc_interval="60000"
trace May 18 23:02:50 mainloop_gio_callback(663):0: New message from lrmd[0x5626d09448b0] = 800 (I/O condition=1)
trace May 18 23:02:50 xml2list(4792):0: Unpacking <attributes iface_in="publ-br0.24" CRM_meta_timeout="120000" CRM_meta_interval="60000" id="1" name="Wigner guest IPv4 tunnel" iface_out="publ-br1" network="i.j.k.f/25" chain="nfcp-check" crm_feature_set="3.0.11" dst_ip="a.b.c.d" src_ip="r.s.t.v" CRM_meta_name="monitor" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:50 xml2list(4798):0: Added iface_in=publ-br0.24
trace May 18 23:02:50 xml2list(4798):0: Added CRM_meta_timeout=120000
trace May 18 23:02:50 xml2list(4798):0: Added CRM_meta_interval=60000
trace May 18 23:02:50 xml2list(4798):0: Added id=1
trace May 18 23:02:50 xml2list(4798):0: Added name=Wigner guest IPv4 tunnel
trace May 18 23:02:50 xml2list(4798):0: Added iface_out=publ-br1
trace May 18 23:02:50 xml2list(4798):0: Added network=i.j.k.f/25
trace May 18 23:02:50 xml2list(4798):0: Added chain=nfcp-check
trace May 18 23:02:50 xml2list(4798):0: Added crm_feature_set=3.0.11
trace May 18 23:02:50 xml2list(4798):0: Added dst_ip=a.b.c.d
trace May 18 23:02:50 xml2list(4798):0: Added src_ip=r.s.t.v
trace May 18 23:02:50 xml2list(4798):0: Added CRM_meta_name=monitor
trace May 18 23:02:50 xml2list(4798):0: Added tunnel_dst_ip=10.10.0.3
trace May 18 23:02:50 xml2list(4798):0: Added tunnel_src_ip=10.10.1.3
trace May 18 23:02:50 lrmd_dispatch_internal(301):0: op lrmd_rsc_exec notify event received
trace May 18 23:02:50 build_operation_update(763):0: Building tunnel-wigner-guest operation update with originator version: 3.0.11
trace May 18 23:02:50 compare_version(536):0: 3.0.11 > 3.0.3 (3)
trace May 18 23:02:50 compare_version(536):0: 3.0.11 > 3.0.6 (3)
debug May 18 23:02:50 create_operation_update(1773):0: do_update_resource: Updating resource tunnel-wigner-guest after monitor op complete (interval=60000)
trace May 18 23:02:50 create_operation_update(1775):0: DC version: 3.0.11
trace May 18 23:02:50 find_entity(2226):0: node <lrm_rsc_op id=tunnel-wigner-guest_monitor_60000> not found in lrm_resource.
trace May 18 23:02:50 compare_version(534):0: 2.1 < 3.0.11 (1)
trace May 18 23:02:50 create_operation_update(1870):0: Timing data (tunnel-wigner-guest_monitor_60000): last=1558213370 change=0 exec=50 queue=0
trace May 18 23:02:50 compare_version(536):0: 3.0.11 > 1.0.8 (1)
trace May 18 23:02:50 calculate_xml_digest_v1(71):0: Sorting xml...
trace May 18 23:02:50 calculate_xml_digest_v1(73):0: Done
trace May 18 23:02:50 crm_md5sum(2102):0: Beginning digest of 255 bytes
trace May 18 23:02:50 crm_md5sum(2110):0: Digest f611e9b58474b7237e8546d025b95c13.
trace May 18 23:02:50 calculate_xml_digest_v1(83):0: digest:source <parameters CRM_meta_timeout="120000" chain="nfcp-check" dst_ip="a.b.c.d" iface_in="publ-br0.24" iface_out="publ-br1" name="Wigner guest IPv4 tunnel" network="i.j.k.f/25" src_ip="r.s.t.v" tunnel_dst_ip="10.10.0.3" tunnel_src_ip="10.10.1.3"/>
trace May 18 23:02:50 get_rsc_metadata(532):0: Retrieved cached metadata for ocf::local:tunnel
trace May 18 23:02:50 build_operation_update(787):0: Including additional digests for ocf::local:tunnel
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting name for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting name match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr name=Wigner guest IPv4 tunnel to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting id for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting id match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr id=1 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting src_ip for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting src_ip match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr src_ip=r.s.t.v to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting dst_ip for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting dst_ip match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr dst_ip=a.b.c.d to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting tunnel_src_ip for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting tunnel_src_ip match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr tunnel_src_ip=10.10.1.3 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting tunnel_dst_ip for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting tunnel_dst_ip match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr tunnel_dst_ip=10.10.0.3 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting network for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting network match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr network=i.j.k.f/25 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting iface_out for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting iface_out match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr iface_out=publ-br1 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting iface_in for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting iface_in match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr iface_in=publ-br0.24 to the xml result
trace May 18 23:02:50 build_parameter_list(621):0: Rejecting chain for private
trace May 18 23:02:50 build_parameter_list(625):0: Inverting chain match for private xml
trace May 18 23:02:50 build_parameter_list(632):0: Adding attr chain=nfcp-check to the xml result
trace May 18 23:02:50 append_secure_list(726):0: tunnel-wigner-guest: no secure parameters
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <status>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <node_state id="1084762125" uname="bifur1" crm-debug-origin="do_update_resource">
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <lrm id="1084762125">
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <lrm_resources>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource <lrm_resource id="tunnel-wigner-guest" type="tunnel" class="ocf" provider="local">
trace May 18 23:02:50 do_update_resource(2286):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </lrm_resource>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </lrm_resources>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </lrm>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </node_state>
trace May 18 23:02:50 do_update_resource(2286):0: do_update_resource </status>
trace May 18 23:02:50 cib_create_op(609):0: Sending call options: 00100000, 1048576
trace May 18 23:02:50 cib_native_perform_op_delegate(384):0: Sending cib_modify message to CIB service (timeout=120s)
trace May 18 23:02:50 crm_ipc_send(1189):0: Sending from client: cib_shm request id: 5895 bytes: 1022 timeout:120000 msg...
trace May 18 23:02:50 crm_ipc_send(1202):0: Message sent, not waiting for reply to 5895 from cib_shm to 1022 bytes...
trace May 18 23:02:50 cib_native_perform_op_delegate(395):0: Reply: No data to dump as XML
trace May 18 23:02:50 cib_native_perform_op_delegate(398):0: Async call, returning 2580
trace May 18 23:02:50 do_update_resource(2313):0: Sent resource state update message: 2580 for monitor=60000 on tunnel-wigner-guest
trace May 18 23:02:50 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:50 cib_client_register_callback_full(632):0: Adding callback cib_rsc_callback for call 2580
info May 18 23:02:50 process_lrm_event(2438):0: Result of monitor operation for tunnel-wigner-guest on bifur1: 0 (ok) | call=3041 key=tunnel-wigner-guest_monitor_60000 confirmed=false cib-update=2580
debug May 18 23:02:50 update_history_cache(196):0: Updating history for 'tunnel-wigner-guest' with monitor op
trace May 18 23:02:50 update_history_cache(266):0: Adding recurring op: tunnel-wigner-guest_monitor_60000
trace May 18 23:02:50 crm_ipc_read(1006):0: No message from lrmd received: Resource temporarily unavailable
trace May 18 23:02:50 mainloop_gio_callback(658):0: Message acquisition from lrmd[0x5626d09448b0] failed: No message of desired type (-42)
trace May 18 23:02:50 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:50 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:50 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:50 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:50 crm_ipc_read(1003):0: Received cib_shm event 13267, size=3000, rc=3000, text: <notify t="cib_notify" subt="cib_diff_notify" cib_op="cib_modify" cib_rc="0" cib_object_type="status
trace May 18 23:02:50 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 2960 (I/O condition=1)
trace May 18 23:02:50 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:50 cib_native_dispatch_internal(116):0: Activating cib_notify callbacks...
trace May 18 23:02:50 cib_native_notify(692):0: Skipping callback - event mismatch 0x5626d08405f0/cib_refresh_notify vs. cib_diff_notify
trace May 18 23:02:50 cib_native_notify(696):0: Invoking callback for 0x5626d0843540/cib_diff_notify event...
trace May 18 23:02:50 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:50 cib_native_notify(696):0: Invoking callback for 0x5626d0a400f0/cib_diff_notify event...
trace May 18 23:02:50 xml_patch_versions(1747):0: Got 0 for del[admin_epoch]
trace May 18 23:02:50 xml_patch_versions(1747):0: Got 559 for del[epoch]
trace May 18 23:02:50 xml_patch_versions(1747):0: Got 19 for del[num_updates]
trace May 18 23:02:50 xml_patch_versions(1758):0: Got 0 for add[admin_epoch]
trace May 18 23:02:50 xml_patch_versions(1758):0: Got 559 for add[epoch]
trace May 18 23:02:50 xml_patch_versions(1758):0: Got 20 for add[num_updates]
debug May 18 23:02:50 te_update_diff(390):0: Processing (cib_modify) diff: 0.559.19 -> 0.559.20 (S_TRANSITION_ENGINE)
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <diff format="2">
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <version>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <source admin_epoch="0" epoch="559" num_updates="19"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <target admin_epoch="0" epoch="559" num_updates="20"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </version>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change operation="modify" path="/cib">
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="num_updates" operation="set" value="20"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <cib crm_feature_set="3.0.11" validate-with="pacemaker-2.6" epoch="559" num_updates="20" admin_epoch="0" cib-last-written="Sat May 18 22:32:41 2019" update-origin="bifur1" update-client="cibadmin" update-user="root" have-quorum="1" dc-uuid="1084762125"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:50 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_60000']'
trace May 18 23:02:50 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_60000']">
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-list>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="transition-key" operation="set" value="22:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="transition-magic" operation="set" value="0:0;22:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="call-id" operation="set" value="3041"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-attr name="last-rc-change" operation="set" value="1558213370"/>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change-list>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw <change-result>
trace May 18 23:02:50 te_update_diff(399):0: Log message too long to be stored in the blackbox. Maximum is QB_LOG_MAX_LEN
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change-result>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </change>
trace May 18 23:02:50 te_update_diff(399):0: Patch:Raw </diff>
trace May 18 23:02:50 te_update_diff(439):0: Handling modify operation for /cib matched by cib
trace May 18 23:02:50 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_60000'] matched by lrm_rsc_op
trace May 18 23:02:50 status_from_rc(232):0: Target rc: == 0
trace May 18 23:02:50 stop_te_timer(438):0: Stopping action timer
trace May 18 23:02:50 te_update_job_count_on(548):0: jobs[bifur1] = 0
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(115):0: Synapse executed
trace May 18 23:02:50 update_synapse_confirmed(76):0: Processing action 22
trace May 18 23:02:50 update_synapse_confirmed(79):0: Confirmed: Action 22 of Synapse 5
trace May 18 23:02:50 update_synapse_confirmed(90):0: Confirmed: Synapse 5
trace May 18 23:02:50 update_synapse_confirmed(96):0: Updated synapse 5
trace May 18 23:02:50 update_graph(112):0: Synapse complete
trace May 18 23:02:50 update_graph(125):0: Updated graph with completed action 22
trace May 18 23:02:50 trigger_graph_processing(511):0: match_graph_event:307 - Triggered graph processing
info May 18 23:02:50 match_graph_event(316):0: Action tunnel-wigner-guest_monitor_60000 (22) confirmed on bifur1 (rc=0)
trace May 18 23:02:50 process_graph_event(520):0: Processed update to tunnel-wigner-guest_monitor_60000: 22:250:0:73562fd6-1fe2-4930-8c6e-5953b82ebb32
trace May 18 23:02:50 cib_native_notify(698):0: Callback invoked...
trace May 18 23:02:50 crm_ipc_read(1003):0: Received cib_shm event 13269, size=184, rc=184, text: <cib-reply t="cib" cib_op="cib_modify" cib_callid="2580" cib_clientid="e21a51c7-754b-4ad6-ab7e-f6740
trace May 18 23:02:50 mainloop_gio_callback(663):0: New message from cib_shm[0x5626d08402d0] = 144 (I/O condition=1)
trace May 18 23:02:50 cib_native_dispatch_internal(100):0: dispatching 0x5626d0733870
trace May 18 23:02:50 cib_native_dispatch_internal(116):0: Activating cib callbacks...
trace May 18 23:02:50 cib_native_callback(649):0: Invoking callback cib_rsc_callback for call 2580
trace May 18 23:02:50 cib_rsc_callback(2203):0: Resource update 2580 complete: rc=0
trace May 18 23:02:50 cib_rsc_callback(2211):0: Triggering FSA: cib_rsc_callback
trace May 18 23:02:50 cib_native_callback(663):0: Invoking global callback for call 2580
trace May 18 23:02:50 cib_native_callback(666):0: OP callback activated for 2580
trace May 18 23:02:50 crm_ipc_read(1006):0: No message from cib_shm received: Resource temporarily unavailable
trace May 18 23:02:50 mainloop_gio_callback(658):0: Message acquisition from cib_shm[0x5626d08402d0] failed: No message of desired type (-42)
trace May 18 23:02:50 crm_fsa_trigger(312):0: Invoked (queue len: 0)
trace May 18 23:02:50 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:50 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:50 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:50 te_graph_trigger(460):0: Invoking graph 250 in state S_TRANSITION_ENGINE
trace May 18 23:02:50 crm_is_corosync_peer_active(479):0: (null): processes=0000000000000000
trace May 18 23:02:50 run_graph(267):0: Entering graph 250 callback
trace May 18 23:02:50 run_graph(274):0: Synapse 0 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 1 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 2 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 3 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 4 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 5 complete
trace May 18 23:02:50 run_graph(274):0: Synapse 6 complete
notice May 18 23:02:50 run_graph(343):0: Transition 250 (Complete=7, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-2364.bz2): Complete
debug May 18 23:02:50 te_graph_trigger(501):0: Transition 250 is now complete
debug May 18 23:02:50 notify_crmd(687):0: Processing transition completion in state S_TRANSITION_ENGINE
debug May 18 23:02:50 notify_crmd(735):0: Transition 250 status: done - <null>
trace May 18 23:02:50 register_fsa_input_adv(113):0: notify_crmd appended FSA input 798 (I_TE_SUCCESS) (cause=C_FSA_INTERNAL) without data
trace May 18 23:02:50 register_fsa_input_adv(175):0: Queue len: 1
trace May 18 23:02:50 register_fsa_input_adv(184):0: Triggering FSA: register_fsa_input_adv
trace May 18 23:02:50 crm_fsa_trigger(312):0: Invoked (queue len: 1)
trace May 18 23:02:50 s_crmd_fsa(159):0: FSA invoked with Cause: C_FSA_INTERNAL State: S_TRANSITION_ENGINE
trace May 18 23:02:50 s_crmd_fsa(175):0: Checking messages (1 remaining)
trace May 18 23:02:50 get_message(275):0: Processing input 798
trace May 18 23:02:50 log_fsa_input(455):0: Processing queued input 798
trace May 18 23:02:50 log_fsa_input(463):0: FSA processing input from notify_crmd
trace May 18 23:02:50 fsa_dump_actions(919):0: Action 1000000000000000 (A_LOG ) New actions
debug May 18 23:02:50 s_crmd_fsa(197):0: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_FSA_INTERNAL origin=notify_crmd ]
trace May 18 23:02:50 do_fsa_action(142):0: actions:trace: // A_LOG
info May 18 23:02:50 do_log(46):0: Input I_TE_SUCCESS received in state S_TRANSITION_ENGINE from notify_crmd
trace May 18 23:02:50 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 18 23:02:50 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 18 23:02:50 crm_set_bit(185):0: Bit 0x00000020 set by do_state
trace May 18 23:02:50 crm_set_bit(185):0: Bit 0x00000080 set by do_state
trace May 18 23:02:50 crm_set_bit(185):0: Bit 0x00000200 set by do_state
debug May 18 23:02:50 do_state_transition(641):0: Starting PEngine Recheck Timer
debug May 18 23:02:50 crm_timer_start(192):0: Started PEngine Recheck Timer (I_PE_CALC:900000ms), src=4712
trace May 18 23:02:50 do_fsa_action(142):0: actions:trace: // A_DC_TIMER_STOP
trace May 18 23:02:50 crm_timer_stop(225):0: Election Trigger (I_DC_TIMEOUT:20000ms) already stopped
trace May 18 23:02:50 do_fsa_action(142):0: actions:trace: // A_INTEGRATE_TIMER_STOP
trace May 18 23:02:50 crm_timer_stop(225):0: Integration Timer (I_INTEGRATED:180000ms) already stopped
trace May 18 23:02:50 do_fsa_action(142):0: actions:trace: // A_FINALIZE_TIMER_STOP
trace May 18 23:02:50 crm_timer_stop(225):0: Finalization Timer (I_ELECTION:1800000ms) already stopped
trace May 18 23:02:50 delete_fsa_input(236):0: About to free C_FSA_INTERNAL data
trace May 18 23:02:50 s_crmd_fsa(246):0: Exiting the FSA
trace May 18 23:02:50 crm_fsa_trigger(314):0: Exited (queue len: 0)
trace May 18 23:02:59 mainloop_timer_cb(1162):0: Invoking callbacks for timer throttle-30000-1
debug May 18 23:02:59 throttle_cib_load(218):0: cib load: 0.001000 (3 ticks in 30s)
trace May 18 23:02:59 throttle_mode(436):0: Negligible CIB load detected: 0.001000
debug May 18 23:02:59 throttle_load_avg(260):0: Current load is 0.100000 (full: 0.10 0.07 0.08 1/181 38207)
trace May 18 23:02:59 throttle_handle_load(380):0: Negligible CPU load detected: 0.025000
debug May 18 23:02:59 throttle_io_load(340):0: Current IO load is 0.000000
trace May 18 23:02:59 throttle_handle_load(380):0: Negligible IO load detected: 0.000000
trace May 18 23:02:59 throttle_handle_load(380):0: Negligible blocked IO ratio detected: 0.000000
notice May 18 23:03:05 crm_signal_dispatch(276):0: Caught 'Trace/breakpoint trap' signal | 5 (invoking handler)
notice May 18 23:03:05 crm_write_blackbox(443):0: Blackbox dump requested, please see /var/lib/pacemaker/blackbox/crmd-3055.5 for contents
More information about the Users
mailing list