<div dir="ltr">One note on this.<div><br></div><div>This problem doesnt happen if</div><div><br></div><div><div>Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=true)</div><div>Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [leave] (DC=true)</div><div>Nov 19 08:36:31 node1 crmd[3298]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=true)</div></div><div><br></div><div>join happens before </div><div>Nov 19 08:36:34 node1 crmd[3298]: notice: do_state_transition: State transition S_IDLE -> S_INTEGRATION [ input=I_NODE_JOIN cause=C_FSA_INTERNAL origin=peer_update_callback ]<br></div><div><br></div><div>I am not sure why crmd join/leave & then join happens. With previous version of heartbeat/pacemaker this doesnt happen.</div><div><br></div><div>here are more logs when the problem doesnt happen</div><div><br></div><div><div>Nov 19 08:36:29 node1 heartbeat: [3143]: info: Link node2:eth0 up.</div><div>Nov 19 08:36:29 node1 heartbeat: [3143]: info: Status update for node node2: status init</div><div>Nov 19 08:36:29 node1 crmd[3298]: notice: crmd_ha_status_callback: Status update: Node node2 now has status [init]</div><div>Nov 19 08:36:29 node1 crmd[3298]: notice: crmd_ha_status_callback: Status update: Node node2 now has status [up]</div><div>Nov 19 08:36:30 node1 heartbeat: [3143]: debug: get_delnodelist: delnodelist=</div><div>Nov 19 08:36:30 node1 heartbeat: [3143]: info: Status update for node node2: status active</div><div>Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_ha_status_callback: Status update: Node node2 now has status [active]</div><div>Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=true)</div><div>Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [leave] (DC=true)</div><div>Nov 19 08:36:31 node1 crmd[3298]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=true)</div><div>Nov 19 08:36:34 node1 ccm: [3293]: debug: quorum plugin: majority</div><div>Nov 19 08:36:34 node1 ccm: [3293]: debug: cluster:linux-ha, member_count=2, member_quorum_votes=200</div><div>Nov 19 08:36:34 node1 ccm: [3293]: debug: total_node_count=2, total_quorum_votes=200</div><div>Nov 19 08:36:34 node1 cib[3294]: notice: crm_update_peer_state: crm_update_ccm_node: Node node2[1] - state is now member (was (null))</div><div>Nov 19 08:36:34 node1 crmd[3298]: notice: crm_update_peer_state: crm_update_ccm_node: Node node2[1] - state is now member (was lost)</div><div>Nov 19 08:36:34 node1 crmd[3298]: notice: do_state_transition: State transition S_IDLE -> S_INTEGRATION [ input=I_NODE_JOIN cause=C_FSA_INTERNAL origin=peer_update_callback ]</div></div><div><br></div><div>after the above, resources are started alright</div><div><div>Nov 19 08:36:40 node1 attrd[3297]: notice: attrd_local_callback: Sending full refresh (origin=crmd)</div><div>Nov 19 08:36:40 node1 attrd[3297]: notice: attrd_trigger_update: Sending flush op to all hosts for: probe_complete (true)</div><div>Nov 19 08:36:40 node1 attrd[3297]: notice: attrd_trigger_update: Sending flush op to all hosts for: master-MYSQL:0 (100)</div><div>Nov 19 08:36:41 node1 pengine[3299]: notice: unpack_config: On loss of CCM Quorum: Ignore</div><div>Nov 19 08:36:41 node1 pengine[3299]: notice: LogActions: Start IPADDR:1#011(node2)</div></div><div><br></div><div>Any help/pointers greatly apprecited.</div><div><br></div><div>Thanks.</div><div><br></div><div>--Shyam</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Mon, Nov 23, 2015 at 12:14 PM, Shyam <span dir="ltr"><<a href="mailto:shyam.kaushik@gmail.com" target="_blank">shyam.kaushik@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hi All,<div><br></div><div>Need a help w.r.t. a timing issue that I hit when using pacemaker-1.1.10 with heartbeat-3.0.5 on Ubuntu Trusty.</div><div><br></div><div><div>As seen in logs below, issue appears to be w.r.t. membership that CRMD looks at that it wrongly moves to INTEGRATION phase when the peer CRMD hasnt joined the cluster fully yet.</div></div><div><br></div><div>We have a 2 node cluster & occasionally when one of the node comes up after reboot it keeps remaining in S_PENDING state/until heartbeat/pacemaker on that node is restarted. This happens periodically & not always. </div><div><br></div><div>Below logs shows the problem clearly<br></div><div><br></div><div>ndoe1 has been running & sees node2 coming up</div><div><br></div><div><div>Nov 20 09:09:10 node1 crmd[3905]: notice: crmd_ha_status_callback: Status update: Node node2 now has status [init]</div><div>Nov 20 09:09:10 node1 crmd[3905]: notice: crmd_ha_status_callback: Status update: Node node2 now has status [up]</div><div>Nov 20 09:09:10 node1 heartbeat: [2943]: info: Link node2:eth0 up.</div><div>Nov 20 09:09:10 node1 heartbeat: [2943]: info: Status update for node node2: status init</div><div>Nov 20 09:09:10 node1 heartbeat: [2943]: info: Status update for node node2: status up</div><div>Nov 20 09:09:10 node1 heartbeat: [2943]: debug: get_delnodelist: delnodelist=</div><div>Nov 20 09:09:10 node1 heartbeat: [2943]: info: all clients are now paused</div><div>Nov 20 09:09:10 node1 crmd[3905]: notice: crmd_ha_status_callback: Status update: Node node2 now has status [active]</div><div>Nov 20 09:09:10 node1 crmd[3905]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=true)</div><div>Nov 20 09:09:10 node1 heartbeat: [2943]: info: Status update for node node2: status active</div><div>Nov 20 09:09:10 node1 crmd[3905]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [leave] (DC=true)</div><div>Nov 20 09:09:11 node1 heartbeat: [2943]: info: all clients are now resumed</div></div><div><br></div><div><br></div><div>as can be seen above, w.r.t. CRMD on peer, it registered at heartbeat & de-registered (not sure why)</div><div>Nov 20 09:09:10 node1 crmd[3905]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=true)<br></div><div>Nov 20 09:09:10 node1 crmd[3905]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [leave] (DC=true)<br></div><div><br></div><div><br></div><div>while this is the state CRMD on node1 moves to INTEGRATION phase & there are join requests flowing through, but presume I cannot be handled by peer</div><div><br></div><div><div>Nov 20 09:09:13 node1 cib[3901]: notice: crm_update_peer_state: crm_update_ccm_node: Node node2[0] - state is now member (was (null))</div><div>Nov 20 09:09:13 node1 crmd[3905]: notice: crm_update_peer_state: crm_update_ccm_node: Node node2[0] - state is now member (was lost)</div><div>Nov 20 09:09:13 node1 crmd[3905]: notice: do_state_transition: State transition S_IDLE -> S_INTEGRATION [ input=I_NODE_JOIN cause=C_FSA_INTERNAL origin=peer_update_callback ]</div><div>Nov 20 09:09:13 node1 ccm: [3900]: debug: quorum plugin: majority</div><div>Nov 20 09:09:13 node1 ccm: [3900]: debug: cluster:linux-ha, member_count=2, member_quorum_votes=200</div><div>Nov 20 09:09:13 node1 ccm: [3900]: debug: total_node_count=2, total_quorum_votes=200</div><div>Nov 20 09:09:13 node1 crmd[3905]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=true)</div><div>Nov 20 09:09:13 node1 crmd[3905]: warning: match_down_event: No match for shutdown action on 00000432-0432-0000-2b91-000000000000</div><div>Nov 20 09:09:13 node1 crmd[3905]: notice: peer_update_callback: Stonith/shutdown of node2 not matched</div><div>Nov 20 09:09:13 node1 attrd[3904]: notice: attrd_local_callback: Sending full refresh (origin=crmd)</div><div>Nov 20 09:09:13 node1 attrd[3904]: notice: attrd_trigger_update: Sending flush op to all hosts for: probe_complete (true)</div><div>Nov 20 09:09:13 node1 attrd[3904]: notice: attrd_trigger_update: Sending flush op to all hosts for: master-MYSQL:0 (100)</div><div>Nov 20 09:09:13 node1 pengine[3906]: notice: unpack_config: On loss of CCM Quorum: Ignore</div><div>Nov 20 09:09:13 node1 pengine[3906]: warning: custom_action: Action IPADDR:0_monitor_0 on node2 is unrunnable (pending)</div></div><div><br></div><div><br></div><div>As can be seen we had</div><div>Nov 20 09:09:13 node1 crmd[3905]: notice: do_state_transition: State transition S_IDLE -> S_INTEGRATION [ input=I_NODE_JOIN cause=C_FSA_INTERNAL <br></div><div><br></div><div>& only then CRMD on peer seems to be alright</div><div><div>Nov 20 09:09:13 node1 crmd[3905]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=true)</div></div><div><br></div><div>so pengine decided not being able to run any resources & we are stuck in this state. While node2 has this trace</div><div><div>Nov 20 09:09:13 node2 cib[2964]: notice: cib_server_process_diff: Not applying diff 1.3.33 -> 1.3.34 (sync in progress)</div><div>Nov 20 09:09:13 node2 cib[2964]: notice: crm_update_peer_state: crm_update_ccm_node: Node node1[1] - state is now member (was (null))</div><div>Nov 20 09:09:13 node2 cib[2964]: notice: crm_update_peer_state: crm_update_ccm_node: Node node2[0] - state is now member (was (null))</div><div>Nov 20 09:09:13 node2 crmd[2968]: notice: crm_cluster_connect: Connecting to cluster infrastructure: heartbeat</div><div>Nov 20 09:09:14 node2 heartbeat: [2938]: info: the send queue length from heartbeat to client crmd is set to 1024</div><div>Nov 20 09:09:15 node2 crmd[2968]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [join] (DC=false)</div><div>Nov 20 09:09:15 node2 crmd[2968]: notice: crmd_client_status_callback: Status update: Client node2/crmd now has status [online] (DC=false)</div><div>Nov 20 09:09:15 node2 crmd[2968]: notice: crmd_client_status_callback: Status update: Client node1/crmd now has status [online] (DC=false)</div><div>Nov 20 09:09:16 node2 crmd[2968]: notice: crm_update_peer_state: crm_update_ccm_node: Node node1[1] - state is now member (was (null))</div><div>Nov 20 09:09:16 node2 crmd[2968]: notice: crm_update_peer_state: crm_update_ccm_node: Node node2[0] - state is now member (was (null))</div><div>Nov 20 09:09:16 node2 crmd[2968]: notice: do_started: The local CRM is operational</div><div>Nov 20 09:09:16 node2 crmd[2968]: notice: do_state_transition: State transition S_STARTING -> S_PENDING [ input=I_PENDING cause=C_FSA_INTERNAL origin=do_started ]</div><div>Nov 20 09:09:27 node2 crmd[2968]: warning: do_log: FSA: Input I_DC_TIMEOUT from crm_timer_popped() received in state S_PENDING</div></div><div><br></div><div><br></div><div>i.e. it moves to S_PENDING state & keeps receiving I_DC_TIMEOUT</div><div><br></div><div>I tried using latest heartbeat, but that doesnt seem to be the problem. Can anyone suggest if this issue has already been fixed in latest pacemaker or any other suggestions how to debug this issue?</div><div><br></div><div>If I enable higher debug level (both in heartbeat/pacemaker), this problem doesnt show up. Any help/pointers on how to go forward is greatly appreciated.</div><div><br></div><div>Thanks!</div><span class="HOEnZb"><font color="#888888"><div><br></div><div>--Shyam</div></font></span></div>
</blockquote></div><br></div>