Am Dienstag, 26. Mai 2009 08:16:53 schrieb Andrew Beekhof: > On Mon, May 25, 2009 at 9:49 PM, Michael Schwartzkopff > > <[email protected]> wrote: > > Hi, > > > > I am just setting up a new cluster. It behaves VERY slow. An example from > > the logs: > > > > I switched on node offline: > > May 25 21:43:10 mom2 cib: [2804]: info: cib_process_request: Operation > > complete: op cib_modify for section nodes (origin=mom1/crm_standby/4, > > version=0.18.1): ok (rc=0) > > > > Only 50 sec later the cluster gets the idea what happened: > > May 25 21:43:59 mom2 pengine: [2813]: info: unpack_status: Node mom2 is > > in standby-mode > > May 25 21:43:59 mom2 pengine: [2813]: info: determine_online_status: Node > > mom2 is standby > > > > ...and tries to pull down the configured resource. > > May 25 21:43:59 mom2 pengine: [2813]: notice: LogActions: Stop resource > > resDRBD:1#011(mom2) > > > > any idea what might be the source for the delay? Thanks. > > Nope. What did the logs say in between?
Tried this morning again. Please see attached logs. -- Dr. Michael Schwartzkopff MultiNET Services GmbH Addresse: Bretonischer Ring 7; 85630 Grasbrunn; Germany Tel: +49 - 89 - 45 69 11 0 Fax: +49 - 89 - 45 69 11 21 mob: +49 - 174 - 343 28 75 mail: [email protected] web: www.multinet.de Sitz der Gesellschaft: 85630 Grasbrunn Registergericht: Amtsgericht München HRB 114375 Geschäftsführer: Günter Jurgeneit, Hubert Martens --- PGP Fingerprint: F919 3919 FF12 ED5A 2801 DEA6 AA77 57A4 EDD8 979B Skype: misch42
May 26 08:17:24 mom2 mgmtd: [2802]: info: CIB query: cib May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - <cib admin_epoch="0" epoch="22" num_updates="8" > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - <configuration > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - <nodes > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - <node id="c6d42f70-936b-47b1-ac46-2e68baae3229" > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - <instance_attributes id="nodes-c6d42f70-936b-47b1-ac46-2e68baae3229" > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - <nvpair value="true" id="standby-c6d42f70-936b-47b1-ac46-2e68baae3229" /> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - </instance_attributes> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - </node> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - </nodes> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - </configuration> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: - </cib> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + <cib admin_epoch="0" epoch="23" num_updates="1" > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + <configuration > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + <nodes > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + <node id="c6d42f70-936b-47b1-ac46-2e68baae3229" > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + <instance_attributes id="nodes-c6d42f70-936b-47b1-ac46-2e68baae3229" > May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + <nvpair value="false" id="standby-c6d42f70-936b-47b1-ac46-2e68baae3229" /> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + </instance_attributes> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + </node> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + </nodes> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + </configuration> May 26 08:18:12 mom2 cib: [2804]: info: log_data_element: cib:diff: + </cib> May 26 08:18:12 mom2 cib: [2804]: info: cib_process_request: Operation complete: op cib_modify for section nodes (origin=local/mgmtd/166, version=0.23.1): ok (rc=0) May 26 08:18:12 mom2 crmd: [2808]: info: abort_transition_graph: need_abort:59 - Triggered transition abort (complete=1) : Non-status change May 26 08:18:12 mom2 crmd: [2808]: info: need_abort: Aborting on change to admin_epoch May 26 08:18:12 mom2 crmd: [2808]: info: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=abort_transition_graph ] May 26 08:18:12 mom2 crmd: [2808]: info: do_state_transition: All 2 cluster nodes are eligible to run resources. May 26 08:18:12 mom2 crmd: [2808]: info: do_pe_invoke: Query 169: Requesting the current CIB: S_POLICY_ENGINE May 26 08:18:12 mom2 crmd: [2808]: info: do_pe_invoke_callback: Invoking the PE: ref=pe_calc-dc-1243318692-209, seq=2, quorate=1 May 26 08:18:12 mom2 pengine: [2813]: notice: unpack_config: On loss of CCM Quorum: Ignore May 26 08:18:12 mom2 pengine: [2813]: info: determine_online_status: Node mom1 is online May 26 08:18:12 mom2 pengine: [2813]: info: unpack_rsc_op: resDRBD:0_monitor_0 on mom1 returned 0 (ok) instead of the expected value: 7 (not running) May 26 08:18:12 mom2 pengine: [2813]: WARN: unpack_rsc_op: Operation resDRBD:0_monitor_0 found resource resDRBD:0 active on mom1 May 26 08:18:12 mom2 pengine: [2813]: info: determine_online_status: Node mom2 is online May 26 08:18:12 mom2 pengine: [2813]: info: find_clone: Internally renamed resDRBD:0 on mom2 to resDRBD:1 May 26 08:18:12 mom2 pengine: [2813]: info: unpack_rsc_op: resDRBD:0_monitor_0 on mom2 returned 0 (ok) instead of the expected value: 7 (not running) May 26 08:18:12 mom2 pengine: [2813]: WARN: unpack_rsc_op: Operation resDRBD:0_monitor_0 found resource resDRBD:1 active on mom2 May 26 08:18:12 mom2 pengine: [2813]: notice: clone_print: Master/Slave Set: masterDRBD May 26 08:18:12 mom2 pengine: [2813]: notice: print_list: #011Masters: [ mom1 ] May 26 08:18:12 mom2 pengine: [2813]: notice: print_list: #011Stopped: [ resDRBD:1 ] May 26 08:18:12 mom2 pengine: [2813]: info: master_color: Promoting resDRBD:0 (Master mom1) May 26 08:18:12 mom2 pengine: [2813]: info: master_color: masterDRBD: Promoted 1 instances of a possible 1 to master May 26 08:18:12 mom2 pengine: [2813]: notice: RecurringOp: Start recurring monitor (20s) for resDRBD:1 on mom2 May 26 08:18:12 mom2 pengine: [2813]: notice: RecurringOp: Start recurring monitor (20s) for resDRBD:1 on mom2 May 26 08:18:12 mom2 pengine: [2813]: notice: LogActions: Leave resource resDRBD:0#011(Master mom1) May 26 08:18:12 mom2 pengine: [2813]: notice: LogActions: Start resDRBD:1#011(mom2) May 26 08:18:12 mom2 crmd: [2808]: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ] May 26 08:18:12 mom2 crmd: [2808]: info: unpack_graph: Unpacked transition 73: 11 actions in 11 synapses May 26 08:18:12 mom2 crmd: [2808]: info: do_te_invoke: Processing graph 73 (ref=pe_calc-dc-1243318692-209) derived from /var/lib/pengine/pe-input-27.bz2 May 26 08:18:12 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 14 fired and confirmed May 26 08:18:12 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 40: notify resDRBD:0_pre_notify_start_0 on mom1 May 26 08:18:12 mom2 pengine: [2813]: info: process_pe_message: Transition 73: PEngine Input stored in: /var/lib/pengine/pe-input-27.bz2 May 26 08:18:12 mom2 cib: [6971]: info: write_cib_contents: Archived previous version as /var/lib/heartbeat/crm/cib-21.raw May 26 08:18:12 mom2 cib: [6971]: info: write_cib_contents: Wrote version 0.23.0 of the CIB to disk (digest: 78ec6a5b3c952328fa949b54a959d633) May 26 08:18:12 mom2 cib: [6971]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.LABQMy (digest: /var/lib/heartbeat/crm/cib.6ByfXp) May 26 08:18:12 mom2 mgmtd: [2802]: info: CIB query: cib May 26 08:18:13 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:0_pre_notify_start_0 (40) confirmed on mom1 (rc=0) May 26 08:18:13 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 15 fired and confirmed May 26 08:18:13 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 12 fired and confirmed May 26 08:18:13 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 10: start resDRBD:1_start_0 on mom2 (local) May 26 08:18:13 mom2 crmd: [2808]: info: do_lrm_rsc_op: Performing key=10:73:0:db9daf87-c4f5-47fe-8b3d-d5e3d6842c50 op=resDRBD:1_start_0 ) May 26 08:18:13 mom2 lrmd: [2805]: info: rsc:resDRBD:1: start May 26 08:18:13 mom2 kernel: [41007.427001] drbd0: disk( Diskless -> Attaching ) May 26 08:18:13 mom2 kernel: [41007.427008] drbd0: Starting worker thread (from cqueue [2591]) May 26 08:18:13 mom2 kernel: [41007.442690] drbd0: Found 6 transactions (111 active extents) in activity log. May 26 08:18:13 mom2 kernel: [41007.442690] drbd0: max_segment_size ( = BIO size ) = 32768 May 26 08:18:13 mom2 kernel: [41007.442690] drbd0: drbd_bm_resize called with capacity == 15710952 May 26 08:18:13 mom2 kernel: [41007.450743] drbd0: resync bitmap: bits=1963869 words=61372 May 26 08:18:13 mom2 kernel: [41007.450747] drbd0: size = 7671 MB (7855476 KB) May 26 08:18:13 mom2 kernel: [41007.467101] drbd0: recounting of set bits took additional 0 jiffies May 26 08:18:13 mom2 kernel: [41007.467101] drbd0: 0 KB (0 bits) marked out-of-sync by on disk bit-map. May 26 08:18:13 mom2 kernel: [41007.467101] drbd0: disk( Attaching -> UpToDate ) May 26 08:18:13 mom2 kernel: [41007.478684] drbd0: conn( StandAlone -> Unconnected ) May 26 08:18:13 mom2 kernel: [41007.480931] drbd0: Starting receiver thread (from drbd0_worker [7006]) May 26 08:18:13 mom2 kernel: [41007.480931] drbd0: receiver (re)started May 26 08:18:13 mom2 kernel: [41007.480931] drbd0: conn( Unconnected -> WFConnection ) May 26 08:18:13 mom2 lrmd: [2805]: info: RA output: (resDRBD:1:start:stdout) May 26 08:18:13 mom2 crmd: [2808]: info: process_lrm_event: LRM operation resDRBD:1_start_0 (call=63, rc=0, cib-update=170, confirmed=true) complete ok May 26 08:18:13 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:1_start_0 (10) confirmed on mom2 (rc=0) May 26 08:18:13 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 13 fired and confirmed May 26 08:18:13 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 16 fired and confirmed May 26 08:18:13 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 41: notify resDRBD:0_post_notify_start_0 on mom1 May 26 08:18:13 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 48: notify resDRBD:1_post_notify_start_0 on mom2 (local) May 26 08:18:13 mom2 crmd: [2808]: info: do_lrm_rsc_op: Performing key=48:73:0:db9daf87-c4f5-47fe-8b3d-d5e3d6842c50 op=resDRBD:1_notify_0 ) May 26 08:18:13 mom2 lrmd: [2805]: info: rsc:resDRBD:1: notify May 26 08:18:13 mom2 crm_master: [7065]: info: Invoked: /usr/sbin/crm_master -l reboot -v 10 May 26 08:18:13 mom2 attrd: [2807]: info: attrd_trigger_update: Sending flush op to all hosts for: master-resDRBD:1 May 26 08:18:13 mom2 attrd: [2807]: info: attrd_perform_update: Sent update 57: master-resDRBD:1=10 May 26 08:18:13 mom2 crmd: [2808]: info: abort_transition_graph: te_update_diff:146 - Triggered transition abort (complete=0, tag=transient_attributes, id=c6d42f70-936b-47b1-ac46-2e68baae3229, magic=NA) : Transient attribute: update May 26 08:18:13 mom2 crmd: [2808]: info: update_abort_priority: Abort priority upgraded from 0 to 1000000 May 26 08:18:13 mom2 crmd: [2808]: info: update_abort_priority: Abort action done superceeded by restart May 26 08:18:13 mom2 lrmd: [2805]: info: RA output: (resDRBD:1:notify:stdout) 0 Trying master-resDRBD:1=10 update via attrd May 26 08:18:13 mom2 crmd: [2808]: info: process_lrm_event: LRM operation resDRBD:1_notify_0 (call=64, rc=0, cib-update=171, confirmed=true) complete ok May 26 08:18:13 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:1_post_notify_start_0 (48) confirmed on mom2 (rc=0) May 26 08:18:13 mom2 kernel: [41007.575744] drbd0: Handshake successful: DRBD Network Protocol version 86 May 26 08:18:13 mom2 kernel: [41007.575744] drbd0: conn( WFConnection -> WFReportParams ) May 26 08:18:13 mom2 kernel: [41007.575744] drbd0: Starting asender thread (from drbd0_receiver [7009]) May 26 08:18:13 mom2 kernel: [41007.579879] drbd0: drbd_sync_handshake: May 26 08:18:13 mom2 kernel: [41007.579879] drbd0: self 59CA76C3EB436A3A:0000000000000000:09B0800A7F50E580:A3305AB6F601D8FF May 26 08:18:13 mom2 kernel: [41007.579879] drbd0: peer 652CC66A09BCE7D5:59CA76C3EB436A3B:09B0800A7F50E581:A3305AB6F601D8FF May 26 08:18:13 mom2 kernel: [41007.579879] drbd0: uuid_compare()=-1 by rule 5 May 26 08:18:13 mom2 kernel: [41007.579879] drbd0: peer( Unknown -> Primary ) conn( WFReportParams -> WFBitMapT ) pdsk( DUnknown -> UpToDate ) May 26 08:18:13 mom2 kernel: [41007.591880] drbd0: conn( WFBitMapT -> WFSyncUUID ) May 26 08:18:13 mom2 kernel: [41007.591880] drbd0: conn( WFSyncUUID -> SyncTarget ) disk( UpToDate -> Inconsistent ) May 26 08:18:13 mom2 kernel: [41007.591880] drbd0: Began resync as SyncTarget (will sync 0 KB [0 bits set]). May 26 08:18:13 mom2 kernel: [41007.591880] drbd0: Resync done (total 1 sec; paused 0 sec; 0 K/sec) May 26 08:18:13 mom2 kernel: [41007.591880] drbd0: conn( SyncTarget -> Connected ) disk( Inconsistent -> UpToDate ) May 26 08:18:14 mom2 mgmtd: [2802]: info: CIB query: cib May 26 08:18:14 mom2 attrd: [2807]: info: attrd_ha_callback: flush message from mom1 May 26 08:18:14 mom2 crmd: [2808]: info: abort_transition_graph: te_update_diff:146 - Triggered transition abort (complete=0, tag=transient_attributes, id=a8254f3f-a97d-45d6-8da3-f72c4d2da1ba, magic=NA) : Transient attribute: update May 26 08:18:14 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:0_post_notify_start_0 (41) confirmed on mom1 (rc=0) May 26 08:18:14 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 17 fired and confirmed May 26 08:18:14 mom2 crmd: [2808]: info: run_graph: ==================================================== May 26 08:18:14 mom2 crmd: [2808]: notice: run_graph: Transition 73 (Complete=10, Pending=0, Fired=0, Skipped=1, Incomplete=0, Source=/var/lib/pengine/pe-input-27.bz2): Stopped May 26 08:18:14 mom2 crmd: [2808]: info: te_graph_trigger: Transition 73 is now complete May 26 08:18:14 mom2 crmd: [2808]: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ] May 26 08:18:14 mom2 crmd: [2808]: info: do_state_transition: All 2 cluster nodes are eligible to run resources. May 26 08:18:14 mom2 crmd: [2808]: info: do_pe_invoke: Query 172: Requesting the current CIB: S_POLICY_ENGINE May 26 08:18:14 mom2 crmd: [2808]: info: do_pe_invoke_callback: Invoking the PE: ref=pe_calc-dc-1243318694-214, seq=2, quorate=1 May 26 08:18:14 mom2 pengine: [2813]: notice: unpack_config: On loss of CCM Quorum: Ignore May 26 08:18:14 mom2 pengine: [2813]: info: determine_online_status: Node mom1 is online May 26 08:18:14 mom2 pengine: [2813]: info: unpack_rsc_op: resDRBD:0_monitor_0 on mom1 returned 0 (ok) instead of the expected value: 7 (not running) May 26 08:18:14 mom2 pengine: [2813]: WARN: unpack_rsc_op: Operation resDRBD:0_monitor_0 found resource resDRBD:0 active on mom1 May 26 08:18:14 mom2 pengine: [2813]: info: determine_online_status: Node mom2 is online May 26 08:18:14 mom2 pengine: [2813]: info: find_clone: Internally renamed resDRBD:0 on mom2 to resDRBD:1 May 26 08:18:14 mom2 pengine: [2813]: info: unpack_rsc_op: resDRBD:0_monitor_0 on mom2 returned 0 (ok) instead of the expected value: 7 (not running) May 26 08:18:14 mom2 pengine: [2813]: WARN: unpack_rsc_op: Operation resDRBD:0_monitor_0 found resource resDRBD:1 active on mom2 May 26 08:18:14 mom2 pengine: [2813]: notice: clone_print: Master/Slave Set: masterDRBD May 26 08:18:14 mom2 pengine: [2813]: notice: print_list: #011Masters: [ mom1 ] May 26 08:18:14 mom2 pengine: [2813]: notice: print_list: #011Slaves: [ mom2 ] May 26 08:18:14 mom2 pengine: [2813]: info: master_color: Promoting resDRBD:0 (Master mom1) May 26 08:18:14 mom2 pengine: [2813]: info: master_color: masterDRBD: Promoted 1 instances of a possible 1 to master May 26 08:18:14 mom2 pengine: [2813]: notice: RecurringOp: Start recurring monitor (20s) for resDRBD:1 on mom2 May 26 08:18:14 mom2 pengine: [2813]: notice: RecurringOp: Start recurring monitor (20s) for resDRBD:1 on mom2 May 26 08:18:14 mom2 pengine: [2813]: notice: LogActions: Leave resource resDRBD:0#011(Master mom1) May 26 08:18:14 mom2 pengine: [2813]: notice: LogActions: Leave resource resDRBD:1#011(Slave mom2) May 26 08:18:14 mom2 crmd: [2808]: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ] May 26 08:18:14 mom2 crmd: [2808]: info: unpack_graph: Unpacked transition 74: 1 actions in 1 synapses May 26 08:18:14 mom2 crmd: [2808]: info: do_te_invoke: Processing graph 74 (ref=pe_calc-dc-1243318694-214) derived from /var/lib/pengine/pe-input-28.bz2 May 26 08:18:14 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 13: monitor resDRBD:1_monitor_20000 on mom2 (local) May 26 08:18:14 mom2 crmd: [2808]: info: do_lrm_rsc_op: Performing key=13:74:0:db9daf87-c4f5-47fe-8b3d-d5e3d6842c50 op=resDRBD:1_monitor_20000 ) May 26 08:18:14 mom2 pengine: [2813]: info: process_pe_message: Transition 74: PEngine Input stored in: /var/lib/pengine/pe-input-28.bz2 May 26 08:18:15 mom2 mgmtd: [2802]: info: CIB query: cib May 26 08:18:24 mom2 crmd: [2808]: info: abort_transition_graph: need_abort:59 - Triggered transition abort (complete=0) : Non-status change May 26 08:18:24 mom2 crmd: [2808]: info: update_abort_priority: Abort priority upgraded from 0 to 1000000 May 26 08:18:24 mom2 crmd: [2808]: info: update_abort_priority: Abort action done superceeded by restart May 26 08:18:24 mom2 crmd: [2808]: info: need_abort: Aborting on change to admin_epoch May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - <cib admin_epoch="0" epoch="23" num_updates="7" > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - <configuration > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - <nodes > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - <node id="c6d42f70-936b-47b1-ac46-2e68baae3229" > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - <instance_attributes id="nodes-c6d42f70-936b-47b1-ac46-2e68baae3229" > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - <nvpair value="false" id="standby-c6d42f70-936b-47b1-ac46-2e68baae3229" /> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - </instance_attributes> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - </node> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - </nodes> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - </configuration> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: - </cib> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + <cib admin_epoch="0" epoch="24" num_updates="1" > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + <configuration > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + <nodes > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + <node id="c6d42f70-936b-47b1-ac46-2e68baae3229" > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + <instance_attributes id="nodes-c6d42f70-936b-47b1-ac46-2e68baae3229" > May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + <nvpair value="true" id="standby-c6d42f70-936b-47b1-ac46-2e68baae3229" /> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + </instance_attributes> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + </node> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + </nodes> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + </configuration> May 26 08:18:24 mom2 cib: [2804]: info: log_data_element: cib:diff: + </cib> May 26 08:18:24 mom2 cib: [2804]: info: cib_process_request: Operation complete: op cib_modify for section nodes (origin=local/mgmtd/175, version=0.24.1): ok (rc=0) May 26 08:18:24 mom2 cib: [7067]: info: write_cib_contents: Archived previous version as /var/lib/heartbeat/crm/cib-22.raw May 26 08:18:24 mom2 cib: [7067]: info: write_cib_contents: Wrote version 0.24.0 of the CIB to disk (digest: 04e9cd2c20512292881863b5a57e2a63) May 26 08:18:24 mom2 cib: [7067]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.6gs1Fm (digest: /var/lib/heartbeat/crm/cib.6AhhpR) May 26 08:18:24 mom2 mgmtd: [2802]: info: CIB query: cib May 26 08:19:14 mom2 crmd: [2808]: info: process_lrm_event: LRM operation resDRBD:1_monitor_20000 (call=65, rc=0, cib-update=173, confirmed=false) complete ok May 26 08:19:14 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:1_monitor_20000 (13) confirmed on mom2 (rc=0) May 26 08:19:14 mom2 crmd: [2808]: info: run_graph: ==================================================== May 26 08:19:14 mom2 crmd: [2808]: notice: run_graph: Transition 74 (Complete=1, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pengine/pe-input-28.bz2): Complete May 26 08:19:14 mom2 crmd: [2808]: info: te_graph_trigger: Transition 74 is now complete May 26 08:19:14 mom2 crmd: [2808]: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ] May 26 08:19:14 mom2 crmd: [2808]: info: do_state_transition: All 2 cluster nodes are eligible to run resources. May 26 08:19:14 mom2 crmd: [2808]: info: do_pe_invoke: Query 174: Requesting the current CIB: S_POLICY_ENGINE May 26 08:19:14 mom2 crmd: [2808]: info: do_pe_invoke_callback: Invoking the PE: ref=pe_calc-dc-1243318754-216, seq=2, quorate=1 May 26 08:19:14 mom2 pengine: [2813]: notice: unpack_config: On loss of CCM Quorum: Ignore May 26 08:19:14 mom2 pengine: [2813]: info: determine_online_status: Node mom1 is online May 26 08:19:14 mom2 pengine: [2813]: info: unpack_rsc_op: resDRBD:0_monitor_0 on mom1 returned 0 (ok) instead of the expected value: 7 (not running) May 26 08:19:14 mom2 pengine: [2813]: WARN: unpack_rsc_op: Operation resDRBD:0_monitor_0 found resource resDRBD:0 active on mom1 May 26 08:19:14 mom2 pengine: [2813]: info: unpack_status: Node mom2 is in standby-mode May 26 08:19:14 mom2 pengine: [2813]: info: determine_online_status: Node mom2 is standby May 26 08:19:14 mom2 pengine: [2813]: info: find_clone: Internally renamed resDRBD:0 on mom2 to resDRBD:1 May 26 08:19:14 mom2 pengine: [2813]: info: unpack_rsc_op: resDRBD:0_monitor_0 on mom2 returned 0 (ok) instead of the expected value: 7 (not running) May 26 08:19:14 mom2 pengine: [2813]: WARN: unpack_rsc_op: Operation resDRBD:0_monitor_0 found resource resDRBD:1 active on mom2 May 26 08:19:14 mom2 pengine: [2813]: notice: clone_print: Master/Slave Set: masterDRBD May 26 08:19:14 mom2 pengine: [2813]: notice: print_list: #011Masters: [ mom1 ] May 26 08:19:14 mom2 pengine: [2813]: notice: print_list: #011Slaves: [ mom2 ] May 26 08:19:14 mom2 pengine: [2813]: WARN: native_color: Resource resDRBD:1 cannot run anywhere May 26 08:19:14 mom2 pengine: [2813]: info: master_color: Promoting resDRBD:0 (Master mom1) May 26 08:19:14 mom2 pengine: [2813]: info: master_color: masterDRBD: Promoted 1 instances of a possible 1 to master May 26 08:19:14 mom2 pengine: [2813]: notice: LogActions: Leave resource resDRBD:0#011(Master mom1) May 26 08:19:14 mom2 pengine: [2813]: notice: LogActions: Stop resource resDRBD:1#011(mom2) May 26 08:19:14 mom2 crmd: [2808]: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ] May 26 08:19:14 mom2 crmd: [2808]: info: unpack_graph: Unpacked transition 75: 11 actions in 11 synapses May 26 08:19:14 mom2 crmd: [2808]: info: do_te_invoke: Processing graph 75 (ref=pe_calc-dc-1243318754-216) derived from /var/lib/pengine/pe-warn-269.bz2 May 26 08:19:14 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 20 fired and confirmed May 26 08:19:14 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 42: notify resDRBD:0_pre_notify_stop_0 on mom1 May 26 08:19:14 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 48: notify resDRBD:1_pre_notify_stop_0 on mom2 (local) May 26 08:19:14 mom2 crmd: [2808]: info: do_lrm_rsc_op: Performing key=48:75:0:db9daf87-c4f5-47fe-8b3d-d5e3d6842c50 op=resDRBD:1_notify_0 ) May 26 08:19:14 mom2 lrmd: [2805]: info: rsc:resDRBD:1: notify May 26 08:19:14 mom2 pengine: [2813]: WARN: process_pe_message: Transition 75: WARNINGs found during PE processing. PEngine Input stored in: /var/lib/pengine/pe-warn-269.bz2 May 26 08:19:14 mom2 pengine: [2813]: info: process_pe_message: Configuration WARNINGs found during PE processing. Please run "crm_verify -L" to identify issues. May 26 08:19:14 mom2 crmd: [2808]: info: process_lrm_event: LRM operation resDRBD:1_notify_0 (call=66, rc=0, cib-update=175, confirmed=true) complete ok May 26 08:19:14 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:1_pre_notify_stop_0 (48) confirmed on mom2 (rc=0) May 26 08:19:14 mom2 mgmtd: [2802]: info: CIB query: cib May 26 08:19:16 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:0_pre_notify_stop_0 (42) confirmed on mom1 (rc=0) May 26 08:19:16 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 21 fired and confirmed May 26 08:19:16 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 18 fired and confirmed May 26 08:19:16 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 11: stop resDRBD:1_stop_0 on mom2 (local) May 26 08:19:16 mom2 crmd: [2808]: info: do_lrm_rsc_op: Performing key=11:75:0:db9daf87-c4f5-47fe-8b3d-d5e3d6842c50 op=resDRBD:1_stop_0 ) May 26 08:19:16 mom2 lrmd: [2805]: info: rsc:resDRBD:1: stop May 26 08:19:16 mom2 crmd: [2808]: info: process_lrm_event: LRM operation resDRBD:1_monitor_20000 (call=65, rc=-2, cib-update=0, confirmed=true) Cancelled unknown exec error May 26 08:19:16 mom2 crm_master: [7143]: info: Invoked: /usr/sbin/crm_master -l reboot -D May 26 08:19:16 mom2 attrd: [2807]: info: attrd_trigger_update: Sending flush op to all hosts for: master-resDRBD:1 May 26 08:19:16 mom2 attrd: [2807]: info: attrd_perform_update: Sent delete 59: node=c6d42f70-936b-47b1-ac46-2e68baae3229, attr=master-resDRBD:1, id=status-master-resDRBD:1-c6d42f70-936b-47b1-ac46-2e68baae3229, set=(null), section=status May 26 08:19:16 mom2 crmd: [2808]: info: abort_transition_graph: te_update_diff:157 - Triggered transition abort (complete=0, tag=transient_attributes, id=c6d42f70-936b-47b1-ac46-2e68baae3229, magic=NA) : Transient attribute: removal May 26 08:19:16 mom2 crmd: [2808]: info: update_abort_priority: Abort priority upgraded from 0 to 1000000 May 26 08:19:16 mom2 crmd: [2808]: info: update_abort_priority: Abort action done superceeded by restart May 26 08:19:16 mom2 lrmd: [2805]: info: RA output: (resDRBD:1:stop:stdout) 1 Trying master-resDRBD:1=(null) delete via attrd May 26 08:19:16 mom2 kernel: [41077.637985] drbd0: peer( Primary -> Unknown ) conn( Connected -> Disconnecting ) pdsk( UpToDate -> DUnknown ) May 26 08:19:16 mom2 kernel: [41077.637985] drbd0: short read expecting header on sock: r=-512 May 26 08:19:16 mom2 kernel: [41077.640524] drbd0: asender terminated May 26 08:19:16 mom2 kernel: [41077.640524] drbd0: Terminating asender thread May 26 08:19:16 mom2 kernel: [41077.659410] drbd0: Connection closed May 26 08:19:16 mom2 kernel: [41077.659410] drbd0: conn( Disconnecting -> StandAlone ) May 26 08:19:16 mom2 kernel: [41077.659410] drbd0: receiver terminated May 26 08:19:16 mom2 kernel: [41077.659410] drbd0: Terminating receiver thread May 26 08:19:16 mom2 kernel: [41077.659410] drbd0: disk( UpToDate -> Diskless ) May 26 08:19:16 mom2 kernel: [41077.659410] drbd0: drbd_bm_resize called with capacity == 0 May 26 08:19:16 mom2 kernel: [41077.659410] drbd0: worker terminated May 26 08:19:16 mom2 kernel: [41077.659410] drbd0: Terminating worker thread May 26 08:19:16 mom2 lrmd: [2805]: info: RA output: (resDRBD:1:stop:stdout) May 26 08:19:16 mom2 crmd: [2808]: info: process_lrm_event: LRM operation resDRBD:1_stop_0 (call=67, rc=0, cib-update=176, confirmed=true) complete ok May 26 08:19:16 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:1_stop_0 (11) confirmed on mom2 (rc=0) May 26 08:19:16 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 19 fired and confirmed May 26 08:19:16 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 22 fired and confirmed May 26 08:19:16 mom2 crmd: [2808]: info: te_rsc_command: Initiating action 43: notify resDRBD:0_post_notify_stop_0 on mom1 May 26 08:19:16 mom2 attrd: [2807]: info: attrd_ha_callback: flush message from mom2 May 26 08:19:16 mom2 mgmtd: [2802]: info: CIB query: cib May 26 08:19:16 mom2 attrd: [2807]: info: attrd_ha_callback: flush message from mom1 May 26 08:19:16 mom2 crmd: [2808]: info: abort_transition_graph: te_update_diff:146 - Triggered transition abort (complete=0, tag=transient_attributes, id=a8254f3f-a97d-45d6-8da3-f72c4d2da1ba, magic=NA) : Transient attribute: update May 26 08:19:16 mom2 crmd: [2808]: info: match_graph_event: Action resDRBD:0_post_notify_stop_0 (43) confirmed on mom1 (rc=0) May 26 08:19:16 mom2 crmd: [2808]: info: te_pseudo_action: Pseudo action 23 fired and confirmed May 26 08:19:16 mom2 crmd: [2808]: info: run_graph: ==================================================== May 26 08:19:16 mom2 crmd: [2808]: notice: run_graph: Transition 75 (Complete=10, Pending=0, Fired=0, Skipped=1, Incomplete=0, Source=/var/lib/pengine/pe-warn-269.bz2): Stopped May 26 08:19:16 mom2 crmd: [2808]: info: te_graph_trigger: Transition 75 is now complete May 26 08:19:16 mom2 crmd: [2808]: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ] May 26 08:19:16 mom2 crmd: [2808]: info: do_state_transition: All 2 cluster nodes are eligible to run resources. May 26 08:19:16 mom2 crmd: [2808]: info: do_pe_invoke: Query 177: Requesting the current CIB: S_POLICY_ENGINE May 26 08:19:16 mom2 crmd: [2808]: info: do_pe_invoke_callback: Invoking the PE: ref=pe_calc-dc-1243318756-221, seq=2, quorate=1 May 26 08:19:16 mom2 pengine: [2813]: notice: unpack_config: On loss of CCM Quorum: Ignore May 26 08:19:16 mom2 pengine: [2813]: info: determine_online_status: Node mom1 is online May 26 08:19:16 mom2 pengine: [2813]: info: unpack_rsc_op: resDRBD:0_monitor_0 on mom1 returned 0 (ok) instead of the expected value: 7 (not running) May 26 08:19:16 mom2 pengine: [2813]: WARN: unpack_rsc_op: Operation resDRBD:0_monitor_0 found resource resDRBD:0 active on mom1 May 26 08:19:16 mom2 pengine: [2813]: info: unpack_status: Node mom2 is in standby-mode May 26 08:19:16 mom2 pengine: [2813]: info: determine_online_status: Node mom2 is standby May 26 08:19:16 mom2 pengine: [2813]: info: find_clone: Internally renamed resDRBD:0 on mom2 to resDRBD:1 May 26 08:19:16 mom2 pengine: [2813]: info: unpack_rsc_op: resDRBD:0_monitor_0 on mom2 returned 0 (ok) instead of the expected value: 7 (not running) May 26 08:19:16 mom2 pengine: [2813]: WARN: unpack_rsc_op: Operation resDRBD:0_monitor_0 found resource resDRBD:1 active on mom2 May 26 08:19:16 mom2 pengine: [2813]: notice: clone_print: Master/Slave Set: masterDRBD May 26 08:19:16 mom2 pengine: [2813]: notice: print_list: #011Masters: [ mom1 ] May 26 08:19:16 mom2 pengine: [2813]: notice: print_list: #011Stopped: [ resDRBD:1 ] May 26 08:19:16 mom2 pengine: [2813]: WARN: native_color: Resource resDRBD:1 cannot run anywhere May 26 08:19:16 mom2 pengine: [2813]: info: master_color: Promoting resDRBD:0 (Master mom1) May 26 08:19:16 mom2 pengine: [2813]: info: master_color: masterDRBD: Promoted 1 instances of a possible 1 to master May 26 08:19:16 mom2 pengine: [2813]: notice: LogActions: Leave resource resDRBD:0#011(Master mom1) May 26 08:19:16 mom2 pengine: [2813]: notice: LogActions: Leave resource resDRBD:1#011(Stopped) May 26 08:19:16 mom2 crmd: [2808]: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ] May 26 08:19:16 mom2 crmd: [2808]: info: unpack_graph: Unpacked transition 76: 0 actions in 0 synapses May 26 08:19:16 mom2 crmd: [2808]: info: do_te_invoke: Processing graph 76 (ref=pe_calc-dc-1243318756-221) derived from /var/lib/pengine/pe-warn-270.bz2 May 26 08:19:16 mom2 crmd: [2808]: info: run_graph: ==================================================== May 26 08:19:16 mom2 crmd: [2808]: notice: run_graph: Transition 76 (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pengine/pe-warn-270.bz2): Complete May 26 08:19:16 mom2 crmd: [2808]: info: te_graph_trigger: Transition 76 is now complete May 26 08:19:16 mom2 crmd: [2808]: info: notify_crmd: Transition 76 status: done - <null> May 26 08:19:16 mom2 crmd: [2808]: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ] May 26 08:19:16 mom2 crmd: [2808]: info: do_state_transition: Starting PEngine Recheck Timer May 26 08:19:16 mom2 pengine: [2813]: WARN: process_pe_message: Transition 76: WARNINGs found during PE processing. PEngine Input stored in: /var/lib/pengine/pe-warn-270.bz2 May 26 08:19:16 mom2 pengine: [2813]: info: process_pe_message: Configuration WARNINGs found during PE processing. Please run "crm_verify -L" to identify issues. May 26 08:19:17 mom2 mgmtd: [2802]: info: CIB query: cib May 26 08:21:25 mom2 cib: [2804]: info: cib_stats: Processed 89 operations (4382.00us average, 0% utilization) in the last 10min
_______________________________________________ Linux-HA mailing list [email protected] http://lists.linux-ha.org/mailman/listinfo/linux-ha See also: http://linux-ha.org/ReportingProblems
