[Pacemaker] crmd - set dc unset dc loop

Philippe Carbonnier Philippe.Carbonnier at vif.fr
Thu Feb 23 06:37:32 EST 2012


Hello Andreas and everybody,

Even with the new timeout : totem token:  5000, sometimes, when jboss1 
goes standby, I've this errors : cib: [12758]: ERROR: send_ais_text: 
Sending message 194: FAILED (rc=2): Library error: Connection timed out 
(110)  and after cib: [12758]: ERROR: send_ais_message: Not connected to AIS


Feb 22 14:13:45 ujboss1 crmd: [12762]: info: run_graph: 
====================================================
Feb 22 14:13:45 ujboss1 crmd: [12762]: notice: run_graph: Transition 
3285 (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0, 
Source=/var/lib/pengine/pe-input-11116.bz2): Complete
Feb 22 14:13:45 ujboss1 crmd: [12762]: info: te_graph_trigger: 
Transition 3285 is now complete
Feb 22 14:13:45 ujboss1 crmd: [12762]: info: notify_crmd: Transition 
3285 status: done - <null>
Feb 22 14:13:45 ujboss1 crmd: [12762]: info: do_state_transition: State 
transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS 
cause=C_FSA_INTERNAL origin=notify_crmd ]
Feb 22 14:13:45 ujboss1 crmd: [12762]: info: do_state_transition: 
Starting PEngine Recheck Timer
Feb 22 14:13:45 ujboss1 pengine: [12761]: info: process_pe_message: 
Transition 3285: PEngine Input stored in: 
/var/lib/pengine/pe-input-11116.bz2
Feb 22 14:17:50 ujboss1 cib: [12758]: info: cib_stats: Processed 1 
operations (0.00us average, 0% utilization) in the last 10min
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- <cib admin_epoch="0" epoch="291" num_updates="1" >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- <configuration >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- <nodes >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- <node id="ujboss1" >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- <instance_attributes id="nodes-ujboss1" >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- <nvpair value="off" id="nodes-ujboss1-standby" />
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- </instance_attributes>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- </node>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- </nodes>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- </configuration>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
- </cib>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ <cib admin_epoch="0" epoch="292" num_updates="1" >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ <configuration >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ <nodes >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ <node id="ujboss1" >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ <instance_attributes id="nodes-ujboss1" >
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ <nvpair value="on" id="nodes-ujboss1-standby" />
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ </instance_attributes>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ </node>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ </nodes>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ </configuration>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: log_data_element: cib:diff: 
+ </cib>
Feb 22 14:17:56 ujboss1 cib: [12758]: info: cib_process_request: 
Operation complete: op cib_modify for section nodes 
(origin=local/crm_attribute/4, version=0.292.1): ok (rc=0)
Feb 22 14:17:56 ujboss1 crmd: [12762]: info: abort_transition_graph: 
need_abort:59 - Triggered transition abort (complete=1) : Non-status change
Feb 22 14:17:56 ujboss1 crmd: [12762]: info: need_abort: Aborting on 
change to admin_epoch
Feb 22 14:17:56 ujboss1 crmd: [12762]: info: do_state_transition: State 
transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC 
cause=C_FSA_INTERNAL origin=abort_transition_graph ]
Feb 22 14:17:56 ujboss1 crmd: [12762]: info: do_state_transition: All 2 
cluster nodes are eligible to run resources.
Feb 22 14:17:56 ujboss1 crmd: [12762]: info: do_pe_invoke: Query 3407: 
Requesting the current CIB: S_POLICY_ENGINE
Feb 22 14:17:58 ujboss1 cib: [12758]: ERROR: send_ais_text: Sending 
message 194: FAILED (rc=2): Library error: Connection timed out (110)
Feb 22 14:17:59 ujboss1 crmd: [12762]: info: do_pe_invoke_callback: 
Invoking the PE: query=3407, ref=pe_calc-dc-1329916679-3431, seq=604, 
quorate=1
Feb 22 14:17:59 ujboss1 pengine: [12761]: notice: unpack_config: On loss 
of CCM Quorum: Ignore
Feb 22 14:17:59 ujboss1 pengine: [12761]: info: unpack_config: Node 
scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Feb 22 14:17:59 ujboss1 pengine: [12761]: info: determine_online_status: 
Node ujboss2 is online
Feb 22 14:17:59 ujboss1 pengine: [12761]: info: unpack_status: Node 
ujboss1 is in standby-mode
Feb 22 14:17:59 ujboss1 pengine: [12761]: info: determine_online_status: 
Node ujboss1 is standby
Feb 22 14:17:59 ujboss1 pengine: [12761]: notice: group_print:  Resource 
Group: vifGroup
Feb 22 14:17:59 ujboss1 pengine: [12761]: notice: native_print:      
clusterIP   (ocf::heartbeat:IPaddr2):       Started ujboss1
Feb 22 14:17:59 ujboss1 pengine: [12761]: notice: native_print:      
routing-jboss       (lsb:routing-jboss):    Started ujboss1
Feb 22 14:17:59 ujboss1 pengine: [12761]: notice: RecurringOp:  Start 
recurring monitor (30s) for clusterIP on ujboss2
Feb 22 14:17:59 ujboss1 pengine: [12761]: notice: RecurringOp:  Start 
recurring monitor (30s) for routing-jboss on ujboss2
Feb 22 14:17:59 ujboss1 pengine: [12761]: notice: LogActions: Move 
resource clusterIP    (Started ujboss1 -> ujboss2)
Feb 22 14:17:59 ujboss1 pengine: [12761]: notice: LogActions: Move 
resource routing-jboss        (Started ujboss1 -> ujboss2)
Feb 22 14:18:00 ujboss1 cib: [10032]: info: write_cib_contents: Archived 
previous version as /var/lib/heartbeat/crm/cib-56.raw
Feb 22 14:18:00 ujboss1 cib: [10032]: info: write_cib_contents: Wrote 
version 0.292.0 of the CIB to disk (digest: 
e978102f42a9b6512133008fe219e5a4)
Feb 22 14:18:00 ujboss1 cib: [10032]: info: retrieveCib: Reading cluster 
configuration from: /var/lib/heartbeat/crm/cib.2Gj3jp (digest: 
/var/lib/heartbeat/crm/cib.ipauMZ)
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: do_state_transition: State 
transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS 
cause=C_IPC_MESSAGE origin=handle_response ]
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: unpack_graph: Unpacked 
transition 3286: 11 actions in 11 synapses
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: do_te_invoke: Processing 
graph 3286 (ref=pe_calc-dc-1329916679-3431) derived from 
/var/lib/pengine/pe-input-11117.bz2
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: te_pseudo_action: Pseudo 
action 15 fired and confirmed
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: te_rsc_command: Initiating 
action 10: stop routing-jboss_stop_0 on ujboss1 (local)
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: cancel_op: operation 
monitor[67] on lsb::routing-jboss::routing-jboss for client 12762, its 
parameters: CRM_meta_interval=[30000] CRM_meta_timeout=[20000] 
crm_feature_set=[3.0.1] CRM_meta_name=[monitor]  cancelled
Feb 22 14:18:00 ujboss1 pengine: [12761]: info: process_pe_message: 
Transition 3286: PEngine Input stored in: 
/var/lib/pengine/pe-input-11117.bz2
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: do_lrm_rsc_op: Performing 
key=10:3286:0:cd17d699-5ac6-4c00-bc70-f61bba0c140c op=routing-jboss_stop_0 )
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: rsc:routing-jboss:68: stop
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: process_lrm_event: LRM 
operation routing-jboss_monitor_30000 (call=67, status=1, cib-update=0, 
confirmed=true) Cancelled
Feb 22 14:18:00 ujboss1 lrmd: [10035]: WARN: For LSB init script, no 
additional parameters are needed.
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: RA output: 
(routing-jboss:stop:stdout) Disabling traffic redirection from 
128.1.13.9 to 128.1.13.7
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: RA output: 
(routing-jboss:stop:stdout) [
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: RA output: 
(routing-jboss:stop:stdout)   OK
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: RA output: 
(routing-jboss:stop:stdout) ]
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: RA output: 
(routing-jboss:stop:stdout)
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: RA output: 
(routing-jboss:stop:stdout)

