On Wed, 2010-12-29 at 12:56 +0100, Dejan Muhamedagic wrote: > > Dec 28 09:19:18 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: > > Performing key=21:2:0:fb701221-ba59-4de8-88dc-032cab9ec090 > > op=vmgroup1:0_stop_0 ) > > Dec 28 09:19:18 vmserve.scd.ucar.edu lrmd: [7514]: info: > > rsc:vmgroup1:0:30: stop > > Dec 28 09:19:18 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: > > Performing key=50:2:0:fb701221-ba59-4de8-88dc-032cab9ec090 > > op=vmgroup2:0_stop_0 ) > > Dec 28 09:19:18 vmserve.scd.ucar.edu lrmd: [7514]: info: > > rsc:vmgroup2:0:31: stop > > Dec 28 09:19:18 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed > > vmgroup1:0:stop process 8088 exited with return code 6. > > Dec 28 09:19:18 vmserve.scd.ucar.edu crmd: [7518]: info: > > process_lrm_event: LRM operation vmgroup1:0_stop_0 (call=30, rc=6, > > cib-update=36, confirmed=true) not configured > > Dec 28 09:19:18 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed > > vmgroup2:0:stop process 8089 exited with return code 6. > > No messages from the drbd RA?
Nothing that I can see. It looks, however, like the same kind of error is occurring with many or all of the resources. I have attached the complete halog entries for the time period in question. > This smells like a bug found in 1.0.9 which should've been > fixed a while ago: > > http://developerbugs.linux-foundation.org/show_bug.cgi?id=2458 After reading that report, it doesn't look like the same problem to me, but I will freely admit that the logs are hard for me to interpret. There are entries like this showing what appear to be the correct parameters: Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[10] on ocf::LVM::DRBDVG0 for client 7518, its parameters: volgrpname=[DRBDVG0] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms > > If it's not a resource problem (i.e. drbd), please either reopen > the bugzilla above or open a new one if it looks like a different > problem. Don't forget to attach hb_report. If you don't see anything obvious in the attached more complete log, I will gladly do so. In the meantime, I may have to downgrade pacemaker so that I can get my cluster back. We are running in non-HA mode right now. --Greg
Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: respawn directive: hacluster /usr/lib64/heartbeat/ipfail Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: Pacemaker support: respawn Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: WARN: File /etc/ha.d//haresources exists. Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: WARN: This file is not used because crm is enabled Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: respawn directive: hacluster /usr/lib64/heartbeat/ccm Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: respawn directive: hacluster /usr/lib64/heartbeat/cib Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: respawn directive: root /usr/lib64/heartbeat/lrmd -r Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: respawn directive: root /usr/lib64/heartbeat/stonithd Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: respawn directive: hacluster /usr/lib64/heartbeat/attrd Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: respawn directive: hacluster /usr/lib64/heartbeat/crmd Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: AUTH: i=1: key = 0xd472250, auth=0x2abe40ad76f0, authname=sha1 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: Pacemaker support: false Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: WARN: Logging daemon is disabled --enabling logging daemon is recommended Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: ************************** Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: Configuration validated. Starting heartbeat 3.0.2 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7139]: info: Heartbeat Hg Version: node: 7153d58dcb99ff4251449c5404754e26ee1af48e Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: heartbeat: version 3.0.2 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: Heartbeat generation: 1265221099 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: glib: UDP Broadcast heartbeat started on port 694 (694) interface eth0 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: glib: UDP Broadcast heartbeat closed on port 694 interface eth0 - Status: 1 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: glib: UDP Broadcast heartbeat started on port 694 (694) interface eth3 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: glib: UDP Broadcast heartbeat closed on port 694 interface eth3 - Status: 1 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: glib: ping group heartbeat started. Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: glib: ping group heartbeat started. Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: G_main_add_TriggerHandler: Added signal manual handler Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: G_main_add_TriggerHandler: Added signal manual handler Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: Local status now set to: 'up' Dec 28 09:18:54 vmserve.scd.ucar.edu heartbeat: [7152]: info: Managed write_hostcachedata process 7200 exited with return code 0. Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Link vmserve2.scd.ucar.edu:eth0 up. Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Status update for node vmserve2.scd.ucar.edu: status active Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Link vmserve2.scd.ucar.edu:eth3 up. Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Link net_64:net_64 up. Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Status update for node net_64: status ping Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Link net_8:net_8 up. Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Status update for node net_8: status ping Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Link vmserve.scd.ucar.edu:eth3 up. Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Link vmserve.scd.ucar.edu:eth0 up. Dec 28 09:18:55 vmserve.scd.ucar.edu heartbeat: [7152]: info: Managed write_hostcachedata process 7349 exited with return code 0. Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Comm_now_up(): updating status to active Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Local status now set to: 'active' Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Starting child client "/usr/lib64/heartbeat/ipfail" (498,496) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Starting child client "/usr/lib64/heartbeat/ccm" (498,496) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Starting child client "/usr/lib64/heartbeat/cib" (498,496) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Starting child client "/usr/lib64/heartbeat/lrmd -r" (0,0) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Starting child client "/usr/lib64/heartbeat/stonithd" (0,0) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Starting child client "/usr/lib64/heartbeat/attrd" (498,496) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Starting child client "/usr/lib64/heartbeat/crmd" (498,496) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7514]: info: Starting "/usr/lib64/heartbeat/lrmd -r" as uid 0 gid 0 (pid 7514) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7516]: info: Starting "/usr/lib64/heartbeat/stonithd" as uid 0 gid 0 (pid 7516) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7512]: info: Starting "/usr/lib64/heartbeat/cib" as uid 498 gid 496 (pid 7512) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7510]: info: Starting "/usr/lib64/heartbeat/ipfail" as uid 498 gid 496 (pid 7510) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7511]: info: Starting "/usr/lib64/heartbeat/ccm" as uid 498 gid 496 (pid 7511) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7517]: info: Starting "/usr/lib64/heartbeat/attrd" as uid 498 gid 496 (pid 7517) Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Managed write_delcachedata process 7520 exited with return code 0. Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7518]: info: Starting "/usr/lib64/heartbeat/crmd" as uid 498 gid 496 (pid 7518) Dec 28 09:18:56 vmserve.scd.ucar.edu lrmd: [7514]: info: G_main_add_SignalHandler: Added signal handler for signal 15 Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: Managed write_hostcachedata process 7519 exited with return code 0. Dec 28 09:18:56 vmserve.scd.ucar.edu ccm: [7511]: info: Hostname: vmserve.scd.ucar.edu Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: ERROR: api_process_request: bad request [getrsc] Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: ERROR: MSG: Dumping message with 5 fields Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: ERROR: MSG[0] : [t=hbapi-req] Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: ERROR: MSG[1] : [reqtype=getrsc] Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: ERROR: MSG[2] : [dest=vmserve.scd.ucar.edu] Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: ERROR: MSG[3] : [pid=7510] Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: ERROR: MSG[4] : [from_id=ipfail] Dec 28 09:18:56 vmserve.scd.ucar.edu ipfail: [7510]: ERROR: No managed resources Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: WARN: Managed /usr/lib64/heartbeat/ipfail process 7510 exited with return code 100. Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: ERROR: Client /usr/lib64/heartbeat/ipfail exited with return code 100. Dec 28 09:18:56 vmserve.scd.ucar.edu ccm: [7511]: info: G_main_add_SignalHandler: Added signal handler for signal 15 Dec 28 09:18:56 vmserve.scd.ucar.edu attrd: [7517]: info: Invoked: /usr/lib64/heartbeat/attrd Dec 28 09:18:56 vmserve.scd.ucar.edu attrd: [7517]: info: main: Starting up Dec 28 09:18:56 vmserve.scd.ucar.edu stonithd: [7516]: info: G_main_add_SignalHandler: Added signal handler for signal 10 Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: Invoked: /usr/lib64/heartbeat/cib Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: G_main_add_TriggerHandler: Added signal manual handler Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Dec 28 09:18:56 vmserve.scd.ucar.edu attrd: [7517]: info: register_heartbeat_conn: Hostname: vmserve.scd.ucar.edu Dec 28 09:18:56 vmserve.scd.ucar.edu attrd: [7517]: info: register_heartbeat_conn: UUID: 6f5ced83-a790-4519-8449-3d4cf43275b0 Dec 28 09:18:56 vmserve.scd.ucar.edu stonithd: [7516]: info: G_main_add_SignalHandler: Added signal handler for signal 12 Dec 28 09:18:56 vmserve.scd.ucar.edu attrd: [7517]: info: crm_cluster_connect: Connecting to Heartbeat Dec 28 09:18:56 vmserve.scd.ucar.edu attrd: [7517]: info: main: Cluster connection active Dec 28 09:18:56 vmserve.scd.ucar.edu lrmd: [7514]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Dec 28 09:18:56 vmserve.scd.ucar.edu attrd: [7517]: info: main: Accepting attribute updates Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig) Dec 28 09:18:56 vmserve.scd.ucar.edu lrmd: [7514]: info: enabling coredumps Dec 28 09:18:56 vmserve.scd.ucar.edu attrd: [7517]: info: main: Starting mainloop... Dec 28 09:18:56 vmserve.scd.ucar.edu lrmd: [7514]: info: G_main_add_SignalHandler: Added signal handler for signal 10 Dec 28 09:18:56 vmserve.scd.ucar.edu crmd: [7518]: info: Invoked: /usr/lib64/heartbeat/crmd Dec 28 09:18:56 vmserve.scd.ucar.edu lrmd: [7514]: info: G_main_add_SignalHandler: Added signal handler for signal 12 Dec 28 09:18:56 vmserve.scd.ucar.edu crmd: [7518]: info: main: CRM Hg Version: da7075976b5ff0bee71074385f8fd02f296ec8a3 Dec 28 09:18:56 vmserve.scd.ucar.edu crmd: [7518]: info: crmd_init: Starting crmd Dec 28 09:18:56 vmserve.scd.ucar.edu lrmd: [7514]: info: Started. Dec 28 09:18:56 vmserve.scd.ucar.edu crmd: [7518]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: the send queue length from heartbeat to client attrd is set to 1024 Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: startCib: CIB Initialization completed successfully Dec 28 09:18:56 vmserve.scd.ucar.edu stonithd: [7516]: info: register_heartbeat_conn: Hostname: vmserve.scd.ucar.edu Dec 28 09:18:56 vmserve.scd.ucar.edu stonithd: [7516]: info: register_heartbeat_conn: UUID: 6f5ced83-a790-4519-8449-3d4cf43275b0 Dec 28 09:18:56 vmserve.scd.ucar.edu stonithd: [7516]: info: crm_cluster_connect: Connecting to Heartbeat Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: the send queue length from heartbeat to client stonithd is set to 1024 Dec 28 09:18:56 vmserve.scd.ucar.edu stonithd: [7516]: notice: /usr/lib64/heartbeat/stonithd start up successfully. Dec 28 09:18:56 vmserve.scd.ucar.edu stonithd: [7516]: info: G_main_add_SignalHandler: Added signal handler for signal 17 Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: register_heartbeat_conn: Hostname: vmserve.scd.ucar.edu Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: register_heartbeat_conn: UUID: 6f5ced83-a790-4519-8449-3d4cf43275b0 Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: crm_cluster_connect: Connecting to Heartbeat Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: ccm_connect: Registering with CCM... Dec 28 09:18:56 vmserve.scd.ucar.edu cib: [7512]: info: cib_init: Requesting the list of configured nodes Dec 28 09:18:56 vmserve.scd.ucar.edu heartbeat: [7152]: info: the send queue length from heartbeat to client cib is set to 1024 Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: cib_init: Starting cib mainloop Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: cib_client_status_callback: Status update: Client vmserve.scd.ucar.edu/cib now has status [join] Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: crm_new_peer: Node 0 is now known as vmserve.scd.ucar.edu Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: crm_update_peer_proc: vmserve.scd.ucar.edu.cib is now online Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7541]: info: write_cib_contents: Archived previous version as /var/lib/heartbeat/crm/cib-92.raw Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7541]: info: write_cib_contents: Wrote version 0.1120.0 of the CIB to disk (digest: 91e8ddfbb03058a78c71317eefc6e93c) Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7541]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.cn2IsJ (digest: /var/lib/heartbeat/crm/cib.jwBjmb) Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: Managed write_cib_contents process 7541 exited with return code 0. Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: cib_client_status_callback: Status update: Client vmserve.scd.ucar.edu/cib now has status [online] Dec 28 09:18:57 vmserve.scd.ucar.edu crmd: [7518]: info: do_cib_control: CIB connection established Dec 28 09:18:57 vmserve.scd.ucar.edu crmd: [7518]: info: register_heartbeat_conn: Hostname: vmserve.scd.ucar.edu Dec 28 09:18:57 vmserve.scd.ucar.edu crmd: [7518]: info: register_heartbeat_conn: UUID: 6f5ced83-a790-4519-8449-3d4cf43275b0 Dec 28 09:18:57 vmserve.scd.ucar.edu crmd: [7518]: info: crm_cluster_connect: Connecting to Heartbeat Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: cib_client_status_callback: Status update: Client vmserve2.scd.ucar.edu/cib now has status [online] Dec 28 09:18:57 vmserve.scd.ucar.edu heartbeat: [7152]: info: the send queue length from heartbeat to client crmd is set to 1024 Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: crm_new_peer: Node 0 is now known as vmserve2.scd.ucar.edu Dec 28 09:18:57 vmserve.scd.ucar.edu cib: [7512]: info: crm_update_peer_proc: vmserve2.scd.ucar.edu.cib is now online Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: do_ha_control: Connected to the cluster Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: do_ccm_control: CCM connection established... waiting for first callback Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: do_started: Delaying start, CCM (0000000000100000) not connected Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: crmd_init: Starting crmd's mainloop Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: config_query_callback: Checking for expired actions every 900000ms Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: notice: crmd_client_status_callback: Status update: Client vmserve.scd.ucar.edu/crmd now has status [online] (DC=false) Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: crm_new_peer: Node 0 is now known as vmserve.scd.ucar.edu Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: crm_update_peer_proc: vmserve.scd.ucar.edu.crmd is now online Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: crmd_client_status_callback: Not the DC Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: notice: crmd_client_status_callback: Status update: Client vmserve.scd.ucar.edu/crmd now has status [online] (DC=false) Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: crmd_client_status_callback: Not the DC Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: notice: crmd_client_status_callback: Status update: Client vmserve2.scd.ucar.edu/crmd now has status [online] (DC=false) Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: crm_new_peer: Node 0 is now known as vmserve2.scd.ucar.edu Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: crm_update_peer_proc: vmserve2.scd.ucar.edu.crmd is now online Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: crmd_client_status_callback: Not the DC Dec 28 09:18:58 vmserve.scd.ucar.edu crmd: [7518]: info: do_started: Delaying start, CCM (0000000000100000) not connected Dec 28 09:19:01 vmserve.scd.ucar.edu attrd: [7517]: info: cib_connect: Connected to the CIB after 1 signon attempts Dec 28 09:19:01 vmserve.scd.ucar.edu attrd: [7517]: info: cib_connect: Sending full refresh Dec 28 09:19:05 vmserve.scd.ucar.edu cib: [7512]: WARN: cib_peer_callback: Discarding cib_apply_diff message (2eb) from vmserve2.scd.ucar.edu: not in our membership Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: WARN: cib_peer_callback: Discarding cib_apply_diff message (2ed) from vmserve2.scd.ucar.edu: not in our membership Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: mem_handle_event: instance=14, nodes=2, new=2, lost=0, n_idx=0, new_idx=0, old_idx=4 Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=14) Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: ccm_event_detail: NEW MEMBERSHIP: trans=14, nodes=2, new=2, lost=0 n_idx=0, new_idx=0, old_idx=4 Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: ccm_event_detail: CURRENT: vmserve2.scd.ucar.edu [nodeid=1, born=12] Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: ccm_event_detail: CURRENT: vmserve.scd.ucar.edu [nodeid=0, born=14] Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: mem_handle_event: instance=14, nodes=2, new=2, lost=0, n_idx=0, new_idx=0, old_idx=4 Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: ccm_event_detail: NEW: vmserve2.scd.ucar.edu [nodeid=1, born=12] Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: cib_ccm_msg_callback: Processing CCM event=NEW MEMBERSHIP (id=14) Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: ccm_event_detail: NEW: vmserve.scd.ucar.edu [nodeid=0, born=14] Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: crm_get_peer: Node vmserve2.scd.ucar.edu now has id: 1 Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: crm_get_peer: Node vmserve2.scd.ucar.edu now has id: 1 Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: crm_update_peer: Node vmserve2.scd.ucar.edu: id=1 state=member (new) addr=(null) votes=-1 born=12 seen=14 proc=00000000000000000000000000000100 Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: crm_update_peer: Node vmserve2.scd.ucar.edu: id=1 state=member (new) addr=(null) votes=-1 born=12 seen=14 proc=00000000000000000000000000000200 Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: crm_update_peer_proc: vmserve2.scd.ucar.edu.ais is now online Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: crm_update_peer_proc: vmserve2.scd.ucar.edu.ais is now online Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: crm_update_peer_proc: vmserve2.scd.ucar.edu.crmd is now online Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: crm_update_peer: Node vmserve.scd.ucar.edu: id=0 state=member (new) addr=(null) votes=-1 born=14 seen=14 proc=00000000000000000000000000000200 Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: crm_update_peer: Node vmserve.scd.ucar.edu: id=0 state=member (new) addr=(null) votes=-1 born=14 seen=14 proc=00000000000000000000000000000100 Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: crm_update_peer_proc: vmserve.scd.ucar.edu.ais is now online Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: crm_update_peer_proc: vmserve.scd.ucar.edu.ais is now online Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: crm_update_peer_proc: vmserve.scd.ucar.edu.crmd is now online Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: do_started: The local CRM is operational Dec 28 09:19:06 vmserve.scd.ucar.edu crmd: [7518]: info: do_state_transition: State transition S_STARTING -> S_PENDING [ input=I_PENDING cause=C_FSA_INTERNAL origin=do_started ] Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: cib_process_diff: Diff 0.1122.3 -> 0.1122.4 not applied to 0.1120.0: current "epoch" is less than required Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: info: cib_server_process_diff: Requesting re-sync from peer Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: WARN: cib_diff_notify: Local-only Change (client:crmd, call: 115): -1.-1.-1 (Application of an update diff failed, requesting a full refresh) Dec 28 09:19:06 vmserve.scd.ucar.edu cib: [7512]: WARN: cib_server_process_diff: Not applying diff 0.1122.4 -> 0.1122.5 (sync in progress) Dec 28 09:19:07 vmserve.scd.ucar.edu cib: [7512]: info: cib_replace_notify: Local-only Replace: -1.-1.-1 from vmserve2.scd.ucar.edu Dec 28 09:19:07 vmserve.scd.ucar.edu attrd: [7517]: info: do_cib_replaced: Sending full refresh Dec 28 09:19:07 vmserve.scd.ucar.edu cib: [7550]: info: write_cib_contents: Archived previous version as /var/lib/heartbeat/crm/cib-93.raw Dec 28 09:19:07 vmserve.scd.ucar.edu cib: [7550]: info: write_cib_contents: Wrote version 0.1122.0 of the CIB to disk (digest: a4ba0f6ce7bee9d9a0899db28897983a) Dec 28 09:19:07 vmserve.scd.ucar.edu cib: [7550]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.1vLfvB (digest: /var/lib/heartbeat/crm/cib.nNLKqu) Dec 28 09:19:07 vmserve.scd.ucar.edu cib: [7512]: info: Managed write_cib_contents process 7550 exited with return code 0. Dec 28 09:19:07 vmserve.scd.ucar.edu crmd: [7518]: info: update_dc: Set DC to vmserve2.scd.ucar.edu (3.0.1) Dec 28 09:19:09 vmserve.scd.ucar.edu crmd: [7518]: info: update_attrd: Connecting to attrd... Dec 28 09:19:09 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for terminate Dec 28 09:19:09 vmserve.scd.ucar.edu crmd: [7518]: info: do_state_transition: State transition S_PENDING -> S_NOT_DC [ input=I_NOT_DC cause=C_HA_MESSAGE origin=do_cl_join_finalize_respond ] Dec 28 09:19:09 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for shutdown Dec 28 09:19:09 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_local_callback: Sending full refresh (origin=crmd) Dec 28 09:19:09 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_trigger_update: Sending flush op to all hosts for: terminate (<null>) Dec 28 09:19:09 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_trigger_update: Sending flush op to all hosts for: shutdown (<null>) Dec 28 09:19:09 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve.scd.ucar.edu Dec 28 09:19:09 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve.scd.ucar.edu Dec 28 09:19:10 vmserve.scd.ucar.edu crmd: [7518]: info: erase_xpath_callback: Deletion of "//node_sta...@uname='vmserve.scd.ucar.edu']/transient_attributes": ok (rc=0) Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for fail-count-VM-kpasswd Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for ping Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for master-vmgroup1:0 Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for probe_complete Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: lrmd_rsc_new(): No lrm_rprovider field in message Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=13:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=stonith-vm1-manual_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for fail-count-fs1 Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:stonith-vm1-manual:2: probe Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: lrmd_rsc_new(): No lrm_rprovider field in message Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=14:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=stonith-vm2-manual_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for master-vmgroup1:1 Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:stonith-vm2-manual:3: probe Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for last-failure-ldirectord Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: lrmd_rsc_new(): No lrm_rprovider field in message Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=15:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=stonith-vm1_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for fail-count-VM-paranfsvm Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:stonith-vm1:4: probe Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for master-vmgroup2:0 Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed stonith-vm1-manual:monitor process 7554 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: lrmd_rsc_new(): No lrm_rprovider field in message Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for last-failure-fs1 Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=16:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=stonith-vm2_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:stonith-vm2:5: probe Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for master-vmgroup2:1 Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for last-failure-VM-kpasswd Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed stonith-vm2-manual:monitor process 7555 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_ha_callback: flush message from vmserve2.scd.ucar.edu Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: find_hash_entry: Creating hash entry for fail-count-ldirectord Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=17:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=vmgroup1:0_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vmgroup1:0:6: probe Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed stonith-vm1:monitor process 7557 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=18:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=vmgroup2:0_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vmgroup2:0:7: probe Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed stonith-vm2:monitor process 7559 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=19:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=vm-ip1_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vm-ip1:8: probe Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=20:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=vm-ip2_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vm-ip2:9: probe Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=21:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=DRBDVG0_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[10] on ocf::LVM::DRBDVG0 for client 7518, its parameters: volgrpname=[DRBDVG0] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=22:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=DRBDVG1_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[11] on ocf::LVM::DRBDVG1 for client 7518, its parameters: volgrpname=[DRBDVG1] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=23:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=fs1_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[12] on ocf::Filesystem::fs1 for client 7518, its parameters: directory=[/vmgroup1] fstype=[ext3] device=[/dev/DRBDVG0/VMLV1] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=24:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=fs2_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[13] on ocf::Filesystem::fs2 for client 7518, its parameters: directory=[/vmgroup2] fstype=[ext3] device=[/dev/DRBDVG1/VMLV2] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: lrmd_rsc_new(): No lrm_rprovider field in message Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=25:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=nfs-exports-1_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[14] on heartbeat::nfsexport::nfs-exports-1 for client 7518, its parameters: 1=[192.168.203.0/24:/share1] 2=[rw,no_root_squash,insecure] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed vm-ip1:monitor process 7564 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed vm-ip2:monitor process 7565 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: lrmd_rsc_new(): No lrm_rprovider field in message Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=26:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=nfs-exports-2_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:nfs-exports-2:15: probe Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=27:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=share1_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:share1:16: probe Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=28:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=share2_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[17] on ocf::Filesystem::share2 for client 7518, its parameters: directory=[/share2] fstype=[ext3] device=[/dev/DRBDVG1/SHARELV2] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed nfs-exports-2:monitor process 7604 exited with return code 1. Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: CRIT: read_pipe:3812 Attempt to read from closed file descriptor 8. Dec 28 09:19:13 vmserve.scd.ucar.edu crm_attribute: [7657]: info: determine_host: Mapped vmserve.scd.ucar.edu to 6f5ced83-a790-4519-8449-3d4cf43275b0 Dec 28 09:19:13 vmserve.scd.ucar.edu crm_attribute: [7657]: info: attrd_lazy_update: Connecting to cluster... 5 retries remaining Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: read_pipe::3818: lrmd_op has been freed Dec 28 09:19:13 vmserve.scd.ucar.edu crm_attribute: [7657]: info: main: Update master-vmgroup1:0=10000 sent via attrd Dec 28 09:19:13 vmserve.scd.ucar.edu crm_attribute: [7658]: info: determine_host: Mapped vmserve.scd.ucar.edu to 6f5ced83-a790-4519-8449-3d4cf43275b0 Dec 28 09:19:13 vmserve.scd.ucar.edu crm_attribute: [7658]: info: attrd_lazy_update: Connecting to cluster... 5 retries remaining Dec 28 09:19:13 vmserve.scd.ucar.edu crm_attribute: [7658]: info: main: Update master-vmgroup2:0=10000 sent via attrd Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_trigger_update: Sending flush op to all hosts for: master-vmgroup1:0 (10000) Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=29:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=vmnfs:0_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vmnfs:0:18: probe Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_perform_update: Sent update 23: master-vmgroup1:0=10000 Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_trigger_update: Sending flush op to all hosts for: master-vmgroup2:0 (10000) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: lrmd_rsc_new(): No lrm_rprovider field in message Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=30:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=xend:0_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_perform_update: Sent update 26: master-vmgroup2:0=10000 Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[19] on heartbeat::xend::xend:0 for client 7518, its parameters: CRM_meta_timeout=[20000] CRM_meta_clone_max=[2] crm_feature_set=[3.0.1] CRM_meta_globally_unique=[false] CRM_meta_clone=[0] CRM_meta_clone_node_max=[1] CRM_meta_notify=[false] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: Managed vmgroup1:0:monitor process 7561 exited with return code 0. Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: Managed vmgroup2:0:monitor process 7563 exited with return code 0. Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=31:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=ping:0_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:ping:0:20: probe Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=32:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=dns_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:dns:21: probe Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed share1:monitor process 7625 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=33:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=dhcp_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:dhcp:22: probe Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=34:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=VM-kpasswd_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[23] on ocf::Xen::VM-kpasswd for client 7518, its parameters: xmfile=[/etc/xen/kpasswd] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=35:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=pdu-ip1_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[24] on ocf::IPaddr::pdu-ip1 for client 7518, its parameters: ip=[192.168.14.3] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=36:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=pdu-ip2_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[25] on ocf::IPaddr::pdu-ip2 for client 7518, its parameters: ip=[192.168.14.4] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed dns:monitor process 7713 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=37:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=VM-csgvm_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:VM-csgvm:26: probe Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed dhcp:monitor process 7717 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=38:1:7:fb701221-ba59-4de8-88dc-032cab9ec090 op=VM-printserver_monitor_0 ) Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:VM-printserver:27: probe Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed vmnfs:0:monitor process 7683 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation stonith-vm1-manual_monitor_0 (call=2, rc=7, cib-update=8, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation stonith-vm2-manual_monitor_0 (call=3, rc=7, cib-update=9, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation stonith-vm1_monitor_0 (call=4, rc=7, cib-update=10, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation stonith-vm2_monitor_0 (call=5, rc=7, cib-update=11, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vm-ip1_monitor_0 (call=8, rc=7, cib-update=12, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vm-ip2_monitor_0 (call=9, rc=7, cib-update=13, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation nfs-exports-2_monitor_0 (call=15, rc=7, cib-update=14, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vmgroup1:0_monitor_0 (call=6, rc=0, cib-update=15, confirmed=true) ok Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vmgroup2:0_monitor_0 (call=7, rc=0, cib-update=16, confirmed=true) ok Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation share1_monitor_0 (call=16, rc=7, cib-update=17, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation dns_monitor_0 (call=21, rc=7, cib-update=18, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed ping:0:monitor process 7699 exited with return code 7. Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation dhcp_monitor_0 (call=22, rc=7, cib-update=19, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vmnfs:0_monitor_0 (call=18, rc=7, cib-update=20, confirmed=true) not running Dec 28 09:19:13 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation ping:0_monitor_0 (call=20, rc=7, cib-update=21, confirmed=true) not running Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed VM-csgvm:monitor process 7739 exited with return code 7. Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed VM-printserver:monitor process 7754 exited with return code 7. Dec 28 09:19:14 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation VM-csgvm_monitor_0 (call=26, rc=7, cib-update=22, confirmed=true) not running Dec 28 09:19:14 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation VM-printserver_monitor_0 (call=27, rc=7, cib-update=23, confirmed=true) not running Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:DRBDVG0:10: probe Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:DRBDVG1:11: probe Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:fs1:12: probe Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:fs2:13: probe Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[14] on heartbeat::nfsexport::nfs-exports-1 for client 7518, its parameters: 1=[192.168.203.0/24:/share1] 2=[rw,no_root_squash,insecure] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed fs1:monitor process 7828 exited with return code 7. Dec 28 09:19:14 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation fs1_monitor_0 (call=12, rc=7, cib-update=24, confirmed=true) not running Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed fs2:monitor process 7833 exited with return code 7. Dec 28 09:19:14 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation fs2_monitor_0 (call=13, rc=7, cib-update=25, confirmed=true) not running Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:share2:17: probe Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:xend:0:19: probe Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed share2:monitor process 7926 exited with return code 7. Dec 28 09:19:14 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation share2_monitor_0 (call=17, rc=7, cib-update=26, confirmed=true) not running Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:VM-kpasswd:23: probe Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[24] on ocf::IPaddr::pdu-ip1 for client 7518, its parameters: ip=[192.168.14.3] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:14 vmserve.scd.ucar.edu lrmd: [7514]: notice: max_child_count (4) reached, postponing execution of operation monitor[25] on ocf::IPaddr::pdu-ip2 for client 7518, its parameters: ip=[192.168.14.4] CRM_meta_timeout=[20000] crm_feature_set=[3.0.1] by 1000 ms Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed VM-kpasswd:monitor process 7974 exited with return code 7. Dec 28 09:19:15 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation VM-kpasswd_monitor_0 (call=23, rc=7, cib-update=27, confirmed=true) not running Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed DRBDVG0:monitor process 7820 exited with return code 7. Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed DRBDVG1:monitor process 7827 exited with return code 7. Dec 28 09:19:15 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation DRBDVG0_monitor_0 (call=10, rc=7, cib-update=28, confirmed=true) not running Dec 28 09:19:15 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation DRBDVG1_monitor_0 (call=11, rc=7, cib-update=29, confirmed=true) not running Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed xend:0:monitor process 7947 exited with return code 3. Dec 28 09:19:15 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation xend:0_monitor_0 (call=19, rc=7, cib-update=30, confirmed=true) not running Dec 28 09:19:15 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: Result: xend is stopped Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:nfs-exports-1:14: probe Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed nfs-exports-1:monitor process 8017 exited with return code 1. Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: CRIT: read_pipe:3812 Attempt to read from closed file descriptor 8. Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: notice: read_pipe::3818: lrmd_op has been freed Dec 28 09:19:15 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation nfs-exports-1_monitor_0 (call=14, rc=7, cib-update=31, confirmed=true) not running Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:pdu-ip1:24: probe Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:pdu-ip2:25: probe Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed pdu-ip1:monitor process 8028 exited with return code 7. Dec 28 09:19:15 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation pdu-ip1_monitor_0 (call=24, rc=7, cib-update=32, confirmed=true) not running Dec 28 09:19:15 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed pdu-ip2:monitor process 8031 exited with return code 7. Dec 28 09:19:15 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation pdu-ip2_monitor_0 (call=25, rc=7, cib-update=33, confirmed=true) not running Dec 28 09:19:16 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_trigger_update: Sending flush op to all hosts for: probe_complete (true) Dec 28 09:19:16 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=145:2:0:fb701221-ba59-4de8-88dc-032cab9ec090 op=vmgroup1:0_notify_0 ) Dec 28 09:19:16 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vmgroup1:0:28: notify Dec 28 09:19:16 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=156:2:0:fb701221-ba59-4de8-88dc-032cab9ec090 op=vmgroup2:0_notify_0 ) Dec 28 09:19:16 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vmgroup2:0:29: notify Dec 28 09:19:16 vmserve.scd.ucar.edu lrmd: [7514]: info: Managed vmgroup1:0:notify process 8044 exited with return code 0. Dec 28 09:19:16 vmserve.scd.ucar.edu lrmd: [7514]: info: Managed vmgroup2:0:notify process 8045 exited with return code 0. Dec 28 09:19:16 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vmgroup1:0_notify_0 (call=28, rc=0, cib-update=34, confirmed=true) ok Dec 28 09:19:16 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vmgroup2:0_notify_0 (call=29, rc=0, cib-update=35, confirmed=true) ok Dec 28 09:19:17 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_perform_update: Sent update 29: probe_complete=true Dec 28 09:19:17 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_trigger_update: Sending flush op to all hosts for: probe_complete (true) Dec 28 09:19:17 vmserve.scd.ucar.edu attrd: [7517]: info: attrd_perform_update: Sent update 32: probe_complete=true Dec 28 09:19:18 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=21:2:0:fb701221-ba59-4de8-88dc-032cab9ec090 op=vmgroup1:0_stop_0 ) Dec 28 09:19:18 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vmgroup1:0:30: stop Dec 28 09:19:18 vmserve.scd.ucar.edu crmd: [7518]: info: do_lrm_rsc_op: Performing key=50:2:0:fb701221-ba59-4de8-88dc-032cab9ec090 op=vmgroup2:0_stop_0 ) Dec 28 09:19:18 vmserve.scd.ucar.edu lrmd: [7514]: info: rsc:vmgroup2:0:31: stop Dec 28 09:19:18 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed vmgroup1:0:stop process 8088 exited with return code 6. Dec 28 09:19:18 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vmgroup1:0_stop_0 (call=30, rc=6, cib-update=36, confirmed=true) not configured Dec 28 09:19:18 vmserve.scd.ucar.edu lrmd: [7514]: WARN: Managed vmgroup2:0:stop process 8089 exited with return code 6. Dec 28 09:19:18 vmserve.scd.ucar.edu crmd: [7518]: info: process_lrm_event: LRM operation vmgroup2:0_stop_0 (call=31, rc=6, cib-update=37, confirmed=true) not configured [looks like a stonith reboot occurs here] Dec 28 09:40:53 vmserve.scd.ucar.edu heartbeat: [7646]: info: respawn directive: hacluster /usr/lib64/heartbeat/ipfail
_______________________________________________ Linux-HA mailing list [email protected] http://lists.linux-ha.org/mailman/listinfo/linux-ha See also: http://linux-ha.org/ReportingProblems
