Hi, I noticed that during the startup of Heardbeat it takes around 9 secs for ccm to be available and ready to accept connections from cib. As you can see on the below log, ccm was invoked at 14:24:53 but was up at 14:25:02, and at 14:25:03 cib was able to connect. Is it a normal behavior or I have a misconfiguration system?
Regards, Pavlos Parissis Sep 20 14:24:49 node-01 heartbeat: [9240]: info: Enabling logging daemon Sep 20 14:24:49 node-01 heartbeat: [9240]: info: logfile and debug file are those specified in logd config file (default /etc/logd.cf) Sep 20 14:24:50 node-01 heartbeat: [9240]: info: Pacemaker support: respawn Sep 20 14:24:50 node-01 heartbeat: [9240]: info: Pacemaker support: false Sep 20 14:24:50 node-01 heartbeat: [9240]: info: ************************** Sep 20 14:24:50 node-01 heartbeat: [9240]: info: Configuration validated. Starting heartbeat 3.0.2 Sep 20 14:24:50 node-01 heartbeat: [9241]: info: heartbeat: version 3.0.2 Sep 20 14:24:50 node-01 heartbeat: [9241]: info: Heartbeat generation: 1284621482 Sep 20 14:24:50 node-01 heartbeat: [9241]: info: glib: UDP multicast heartbeat started for group 239.0.0.43 port 694 interface eth0 (ttl=1 loop=0) Sep 20 14:24:50 node-01 heartbeat: [9241]: info: glib: UDP Broadcast heartbeat started on port 694 (694) interface eth1 Sep 20 14:24:50 node-01 heartbeat: [9241]: info: glib: UDP Broadcast heartbeat closed on port 694 interface eth1 - Status: 1 Sep 20 14:24:50 node-01 heartbeat: [9241]: info: G_main_add_TriggerHandler: Added signal manual handler Sep 20 14:24:50 node-01 heartbeat: [9241]: info: G_main_add_TriggerHandler: Added signal manual handler Sep 20 14:24:50 node-01 heartbeat: [9241]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Sep 20 14:24:50 node-01 heartbeat: [9241]: info: Local status now set to: 'up' Sep 20 14:24:52 node-01 heartbeat: [9241]: info: Link node-02:eth0 up. Sep 20 14:24:52 node-01 heartbeat: [9241]: info: Link node-03:eth0 up. Sep 20 14:24:52 node-01 heartbeat: [9241]: info: Status update for node node-03: status active Sep 20 14:24:52 node-01 heartbeat: [9241]: info: Link node-01:eth1 up. Sep 20 14:24:52 node-01 heartbeat: [9241]: info: Link node-02:eth1 up. Sep 20 14:24:52 node-01 heartbeat: [9241]: info: Link node-03:eth1 up. Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Comm_now_up(): updating status to active Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Local status now set to: 'active' Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Starting child client "/usr/lib/heartbeat/ccm" (103,105) Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Starting child client "/usr/lib/heartbeat/cib" (103,105) Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Starting child client "/usr/lib/heartbeat/lrmd -r" (0,0) Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Starting child client "/usr/lib/heartbeat/stonithd" (0,0) Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Starting child client "/usr/lib/heartbeat/attrd" (103,105) Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Starting child client "/usr/lib/heartbeat/crmd" (103,105) Sep 20 14:24:53 node-01 heartbeat: [9251]: info: Starting "/usr/lib/heartbeat/ccm" as uid 103 gid 105 (pid 9251) Sep 20 14:24:53 node-01 heartbeat: [9252]: info: Starting "/usr/lib/heartbeat/cib" as uid 103 gid 105 (pid 9252) Sep 20 14:24:53 node-01 heartbeat: [9253]: info: Starting "/usr/lib/heartbeat/lrmd -r" as uid 0 gid 0 (pid 9253) Sep 20 14:24:53 node-01 heartbeat: [9254]: info: Starting "/usr/lib/heartbeat/stonithd" as uid 0 gid 0 (pid 9254) Sep 20 14:24:53 node-01 heartbeat: [9255]: info: Starting "/usr/lib/heartbeat/attrd" as uid 103 gid 105 (pid 9255) Sep 20 14:24:53 node-01 heartbeat: [9256]: info: Starting "/usr/lib/heartbeat/crmd" as uid 103 gid 105 (pid 9256) Sep 20 14:24:53 node-01 stonithd: [9254]: info: G_main_add_SignalHandler: Added signal handler for signal 10 Sep 20 14:24:53 node-01 stonithd: [9254]: info: G_main_add_SignalHandler: Added signal handler for signal 12 Sep 20 14:24:53 node-01 attrd: [9255]: info: Invoked: /usr/lib/heartbeat/attrd Sep 20 14:24:53 node-01 attrd: [9255]: info: main: Starting up Sep 20 14:24:53 node-01 attrd: [9255]: info: crm_cluster_connect: Connecting to Heartbeat Sep 20 14:24:53 node-01 crmd: [9256]: info: Invoked: /usr/lib/heartbeat/crmd Sep 20 14:24:53 node-01 crmd: [9256]: info: main: CRM Hg Version: 89bd754939df5150de7cd76835f98fe90851b677 Sep 20 14:24:53 node-01 crmd: [9256]: info: crmd_init: Starting crmd Sep 20 14:24:53 node-01 crmd: [9256]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Sep 20 14:24:53 node-01 stonithd: [9254]: info: crm_cluster_connect: Connecting to Heartbeat Sep 20 14:24:53 node-01 ccm: [9251]: info: Hostname: node-01 Sep 20 14:24:53 node-01 attrd: [9255]: info: register_heartbeat_conn: Hostname: node-01 Sep 20 14:24:53 node-01 attrd: [9255]: info: register_heartbeat_conn: UUID: d5557037-cf8f-49b7-95f5-c264927a0c76 Sep 20 14:24:53 node-01 attrd: [9255]: info: main: Cluster connection active Sep 20 14:24:53 node-01 attrd: [9255]: info: main: Accepting attribute updates Sep 20 14:24:53 node-01 attrd: [9255]: info: main: Starting mainloop... Sep 20 14:24:53 node-01 stonithd: [9254]: info: register_heartbeat_conn: Hostname: node-01 Sep 20 14:24:53 node-01 stonithd: [9254]: info: register_heartbeat_conn: UUID: d5557037-cf8f-49b7-95f5-c264927a0c76 Sep 20 14:24:53 node-01 cib: [9252]: info: Invoked: /usr/lib/heartbeat/cib Sep 20 14:24:53 node-01 cib: [9252]: info: G_main_add_TriggerHandler: Added signal manual handler Sep 20 14:24:53 node-01 cib: [9252]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Sep 20 14:24:53 node-01 cib: [9252]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig) Sep 20 14:24:53 node-01 cib: [9252]: info: startCib: CIB Initialization completed successfully Sep 20 14:24:53 node-01 cib: [9252]: info: crm_cluster_connect: Connecting to Heartbeat Sep 20 14:24:53 node-01 lrmd: [9253]: info: G_main_add_SignalHandler: Added signal handler for signal 15 Sep 20 14:24:53 node-01 stonithd: [9254]: notice: /usr/lib/heartbeat/stonithd start up successfully. Sep 20 14:24:53 node-01 stonithd: [9254]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Sep 20 14:24:53 node-01 lrmd: [9253]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Sep 20 14:24:53 node-01 lrmd: [9253]: info: enabling coredumps Sep 20 14:24:53 node-01 lrmd: [9253]: info: G_main_add_SignalHandler: Added signal handler for signal 10 Sep 20 14:24:53 node-01 lrmd: [9253]: info: G_main_add_SignalHandler: Added signal handler for signal 12 Sep 20 14:24:53 node-01 lrmd: [9253]: info: Started. Sep 20 14:24:53 node-01 heartbeat: [9241]: info: Status update for node node-02: status active Sep 20 14:24:53 node-01 cib: [9252]: info: register_heartbeat_conn: Hostname: node-01 Sep 20 14:24:53 node-01 cib: [9252]: info: register_heartbeat_conn: UUID: d5557037-cf8f-49b7-95f5-c264927a0c76 Sep 20 14:24:53 node-01 cib: [9252]: info: ccm_connect: Registering with CCM... Sep 20 14:24:53 node-01 cib: [9252]: WARN: ccm_connect: CCM Activation failed Sep 20 14:24:53 node-01 cib: [9252]: WARN: ccm_connect: CCM Connection failed 1 times (30 max) Sep 20 14:24:54 node-01 crmd: [9256]: info: do_cib_control: Could not connect to the CIB service: connection failed Sep 20 14:24:54 node-01 crmd: [9256]: WARN: do_cib_control: Couldn't complete CIB registration 1 times... pause and retry Sep 20 14:24:54 node-01 crmd: [9256]: info: crmd_init: Starting crmd's mainloop Sep 20 14:24:56 node-01 crmd: [9256]: info: crm_timer_popped: Wait Timer (I_NULL) just popped! Sep 20 14:24:56 node-01 cib: [9252]: info: ccm_connect: Registering with CCM... Sep 20 14:24:56 node-01 cib: [9252]: WARN: ccm_connect: CCM Activation failed Sep 20 14:24:56 node-01 cib: [9252]: WARN: ccm_connect: CCM Connection failed 2 times (30 max) Sep 20 14:24:57 node-01 crmd: [9256]: info: do_cib_control: Could not connect to the CIB service: connection failed Sep 20 14:24:57 node-01 crmd: [9256]: WARN: do_cib_control: Couldn't complete CIB registration 2 times... pause and retry Sep 20 14:24:59 node-01 crmd: [9256]: info: crm_timer_popped: Wait Timer (I_NULL) just popped! Sep 20 14:24:59 node-01 cib: [9252]: info: ccm_connect: Registering with CCM... Sep 20 14:24:59 node-01 cib: [9252]: WARN: ccm_connect: CCM Activation failed Sep 20 14:25:00 node-01 cib: [9252]: WARN: ccm_connect: CCM Connection failed 3 times (30 max) Sep 20 14:25:00 node-01 crmd: [9256]: info: do_cib_control: Could not connect to the CIB service: connection failed Sep 20 14:25:00 node-01 crmd: [9256]: WARN: do_cib_control: Couldn't complete CIB registration 3 times... pause and retry Sep 20 14:25:02 node-01 ccm: [9251]: info: G_main_add_SignalHandler: Added signal handler for signal 15 Sep 20 14:25:02 node-01 crmd: [9256]: info: crm_timer_popped: Wait Timer (I_NULL) just popped! Sep 20 14:25:03 node-01 cib: [9252]: info: ccm_connect: Registering with CCM... Sep 20 14:25:03 node-01 cib: [9252]: info: cib_init: Requesting the list of configured nodes Sep 20 14:25:03 node-01 cib: [9252]: info: cib_init: Starting cib mainloop Sep 20 14:25:03 node-01 cib: [9252]: info: cib_client_status_callback: Status update: Client node-01/cib now has status [join] Sep 20 14:25:03 node-01 cib: [9252]: info: crm_new_peer: Node 0 is now known as node-01 Sep 20 14:25:03 node-01 cib: [9252]: info: crm_update_peer_proc: node-01.cib is now online Sep 20 14:25:03 node-01 cib: [9260]: info: write_cib_contents: Archived previous version as /var/lib/heartbeat/crm/cib-23.raw Sep 20 14:25:03 node-01 cib: [9260]: info: write_cib_contents: Wrote version 0.140.0 of the CIB to disk (digest: 8f5ae40321e7e724a46f9314e975ff81) Sep 20 14:25:03 node-01 cib: [9260]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.WMvxOC (digest: /var/lib/heartbeat/crm/cib.JeubDG) Sep 20 14:25:03 node-01 crmd: [9256]: info: do_cib_control: CIB connection established Sep 20 14:25:03 node-01 crmd: [9256]: info: crm_cluster_connect: Connecting to Heartbeat Sep 20 14:25:03 node-01 cib: [9252]: info: cib_client_status_callback: Status update: Client node-01/cib now has status [online] Sep 20 14:25:03 node-01 crmd: [9256]: info: register_heartbeat_conn: Hostname: node-01 Sep 20 14:25:03 node-01 cib: [9252]: info: cib_client_status_callback: Status update: Client node-03/cib now has status [online] Sep 20 14:25:03 node-01 crmd: [9256]: info: register_heartbeat_conn: UUID: d5557037-cf8f-49b7-95f5-c264927a0c76 Sep 20 14:25:04 node-01 cib: [9252]: info: crm_new_peer: Node 0 is now known as node-03 Sep 20 14:25:04 node-01 cib: [9252]: info: crm_update_peer_proc: node-03.cib is now online Sep 20 14:25:04 node-01 cib: [9252]: info: cib_client_status_callback: Status update: Client node-02/cib now has status [online] Sep 20 14:25:04 node-01 cib: [9252]: info: crm_new_peer: Node 0 is now known as node-02 Sep 20 14:25:04 node-01 cib: [9252]: info: crm_update_peer_proc: node-02.cib is now online Sep 20 14:25:04 node-01 cib: [9252]: WARN: cib_peer_callback: Discarding cib_apply_diff message (15b6) from node-03: not in our membership Sep 20 14:25:05 node-01 crmd: [9256]: info: do_ha_control: Connected to the cluster Sep 20 14:25:05 node-01 crmd: [9256]: info: do_ccm_control: CCM connection established... waiting for first callback Sep 20 14:25:05 node-01 crmd: [9256]: info: do_started: Delaying start, CCM (0000000000100000) not connected Sep 20 14:25:05 node-01 crmd: [9256]: info: config_query_callback: Checking for expired actions every 900000ms Sep 20 14:25:05 node-01 crmd: [9256]: notice: crmd_client_status_callback: Status update: Client node-01/crmd now has status [online] (DC=false) Sep 20 14:25:05 node-01 crmd: [9256]: info: crm_new_peer: Node 0 is now known as node-01 _______________________________________________ Linux-HA mailing list [email protected] http://lists.linux-ha.org/mailman/listinfo/linux-ha See also: http://linux-ha.org/ReportingProblems