Feb 22 14:18:00 ujboss1 crmd: [12762]: info: process_lrm_event: LRM 
operation routing-jboss_stop_0 (call=68, rc=0, cib-update=3408, 
confirmed=true) ok
Feb 22 14:18:00 ujboss1 cib: [12758]: ERROR: send_ais_message: Not 
connected to AIS
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: match_graph_event: Action 
routing-jboss_stop_0 (10) confirmed on ujboss1 (rc=0)
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: te_rsc_command: Initiating 
action 7: stop clusterIP_stop_0 on ujboss1 (local)
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: cancel_op: operation 
monitor[65] on ocf::IPaddr2::clusterIP for client 12762, its parameters: 
CRM_meta_interval=[30000] ip=[128.1.13.9] cidr_netmask=[32] 
CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] CRM_meta_name=[monitor] 
iflabel=[jbossfailover]  cancelled
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: do_lrm_rsc_op: Performing 
key=7:3286:0:cd17d699-5ac6-4c00-bc70-f61bba0c140c op=clusterIP_stop_0 )
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: rsc:clusterIP:69: stop
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: process_lrm_event: LRM 
operation clusterIP_monitor_30000 (call=65, status=1, cib-update=0, 
confirmed=true) Cancelled
Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: RA output: 
(clusterIP:stop:stderr) logger: unknown facility name: none.

Feb 22 14:18:00 ujboss1 lrmd: [12759]: info: RA output: 
(clusterIP:stop:stderr) logger: unknown facility name: none.

Feb 22 14:18:00 ujboss1 crmd: [12762]: info: process_lrm_event: LRM 
operation clusterIP_stop_0 (call=69, rc=0, cib-update=3409, 
confirmed=true) ok
Feb 22 14:18:00 ujboss1 cib: [12758]: ERROR: send_ais_message: Not 
connected to AIS
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: match_graph_event: Action 
clusterIP_stop_0 (7) confirmed on ujboss1 (rc=0)
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: te_pseudo_action: Pseudo 
action 16 fired and confirmed
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: te_pseudo_action: Pseudo 
action 3 fired and confirmed
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: te_pseudo_action: Pseudo 
action 13 fired and confirmed
Feb 22 14:18:00 ujboss1 crmd: [12762]: info: te_rsc_command: Initiating 
action 8: start clusterIP_start_0 on ujboss2
Feb 22 14:18:01 ujboss1 cib: [12758]: ERROR: send_ais_message: Not 
connected to AIS
Feb 22 14:18:01 ujboss1 crmd: [12762]: info: match_graph_event: Action 
clusterIP_start_0 (8) confirmed on ujboss2 (rc=0)
Feb 22 14:18:01 ujboss1 crmd: [12762]: info: te_rsc_command: Initiating 
action 9: monitor clusterIP_monitor_30000 on ujboss2
Feb 22 14:18:01 ujboss1 crmd: [12762]: info: te_rsc_command: Initiating 
action 11: start routing-jboss_start_0 on ujboss2
Feb 22 14:18:01 ujboss1 cib: [12758]: ERROR: send_ais_message: Not 
connected to AIS




Le 19/01/2012 17:38, Philippe Carbonnier a écrit :
> Hello Andreas, all,
>
> many thanks for your help. I have change my configurations, and will 
> take you informed.
> Best regards,
> Philippe
>
> Le 19/01/2012 14:38, Andreas Kurz a écrit :
>> Hello,
>>
>> On 01/19/2012 12:21 PM, Philippe Carbonnier wrote:
>>> Hello Andreas, and others,
>>>
>>> I'm sorry not having well explain my problem (I'm french and don't speak
>>> english fluently...).
>> np .. I'm also not a native speaker ;-)
>>
>>> The loop has arrived after putting ujoss1 (not ujboss2) standy, this is
>>> why I put more log for ujboss1 and not ujboss2.
>>>
>>> I'll try to answer your questions :
>>> the network setup is simple : ujboss1 ans ujboss2 are on the same lan,
>>> without firewall between. Perhaps it's not what you was looking for?
>> hmm ... looks really like a short split brain ... default timeouts in
>> corosync are quite short at 1000ms for token lost ... try e.g. "token:
>> 5000" in the "totem" section of your corosync config.
>>
>> Regards,
>> Andreas
>>
>>
>>
>> _______________________________________________
>> Pacemaker mailing list:Pacemaker at oss.clusterlabs.org
>> http://oss.clusterlabs.org/mailman/listinfo/pacemaker
>>
>> Project Home:http://www.clusterlabs.org
>> Getting started:http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
>> Bugs:http://bugs.clusterlabs.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.clusterlabs.org/pipermail/pacemaker/attachments/20120223/4847f003/attachment-0002.html>


More information about the Pacemaker mailing list