Dec  2 07:09:23 vm1 corosync[1020]:   [TOTEM ] The network interface [192.168.122.175] is now up.
Dec  2 07:09:23 vm1 corosync[1020]:   [SERV  ] Service engine loaded: corosync configuration map access [0]
Dec  2 07:09:23 vm1 corosync[1020]:   [QB    ] server name: cmap
Dec  2 07:09:23 vm1 corosync[1020]:   [SERV  ] Service engine loaded: corosync configuration service [1]
Dec  2 07:09:23 vm1 corosync[1020]:   [QB    ] server name: cfg
Dec  2 07:09:23 vm1 corosync[1020]:   [SERV  ] Service engine loaded: corosync cluster closed process group service v1.01 [2]
Dec  2 07:09:23 vm1 corosync[1020]:   [QB    ] server name: cpg
Dec  2 07:09:23 vm1 corosync[1020]:   [SERV  ] Service engine loaded: corosync profile loading service [4]
Dec  2 07:09:23 vm1 corosync[1020]:   [WD    ] No Watchdog, try modprobe <a watchdog>
Dec  2 07:09:23 vm1 corosync[1020]:   [WD    ] no resources configured.
Dec  2 07:09:23 vm1 corosync[1020]:   [SERV  ] Service engine loaded: corosync watchdog service [7]
Dec  2 07:09:23 vm1 corosync[1020]:   [QUORUM] Using quorum provider corosync_votequorum
Dec  2 07:09:23 vm1 corosync[1020]:   [QUORUM] This node is within the primary component and will provide service.
Dec  2 07:09:23 vm1 corosync[1020]:   [QUORUM] Members[0]:
Dec  2 07:09:23 vm1 corosync[1020]:   [SERV  ] Service engine loaded: corosync vote quorum service v1.0 [5]
Dec  2 07:09:23 vm1 corosync[1020]:   [QB    ] server name: votequorum
Dec  2 07:09:23 vm1 corosync[1020]:   [SERV  ] Service engine loaded: corosync cluster quorum service v0.1 [3]
Dec  2 07:09:23 vm1 corosync[1020]:   [QB    ] server name: quorum
Dec  2 07:09:23 vm1 corosync[1020]:   [TOTEM ] A new membership (192.168.122.175:168) was formed. Members joined: 1084783279
Dec  2 07:09:23 vm1 corosync[1020]:   [QUORUM] Members[1]: 1084783279
Dec  2 07:09:23 vm1 corosync[1020]:   [MAIN  ] Completed service synchronization, ready to provide service.
Dec  2 07:09:23 vm1 pacemakerd[1062]:   notice: mcp_read_config: Configured corosync to accept connections from group 113: OK (1)
Dec  2 07:09:23 vm1 pacemakerd[1062]:   notice: main: Starting Pacemaker 1.1.10 (Build: 42f2063):  generated-manpages agent-manpages ncurses libqb-logging libqb-ipc lha-fencing upstart nagios  heartbeat corosync-native snmp libesmtp
Dec  2 07:09:23 vm1 pacemakerd[1062]:   notice: cluster_connect_quorum: Quorum acquired
Dec  2 07:09:23 vm1 pacemakerd[1062]:   notice: corosync_node_name: Unable to get node name for nodeid 1084783279
Dec  2 07:09:23 vm1 pacemakerd[1062]:   notice: get_node_name: Defaulting to uname -n for the local corosync node name
Dec  2 07:09:23 vm1 pacemakerd[1062]:   notice: crm_update_peer_state: pcmk_quorum_notification: Node vm1[1084783279] - state is now member (was (null))
Dec  2 07:09:23 vm1 attrd[1073]:   notice: crm_cluster_connect: Connecting to cluster infrastructure: corosync
Dec  2 07:09:23 vm1 stonith-ng[1071]:   notice: crm_cluster_connect: Connecting to cluster infrastructure: corosync
Dec  2 07:09:23 vm1 crmd[1075]:   notice: main: CRM Git Version: 42f2063
Dec  2 07:09:23 vm1 attrd[1073]:   notice: corosync_node_name: Unable to get node name for nodeid 1084783279
Dec  2 07:09:23 vm1 attrd[1073]:   notice: get_node_name: Defaulting to uname -n for the local corosync node name
Dec  2 07:09:23 vm1 attrd[1073]:   notice: main: Starting mainloop...
Dec  2 07:09:23 vm1 stonith-ng[1071]:   notice: corosync_node_name: Unable to get node name for nodeid 1084783279
Dec  2 07:09:23 vm1 stonith-ng[1071]:   notice: get_node_name: Defaulting to uname -n for the local corosync node name
Dec  2 07:09:23 vm1 cib[1070]:   notice: crm_cluster_connect: Connecting to cluster infrastructure: corosync
Dec  2 07:09:23 vm1 cib[1070]:   notice: corosync_node_name: Unable to get node name for nodeid 1084783279
Dec  2 07:09:23 vm1 cib[1070]:   notice: get_node_name: Defaulting to uname -n for the local corosync node name
Dec  2 07:09:24 vm1 crmd[1075]:   notice: crm_cluster_connect: Connecting to cluster infrastructure: corosync
Dec  2 07:09:24 vm1 stonith-ng[1071]:   notice: setup_cib: Watching for stonith topology changes
Dec  2 07:09:24 vm1 stonith-ng[1071]:   notice: unpack_config: On loss of CCM Quorum: Ignore
Dec  2 07:09:24 vm1 crmd[1075]:   notice: corosync_node_name: Unable to get node name for nodeid 1084783279
Dec  2 07:09:24 vm1 crmd[1075]:   notice: get_node_name: Defaulting to uname -n for the local corosync node name
Dec  2 07:09:24 vm1 crmd[1075]:   notice: cluster_connect_quorum: Quorum acquired
Dec  2 07:09:24 vm1 crmd[1075]:   notice: crm_update_peer_state: pcmk_quorum_notification: Node vm1[1084783279] - state is now member (was (null))
Dec  2 07:09:25 vm1 crmd[1075]:   notice: corosync_node_name: Unable to get node name for nodeid 1084783279
Dec  2 07:09:25 vm1 crmd[1075]:   notice: get_node_name: Defaulting to uname -n for the local corosync node name
Dec  2 07:09:25 vm1 crmd[1075]:   notice: do_started: The local CRM is operational
Dec  2 07:09:25 vm1 crmd[1075]:   notice: do_state_transition: State transition S_STARTING -> S_PENDING [ input=I_PENDING cause=C_FSA_INTERNAL origin=do_started ]
Dec  2 07:09:33 vm1 ntpdate[620]: adjust time server 188.166.163.79 offset 0.412702 sec
Dec  2 07:09:33 vm1 ntpd[1131]: ntpd 4.2.6p5@1.2349-o Wed Oct  5 12:35:25 UTC 2016 (1)
Dec  2 07:09:33 vm1 ntpd[1132]: proto: precision = 0.103 usec
Dec  2 07:09:33 vm1 ntpd[1132]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
Dec  2 07:09:33 vm1 ntpd[1132]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Dec  2 07:09:33 vm1 ntpd[1132]: Listen and drop on 1 v6wildcard :: UDP 123
Dec  2 07:09:33 vm1 ntpd[1132]: Listen normally on 2 lo 127.0.0.1 UDP 123
Dec  2 07:09:33 vm1 ntpd[1132]: Listen normally on 3 eth0 192.168.122.175 UDP 123
Dec  2 07:09:33 vm1 ntpd[1132]: Listen normally on 4 lo ::1 UDP 123
Dec  2 07:09:33 vm1 ntpd[1132]: Listen normally on 5 eth0 fe80::5054:ff:fe74:8cc7 UDP 123
Dec  2 07:09:33 vm1 ntpd[1132]: peers refreshed
Dec  2 07:09:33 vm1 ntpd[1132]: Listening on routing socket on fd #22 for interface updates
Dec  2 07:09:38 vm1 ntpd[1132]: ntpd exiting on signal 15
Dec  2 07:09:46 vm1 crmd[1075]:  warning: do_log: FSA: Input I_DC_TIMEOUT from crm_timer_popped() received in state S_PENDING
Dec  2 07:09:46 vm1 crmd[1075]:   notice: do_state_transition: State transition S_ELECTION -> S_INTEGRATION [ input=I_ELECTION_DC cause=C_FSA_INTERNAL origin=do_election_check ]
Dec  2 07:09:46 vm1 cib[1070]:   notice: corosync_node_name: Unable to get node name for nodeid 1084783279
Dec  2 07:09:46 vm1 cib[1070]:   notice: get_node_name: Defaulting to uname -n for the local corosync node name
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_local_callback: Sending full refresh (origin=crmd)
Dec  2 07:09:46 vm1 pengine[1074]:   notice: unpack_config: On loss of CCM Quorum: Ignore
Dec  2 07:09:46 vm1 pengine[1074]:   notice: LogActions: Start   dlm:0#011(vm1)
Dec  2 07:09:46 vm1 pengine[1074]:   notice: LogActions: Start   clvmd:0#011(vm1)
Dec  2 07:09:46 vm1 pengine[1074]:   notice: LogActions: Start   vg#011(vm1)
Dec  2 07:09:46 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 4: monitor dlm:0_monitor_0 on vm1 (local)
Dec  2 07:09:46 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 5: monitor clvmd:0_monitor_0 on vm1 (local)
Dec  2 07:09:46 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 6: monitor vg_monitor_0 on vm1 (local)
Dec  2 07:09:46 vm1 pengine[1074]:   notice: process_pe_message: Calculated Transition 0: /var/lib/pacemaker/pengine/pe-input-141.bz2
Dec  2 07:09:46 vm1 LVM(vg)[1235]: WARNING: LVM Volume vg is not available (stopped)
Dec  2 07:09:46 vm1 LVM(vg)[1235]: INFO: LVM Volume vg is offline
Dec  2 07:09:46 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation clvmd_monitor_0 (call=11, rc=7, cib-update=23, confirmed=true) not running
Dec  2 07:09:46 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation dlm_monitor_0 (call=6, rc=7, cib-update=24, confirmed=true) not running
Dec  2 07:09:46 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation vg_monitor_0 (call=15, rc=7, cib-update=25, confirmed=true) not running
Dec  2 07:09:46 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 3: probe_complete probe_complete on vm1 (local) - no waiting
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_trigger_update: Sending flush op to all hosts for: probe_complete (true)
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_perform_update: Sent update 4: probe_complete=true
Dec  2 07:09:46 vm1 attrd[1073]:   notice: corosync_node_name: Unable to get node name for nodeid 1084783279
Dec  2 07:09:46 vm1 attrd[1073]:   notice: get_node_name: Defaulting to uname -n for the local corosync node name
Dec  2 07:09:46 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 7: start dlm:0_start_0 on vm1 (local)
Dec  2 07:09:46 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 23: start vg_start_0 on vm1 (local)
Dec  2 07:09:46 vm1 dlm_controld[1285]: 25 dlm_controld 4.0.1 started
Dec  2 07:09:46 vm1 LVM(vg)[1278]: INFO: Activating volume group vg
Dec  2 07:09:46 vm1 kernel: [   25.367705] dlm_controld wrote to rmem_default when file position was not 0!
Dec  2 07:09:46 vm1 kernel: [   25.367705] This will not be supported in the future. To silence this
Dec  2 07:09:46 vm1 kernel: [   25.367705] warning, set kernel.sysctl_writes_strict = -1
Dec  2 07:09:46 vm1 LVM(vg)[1278]: ERROR: connect() failed on local socket: No such file or directory Internal cluster locking initialisation failed. WARNING: Falling back to local file-based locking. Volume Groups with the clustered attribute will be inaccessible. Reading all physical volumes. This may take a while... Found volume group "vm1-vg" using metadata type lvm2 Skipping clustered volume group vg
Dec  2 07:09:46 vm1 LVM(vg)[1278]: ERROR: connect() failed on local socket: No such file or directory Internal cluster locking initialisation failed. WARNING: Falling back to local file-based locking. Volume Groups with the clustered attribute will be inaccessible. Skipping clustered volume group vg
Dec  2 07:09:46 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation vg_start_0 (call=22, rc=1, cib-update=26, confirmed=true) unknown error
Dec  2 07:09:46 vm1 crmd[1075]:  warning: status_from_rc: Action 23 (vg_start_0) on vm1 failed (target: 0 vs. rc: 1): Error
Dec  2 07:09:46 vm1 crmd[1075]:  warning: update_failcount: Updating failcount for vg on vm1 after failed start: rc=1 (update=INFINITY, time=1480658986)
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_trigger_update: Sending flush op to all hosts for: fail-count-vg (INFINITY)
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_perform_update: Sent update 7: fail-count-vg=INFINITY
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_trigger_update: Sending flush op to all hosts for: last-failure-vg (1480658986)
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_perform_update: Sent update 10: last-failure-vg=1480658986
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_trigger_update: Sending flush op to all hosts for: fail-count-vg (INFINITY)
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_perform_update: Sent update 12: fail-count-vg=INFINITY
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_trigger_update: Sending flush op to all hosts for: last-failure-vg (1480658986)
Dec  2 07:09:46 vm1 attrd[1073]:   notice: attrd_perform_update: Sent update 14: last-failure-vg=1480658986
Dec  2 07:09:46 vm1 crmd[1075]:  warning: update_failcount: Updating failcount for vg on vm1 after failed start: rc=1 (update=INFINITY, time=1480658986)
Dec  2 07:09:47 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation dlm_start_0 (call=20, rc=0, cib-update=27, confirmed=true) ok
Dec  2 07:09:47 vm1 crmd[1075]:   notice: run_graph: Transition 0 (Complete=9, Pending=0, Fired=0, Skipped=5, Incomplete=1, Source=/var/lib/pacemaker/pengine/pe-input-141.bz2): Stopped
Dec  2 07:09:47 vm1 pengine[1074]:   notice: unpack_config: On loss of CCM Quorum: Ignore
Dec  2 07:09:47 vm1 pengine[1074]:  warning: unpack_rsc_op: Processing failed op start for vg on vm1: unknown error (1)
Dec  2 07:09:47 vm1 pengine[1074]:  warning: common_apply_stickiness: Forcing vg away from vm1 after 1000000 failures (max=1000000)
Dec  2 07:09:47 vm1 pengine[1074]:   notice: LogActions: Start   clvmd:0#011(vm1)
Dec  2 07:09:47 vm1 pengine[1074]:   notice: LogActions: Stop    vg#011(vm1)
Dec  2 07:09:47 vm1 pengine[1074]:   notice: process_pe_message: Calculated Transition 1: /var/lib/pacemaker/pengine/pe-input-142.bz2
Dec  2 07:09:47 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 7: monitor dlm_monitor_60000 on vm1 (local)
Dec  2 07:09:47 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 1: stop vg_stop_0 on vm1 (local)
Dec  2 07:09:47 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 8: start clvmd_start_0 on vm1 (local)
Dec  2 07:09:47 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation dlm_monitor_60000 (call=26, rc=0, cib-update=29, confirmed=false) ok
Dec  2 07:09:47 vm1 clvmd(clvmd)[1309]: INFO: Starting clvmd
Dec  2 07:09:47 vm1 clvmd[1332]: CLVMD started
Dec  2 07:09:47 vm1 kernel: [   26.403628] dlm: Using SCTP for communications
Dec  2 07:09:47 vm1 kernel: [   26.413789] sctp: Hash tables configured (established 256 bind 256)
Dec  2 07:09:47 vm1 kernel: [   26.415925] dlm: clvmd: joining the lockspace group...
Dec  2 07:09:47 vm1 kernel: [   26.418602] dlm: clvmd: group event done 0 0
Dec  2 07:09:47 vm1 kernel: [   26.419054] dlm: clvmd: dlm_recover 1
Dec  2 07:09:47 vm1 kernel: [   26.419065] dlm: clvmd: add member 1084783279
Dec  2 07:09:47 vm1 kernel: [   26.419067] dlm: clvmd: dlm_recover_members 1 nodes
Dec  2 07:09:47 vm1 kernel: [   26.419068] dlm: clvmd: join complete
Dec  2 07:09:47 vm1 kernel: [   26.419557] dlm: clvmd: generation 1 slots 1 1:1084783279
Dec  2 07:09:47 vm1 kernel: [   26.419558] dlm: clvmd: dlm_recover_directory
Dec  2 07:09:47 vm1 kernel: [   26.419559] dlm: clvmd: dlm_recover_directory 0 in 0 new
Dec  2 07:09:47 vm1 kernel: [   26.419560] dlm: clvmd: dlm_recover_directory 0 out 0 messages
Dec  2 07:09:47 vm1 kernel: [   26.419566] dlm: clvmd: dlm_recover 1 generation 1 done: 0 ms
Dec  2 07:09:47 vm1 LVM(vg)[1308]: INFO: Deactivating volume group vg
Dec  2 07:09:48 vm1 clvmd[1332]: Created DLM lockspace for CLVMD.
Dec  2 07:09:48 vm1 clvmd[1332]: DLM initialisation complete
Dec  2 07:09:48 vm1 clvmd[1332]: Our local node id is 1084783279
Dec  2 07:09:48 vm1 clvmd[1332]: Connected to Corosync
Dec  2 07:09:48 vm1 clvmd[1332]: Cluster LVM daemon started - connected to Corosync
Dec  2 07:09:48 vm1 clvmd[1332]: Cluster ready, doing some more initialisation
Dec  2 07:09:48 vm1 clvmd[1332]: starting LVM thread
Dec  2 07:09:48 vm1 clvmd[1332]: LVM thread function started
Dec  2 07:09:48 vm1 lvm[1332]: clvmd ready for work
Dec  2 07:09:48 vm1 lvm[1332]: Using timeout of 60 seconds
Dec  2 07:09:48 vm1 lvm[1332]: confchg callback. 1 joined, 0 left, 1 members
Dec  2 07:09:48 vm1 lvm[1332]: Got new connection on fd 5
Dec  2 07:09:48 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:09:48 vm1 lvm[1332]: creating pipe, [13, 14]
Dec  2 07:09:48 vm1 lvm[1332]: Creating pre&post thread
Dec  2 07:09:48 vm1 lvm[1332]: Created pre&post thread, state = 0
Dec  2 07:09:48 vm1 lvm[1332]: Sub thread ready for work.
Dec  2 07:09:48 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:09:48 vm1 lvm[1332]: in sub thread: client = 0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 1 (client=0x8517f0)
Dec  2 07:09:48 vm1 lvm[1332]: lock_resource 'V_vg', flags=0, mode=3
Dec  2 07:09:48 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:09:48 vm1 lvm[1332]: Writing status 0 down pipe 14
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:09:48 vm1 lvm[1332]: distribute command: XID = 0, flags=0x1 (LOCAL)
Dec  2 07:09:48 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851b60. client=0x8517f0, msg=0x851900, len=24, csid=(nil), xid=0
Dec  2 07:09:48 vm1 lvm[1332]: process_work_item: local
Dec  2 07:09:48 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851ba0, msglen =24, client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:09:48 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:09:48 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:09:48 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:09:48 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:09:48 vm1 lvm[1332]: Got post command condition...
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:09:48 vm1 lvm[1332]: Send local reply
Dec  2 07:09:48 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:09:48 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Writing status 0 down pipe 14
Dec  2 07:09:48 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: distribute command: XID = 1, flags=0x1 (LOCAL)
Dec  2 07:09:48 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851b90. client=0x8517f0, msg=0x851b60, len=31, csid=(nil), xid=1
Dec  2 07:09:48 vm1 lvm[1332]: process_work_item: local
Dec  2 07:09:48 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851bd0, msglen =31, client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Syncing device names
Dec  2 07:09:48 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:09:48 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:09:48 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:09:48 vm1 lvm[1332]: Got post command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Send local reply
Dec  2 07:09:48 vm1 lvm[1332]: Read on local socket 5, len = 84
Dec  2 07:09:48 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:09:48 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:09:48 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Writing status 0 down pipe 14
Dec  2 07:09:48 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: distribute command: XID = 2, flags=0x0 ()
Dec  2 07:09:48 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:09:48 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851e50. client=0x8517f0, msg=0x851b90, len=84, csid=(nil), xid=2
Dec  2 07:09:48 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:09:48 vm1 lvm[1332]: process_work_item: local
Dec  2 07:09:48 vm1 lvm[1332]: process_local_command: LOCK_QUERY (0x34) msg=0x851bf0, msglen =84, client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: do_lock_query: resource 'Y9s0qu8doBG5RzmdlanzhUeWenRLq30OwuDvJhYLEnPWcqlIqnearqNGu0l0OcNi', mode -1 (?)
Dec  2 07:09:48 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:09:48 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:09:48 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:09:48 vm1 lvm[1332]: Got post command condition...
Dec  2 07:09:48 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 84
Dec  2 07:09:48 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Send local reply
Dec  2 07:09:48 vm1 lvm[1332]: Read on local socket 5, len = 84
Dec  2 07:09:48 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Writing status 0 down pipe 14
Dec  2 07:09:48 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: distribute command: XID = 3, flags=0x1 (LOCAL)
Dec  2 07:09:48 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851bf0. client=0x8517f0, msg=0x851b90, len=84, csid=(nil), xid=3
Dec  2 07:09:48 vm1 lvm[1332]: process_work_item: local
Dec  2 07:09:48 vm1 lvm[1332]: process_local_command: LOCK_LV (0x32) msg=0x851e50, msglen =84, client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: do_lock_lv: resource 'Y9s0qu8doBG5RzmdlanzhUeWenRLq30OwuDvJhYLEnPWcqlIqnearqNGu0l0OcNi', cmd = 0x98 LCK_LV_DEACTIVATE (NULL|LV|NONBLOCK|CLUSTER_VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:09:48 vm1 lvm[1332]: do_deactivate_lock, lock not already held
Dec  2 07:09:48 vm1 lvm[1332]: Command return is 0, critical_section is 0
Dec  2 07:09:48 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:09:48 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:09:48 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:09:48 vm1 lvm[1332]: Got post command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Send local reply
Dec  2 07:09:48 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:09:48 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:09:48 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:09:48 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Writing status 0 down pipe 14
Dec  2 07:09:48 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: distribute command: XID = 4, flags=0x0 ()
Dec  2 07:09:48 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:09:48 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851df0. client=0x8517f0, msg=0x851b60, len=31, csid=(nil), xid=4
Dec  2 07:09:48 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:09:48 vm1 lvm[1332]: process_work_item: local
Dec  2 07:09:48 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851b90, msglen =31, client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Syncing device names
Dec  2 07:09:48 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:09:48 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:09:48 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:09:48 vm1 lvm[1332]: Got post command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Send local reply
Dec  2 07:09:48 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:09:48 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:09:48 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 6 (client=0x8517f0)
Dec  2 07:09:48 vm1 lvm[1332]: unlock_resource: V_vg lockid: 1
Dec  2 07:09:48 vm1 lvm[1332]: Writing status 0 down pipe 14
Dec  2 07:09:48 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: distribute command: XID = 5, flags=0x1 (LOCAL)
Dec  2 07:09:48 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851b60. client=0x8517f0, msg=0x851900, len=24, csid=(nil), xid=5
Dec  2 07:09:48 vm1 lvm[1332]: process_work_item: local
Dec  2 07:09:48 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851ba0, msglen =24, client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:09:48 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:09:48 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:09:48 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:09:48 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:09:48 vm1 lvm[1332]: Got post command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:09:48 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:09:48 vm1 lvm[1332]: read on PIPE 13: 4 bytes: status: 0
Dec  2 07:09:48 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:09:48 vm1 lvm[1332]: Send local reply
Dec  2 07:09:48 vm1 LVM(vg)[1308]: INFO: 0 logical volume(s) in volume group "vg" now active
Dec  2 07:09:48 vm1 lvm[1332]: Read on local socket 5, len = 0
Dec  2 07:09:48 vm1 lvm[1332]: EOF on local socket: inprogress=0
Dec  2 07:09:48 vm1 lvm[1332]: Waiting for child thread
Dec  2 07:09:48 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:09:48 vm1 lvm[1332]: Subthread finished
Dec  2 07:09:48 vm1 lvm[1332]: Joined child thread
Dec  2 07:09:48 vm1 lvm[1332]: ret == 0, errno = 0. removing client
Dec  2 07:09:48 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851900. client=0x8517f0, msg=(nil), len=0, csid=(nil), xid=5
Dec  2 07:09:48 vm1 lvm[1332]: process_work_item: free fd -1
Dec  2 07:09:48 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:09:48 vm1 LVM(vg)[1308]: INFO: LVM Volume vg is not available (stopped)
Dec  2 07:09:48 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation vg_stop_0 (call=28, rc=0, cib-update=30, confirmed=true) ok
Dec  2 07:09:48 vm1 ntpdate[1229]: adjust time server 37.120.191.245 offset 0.411105 sec
Dec  2 07:09:48 vm1 ntpd[1388]: ntpd 4.2.6p5@1.2349-o Wed Oct  5 12:35:25 UTC 2016 (1)
Dec  2 07:09:48 vm1 ntpd[1389]: proto: precision = 0.134 usec
Dec  2 07:09:48 vm1 ntpd[1389]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
Dec  2 07:09:48 vm1 ntpd[1389]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Dec  2 07:09:48 vm1 ntpd[1389]: Listen and drop on 1 v6wildcard :: UDP 123
Dec  2 07:09:48 vm1 ntpd[1389]: Listen normally on 2 lo 127.0.0.1 UDP 123
Dec  2 07:09:48 vm1 ntpd[1389]: Listen normally on 3 eth0 192.168.122.175 UDP 123
Dec  2 07:09:48 vm1 ntpd[1389]: Listen normally on 4 lo ::1 UDP 123
Dec  2 07:09:48 vm1 ntpd[1389]: Listen normally on 5 eth0 fe80::5054:ff:fe74:8cc7 UDP 123
Dec  2 07:09:48 vm1 ntpd[1389]: peers refreshed
Dec  2 07:09:48 vm1 ntpd[1389]: Listening on routing socket on fd #22 for interface updates
Dec  2 07:09:50 vm1 lrmd[1072]:   notice: operation_finished: clvmd_start_0:1309:stderr [   local socket: connect failed: No such file or directory ]
Dec  2 07:09:50 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation clvmd_start_0 (call=30, rc=0, cib-update=31, confirmed=true) ok
Dec  2 07:09:50 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 9: monitor clvmd_monitor_40000 on vm1 (local)
Dec  2 07:09:50 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation clvmd_monitor_40000 (call=35, rc=0, cib-update=32, confirmed=false) ok
Dec  2 07:09:50 vm1 crmd[1075]:   notice: run_graph: Transition 1 (Complete=9, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-142.bz2): Complete
Dec  2 07:09:50 vm1 crmd[1075]:   notice: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ]
Dec  2 07:17:01 vm1 CRON[1566]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec  2 07:24:50 vm1 crmd[1075]:   notice: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_TIMER_POPPED origin=crm_timer_popped ]
Dec  2 07:24:50 vm1 pengine[1074]:   notice: unpack_config: On loss of CCM Quorum: Ignore
Dec  2 07:24:50 vm1 pengine[1074]:  warning: unpack_rsc_op: Processing failed op start for vg on vm1: unknown error (1)
Dec  2 07:24:50 vm1 pengine[1074]:  warning: common_apply_stickiness: Forcing vg away from vm1 after 1000000 failures (max=1000000)
Dec  2 07:24:50 vm1 crmd[1075]:   notice: run_graph: Transition 2 (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-143.bz2): Complete
Dec  2 07:24:50 vm1 crmd[1075]:   notice: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ]
Dec  2 07:24:50 vm1 pengine[1074]:   notice: process_pe_message: Calculated Transition 2: /var/lib/pacemaker/pengine/pe-input-143.bz2
Dec  2 07:33:57 vm1 dhclient: DHCPREQUEST of 192.168.122.175 on eth0 to 192.168.122.1 port 67 (xid=0x1068268f)
Dec  2 07:33:57 vm1 dhclient: DHCPACK of 192.168.122.175 from 192.168.122.1
Dec  2 07:33:57 vm1 dhclient: bound to 192.168.122.175 -- renewal in 1616 seconds.
Dec  2 07:39:50 vm1 crmd[1075]:   notice: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_TIMER_POPPED origin=crm_timer_popped ]
Dec  2 07:39:50 vm1 pengine[1074]:   notice: unpack_config: On loss of CCM Quorum: Ignore
Dec  2 07:39:50 vm1 pengine[1074]:  warning: unpack_rsc_op: Processing failed op start for vg on vm1: unknown error (1)
Dec  2 07:39:50 vm1 pengine[1074]:  warning: common_apply_stickiness: Forcing vg away from vm1 after 1000000 failures (max=1000000)
Dec  2 07:39:50 vm1 crmd[1075]:   notice: run_graph: Transition 3 (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-143.bz2): Complete
Dec  2 07:39:50 vm1 crmd[1075]:   notice: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ]
Dec  2 07:39:50 vm1 pengine[1074]:   notice: process_pe_message: Calculated Transition 3: /var/lib/pacemaker/pengine/pe-input-143.bz2
Dec  2 07:43:08 vm1 lvm[1332]: Got new connection on fd 5
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:43:08 vm1 lvm[1332]: creating pipe, [12, 13]
Dec  2 07:43:08 vm1 lvm[1332]: Creating pre&post thread
Dec  2 07:43:08 vm1 lvm[1332]: Created pre&post thread, state = 0
Dec  2 07:43:08 vm1 lvm[1332]: in sub thread: client = 0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 1 (client=0x8517f0)
Dec  2 07:43:08 vm1 lvm[1332]: lock_resource 'V_vm1-vg', flags=0, mode=3
Dec  2 07:43:08 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 6, flags=0x1 (LOCAL)
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=6
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:08 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 7, flags=0x1 (LOCAL)
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=7
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851970, msglen =31, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 8, flags=0x1 (LOCAL)
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=8
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851970, msglen =31, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:08 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:08 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 9, flags=0x0 ()
Dec  2 07:43:08 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=9
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 6 (client=0x8517f0)
Dec  2 07:43:08 vm1 lvm[1332]: unlock_resource: V_vm1-vg lockid: 1
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 10, flags=0x1 (LOCAL)
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=10
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:08 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 1 (client=0x8517f0)
Dec  2 07:43:08 vm1 lvm[1332]: lock_resource 'V_vg', flags=0, mode=3
Dec  2 07:43:08 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 11, flags=0x1 (LOCAL)
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=11
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:08 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 12, flags=0x1 (LOCAL)
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=12
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851970, msglen =31, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:08 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:08 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 13, flags=0x0 ()
Dec  2 07:43:08 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=13
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 6 (client=0x8517f0)
Dec  2 07:43:08 vm1 lvm[1332]: unlock_resource: V_vg lockid: 1
Dec  2 07:43:08 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:08 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: distribute command: XID = 14, flags=0x1 (LOCAL)
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=14
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:08 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:08 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:43:08 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:08 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:08 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:08 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:08 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:08 vm1 lvm[1332]: Send local reply
Dec  2 07:43:08 vm1 lvm[1332]: Read on local socket 5, len = 0
Dec  2 07:43:08 vm1 lvm[1332]: EOF on local socket: inprogress=0
Dec  2 07:43:08 vm1 lvm[1332]: Waiting for child thread
Dec  2 07:43:08 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:08 vm1 lvm[1332]: Subthread finished
Dec  2 07:43:08 vm1 lvm[1332]: Joined child thread
Dec  2 07:43:08 vm1 lvm[1332]: ret == 0, errno = 0. removing client
Dec  2 07:43:08 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851900. client=0x8517f0, msg=(nil), len=0, csid=(nil), xid=14
Dec  2 07:43:08 vm1 lvm[1332]: process_work_item: free fd -1
Dec  2 07:43:08 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Got new connection on fd 5
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 29
Dec  2 07:43:09 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:09 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:09 vm1 lvm[1332]: creating pipe, [12, 13]
Dec  2 07:43:09 vm1 lvm[1332]: Creating pre&post thread
Dec  2 07:43:09 vm1 lvm[1332]: Created pre&post thread, state = 0
Dec  2 07:43:09 vm1 lvm[1332]: in sub thread: client = 0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: doing PRE command LOCK_VG 'P_#global' at 1 (client=0x8517f0)
Dec  2 07:43:09 vm1 lvm[1332]: lock_resource 'P_#global', flags=0, mode=3
Dec  2 07:43:09 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:43:09 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:09 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: distribute command: XID = 15, flags=0x0 ()
Dec  2 07:43:09 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=29, csid=(nil), xid=15
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:09 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851930, msglen =29, client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: do_lock_vg: resource 'P_#global', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:09 vm1 lvm[1332]: Refreshing context
Dec  2 07:43:09 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:09 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 29
Dec  2 07:43:09 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:09 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:09 vm1 lvm[1332]: Send local reply
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:43:09 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:09 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 1 (client=0x8517f0)
Dec  2 07:43:09 vm1 lvm[1332]: lock_resource 'V_vm1-vg', flags=0, mode=3
Dec  2 07:43:09 vm1 lvm[1332]: lock_resource returning 0, lock_id=2
Dec  2 07:43:09 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:09 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: distribute command: XID = 16, flags=0x1 (LOCAL)
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=16
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:09 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:09 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:43:09 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:09 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Send local reply
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:09 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:09 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:09 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:09 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: distribute command: XID = 17, flags=0x0 ()
Dec  2 07:43:09 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=17
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:09 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:09 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:09 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:09 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:09 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Send local reply
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:43:09 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:09 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 6 (client=0x8517f0)
Dec  2 07:43:09 vm1 lvm[1332]: unlock_resource: V_vm1-vg lockid: 2
Dec  2 07:43:09 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:09 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: distribute command: XID = 18, flags=0x1 (LOCAL)
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=18
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:09 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:09 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:43:09 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:09 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Send local reply
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:43:09 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:09 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 1 (client=0x8517f0)
Dec  2 07:43:09 vm1 lvm[1332]: lock_resource 'V_vg', flags=0, mode=3
Dec  2 07:43:09 vm1 lvm[1332]: lock_resource returning 0, lock_id=2
Dec  2 07:43:09 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:09 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: distribute command: XID = 19, flags=0x1 (LOCAL)
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=19
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:09 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:09 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:43:09 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:09 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Send local reply
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:09 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:09 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:09 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:09 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: distribute command: XID = 20, flags=0x0 ()
Dec  2 07:43:09 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=20
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:09 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:09 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:09 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:09 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:09 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Send local reply
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:43:09 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:09 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 6 (client=0x8517f0)
Dec  2 07:43:09 vm1 lvm[1332]: unlock_resource: V_vg lockid: 2
Dec  2 07:43:09 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:09 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: distribute command: XID = 21, flags=0x1 (LOCAL)
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=21
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:09 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:09 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:43:09 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:09 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Send local reply
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 29
Dec  2 07:43:09 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:09 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:09 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:09 vm1 lvm[1332]: doing PRE command LOCK_VG 'P_#global' at 6 (client=0x8517f0)
Dec  2 07:43:09 vm1 lvm[1332]: unlock_resource: P_#global lockid: 1
Dec  2 07:43:09 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:09 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: distribute command: XID = 22, flags=0x0 ()
Dec  2 07:43:09 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=29, csid=(nil), xid=22
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:09 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851930, msglen =29, client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: do_lock_vg: resource 'P_#global', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:09 vm1 lvm[1332]: Refreshing context
Dec  2 07:43:09 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:09 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 29
Dec  2 07:43:09 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:09 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:09 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:09 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:09 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:09 vm1 lvm[1332]: Send local reply
Dec  2 07:43:09 vm1 lvm[1332]: Read on local socket 5, len = 0
Dec  2 07:43:09 vm1 lvm[1332]: EOF on local socket: inprogress=0
Dec  2 07:43:09 vm1 lvm[1332]: Waiting for child thread
Dec  2 07:43:09 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:09 vm1 lvm[1332]: Subthread finished
Dec  2 07:43:09 vm1 lvm[1332]: Joined child thread
Dec  2 07:43:09 vm1 lvm[1332]: ret == 0, errno = 0. removing client
Dec  2 07:43:09 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851900. client=0x8517f0, msg=(nil), len=0, csid=(nil), xid=22
Dec  2 07:43:09 vm1 lvm[1332]: process_work_item: free fd -1
Dec  2 07:43:09 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Got new connection on fd 5
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:43:16 vm1 lvm[1332]: creating pipe, [12, 13]
Dec  2 07:43:16 vm1 lvm[1332]: Creating pre&post thread
Dec  2 07:43:16 vm1 lvm[1332]: Created pre&post thread, state = 0
Dec  2 07:43:16 vm1 lvm[1332]: in sub thread: client = 0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 1 (client=0x8517f0)
Dec  2 07:43:16 vm1 lvm[1332]: lock_resource 'V_vm1-vg', flags=0, mode=3
Dec  2 07:43:16 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 23, flags=0x1 (LOCAL)
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=23
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:16 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 24, flags=0x1 (LOCAL)
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=24
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851970, msglen =31, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 25, flags=0x1 (LOCAL)
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=25
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851970, msglen =31, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:16 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:16 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 26, flags=0x0 ()
Dec  2 07:43:16 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=26
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 6 (client=0x8517f0)
Dec  2 07:43:16 vm1 lvm[1332]: unlock_resource: V_vm1-vg lockid: 1
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 27, flags=0x1 (LOCAL)
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=27
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:16 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 1 (client=0x8517f0)
Dec  2 07:43:16 vm1 lvm[1332]: lock_resource 'V_vg', flags=0, mode=3
Dec  2 07:43:16 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 28, flags=0x1 (LOCAL)
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=28
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:16 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 29, flags=0x1 (LOCAL)
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=29
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851970, msglen =31, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:16 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:16 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 30, flags=0x0 ()
Dec  2 07:43:16 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=30
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 6 (client=0x8517f0)
Dec  2 07:43:16 vm1 lvm[1332]: unlock_resource: V_vg lockid: 1
Dec  2 07:43:16 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:16 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: distribute command: XID = 31, flags=0x1 (LOCAL)
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=31
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:16 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:16 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:43:16 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:16 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:16 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:16 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:16 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:16 vm1 lvm[1332]: Send local reply
Dec  2 07:43:16 vm1 lvm[1332]: Read on local socket 5, len = 0
Dec  2 07:43:16 vm1 lvm[1332]: EOF on local socket: inprogress=0
Dec  2 07:43:16 vm1 lvm[1332]: Waiting for child thread
Dec  2 07:43:16 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:16 vm1 lvm[1332]: Subthread finished
Dec  2 07:43:16 vm1 lvm[1332]: Joined child thread
Dec  2 07:43:16 vm1 lvm[1332]: ret == 0, errno = 0. removing client
Dec  2 07:43:16 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851900. client=0x8517f0, msg=(nil), len=0, csid=(nil), xid=31
Dec  2 07:43:16 vm1 lvm[1332]: process_work_item: free fd -1
Dec  2 07:43:16 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:24 vm1 lvm[1332]: Got new connection on fd 5
Dec  2 07:43:24 vm1 lvm[1332]: Read on local socket 5, len = 29
Dec  2 07:43:24 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:24 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:24 vm1 lvm[1332]: creating pipe, [12, 13]
Dec  2 07:43:24 vm1 lvm[1332]: Creating pre&post thread
Dec  2 07:43:24 vm1 lvm[1332]: Created pre&post thread, state = 0
Dec  2 07:43:24 vm1 lvm[1332]: in sub thread: client = 0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: doing PRE command LOCK_VG 'P_#global' at 1 (client=0x8517f0)
Dec  2 07:43:24 vm1 lvm[1332]: lock_resource 'P_#global', flags=0, mode=3
Dec  2 07:43:24 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:43:24 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:24 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: distribute command: XID = 32, flags=0x0 ()
Dec  2 07:43:24 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:24 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=29, csid=(nil), xid=32
Dec  2 07:43:24 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:24 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851930, msglen =29, client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: do_lock_vg: resource 'P_#global', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:24 vm1 lvm[1332]: Refreshing context
Dec  2 07:43:24 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:24 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 29
Dec  2 07:43:24 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:24 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:24 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:24 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:24 vm1 lvm[1332]: Send local reply
Dec  2 07:43:24 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:43:24 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:24 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 1 (client=0x8517f0)
Dec  2 07:43:24 vm1 lvm[1332]: lock_resource 'V_vm1-vg', flags=0, mode=3
Dec  2 07:43:24 vm1 lvm[1332]: lock_resource returning 0, lock_id=2
Dec  2 07:43:24 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:24 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: distribute command: XID = 33, flags=0x1 (LOCAL)
Dec  2 07:43:24 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=33
Dec  2 07:43:24 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:24 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:24 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:43:24 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:24 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:24 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:24 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:24 vm1 lvm[1332]: Send local reply
Dec  2 07:43:24 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:24 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:24 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:24 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:24 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:24 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: distribute command: XID = 34, flags=0x0 ()
Dec  2 07:43:24 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:24 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=34
Dec  2 07:43:24 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:24 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:24 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:24 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:24 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:24 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:24 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:24 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:24 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Send local reply
Dec  2 07:43:24 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:43:24 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:24 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 6 (client=0x8517f0)
Dec  2 07:43:24 vm1 lvm[1332]: unlock_resource: V_vm1-vg lockid: 2
Dec  2 07:43:24 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:24 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: distribute command: XID = 35, flags=0x1 (LOCAL)
Dec  2 07:43:24 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=35
Dec  2 07:43:24 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:24 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:24 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:43:24 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:24 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:24 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:24 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:24 vm1 lvm[1332]: Send local reply
Dec  2 07:43:24 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:43:24 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:24 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 1 (client=0x8517f0)
Dec  2 07:43:24 vm1 lvm[1332]: lock_resource 'V_vg', flags=0, mode=3
Dec  2 07:43:24 vm1 lvm[1332]: lock_resource returning 0, lock_id=2
Dec  2 07:43:24 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:24 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: distribute command: XID = 36, flags=0x1 (LOCAL)
Dec  2 07:43:24 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=36
Dec  2 07:43:24 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:24 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:24 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:43:24 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:24 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:24 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:24 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:24 vm1 lvm[1332]: Send local reply
Dec  2 07:43:24 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:43:24 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:24 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:24 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:24 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:24 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: distribute command: XID = 37, flags=0x0 ()
Dec  2 07:43:24 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:24 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=37
Dec  2 07:43:24 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:24 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Syncing device names
Dec  2 07:43:24 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:24 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:24 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:24 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:24 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:24 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:24 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Send local reply
Dec  2 07:43:24 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:43:24 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:24 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 6 (client=0x8517f0)
Dec  2 07:43:24 vm1 lvm[1332]: unlock_resource: V_vg lockid: 2
Dec  2 07:43:24 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:24 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: distribute command: XID = 38, flags=0x1 (LOCAL)
Dec  2 07:43:24 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=38
Dec  2 07:43:24 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:24 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:24 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:43:24 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:24 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:24 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:24 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:24 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: Send local reply
Dec  2 07:43:24 vm1 lvm[1332]: Read on local socket 5, len = 29
Dec  2 07:43:24 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:43:24 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:43:24 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:24 vm1 lvm[1332]: doing PRE command LOCK_VG 'P_#global' at 6 (client=0x8517f0)
Dec  2 07:43:24 vm1 lvm[1332]: unlock_resource: P_#global lockid: 1
Dec  2 07:43:24 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:43:24 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:43:24 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:24 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: distribute command: XID = 39, flags=0x0 ()
Dec  2 07:43:24 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:43:24 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=29, csid=(nil), xid=39
Dec  2 07:43:24 vm1 lvm[1332]: process_work_item: local
Dec  2 07:43:24 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851930, msglen =29, client=0x8517f0
Dec  2 07:43:24 vm1 lvm[1332]: do_lock_vg: resource 'P_#global', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:43:24 vm1 lvm[1332]: Refreshing context
Dec  2 07:43:24 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:43:24 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 29
Dec  2 07:43:25 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:43:25 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:43:25 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:43:25 vm1 lvm[1332]: Got post command condition...
Dec  2 07:43:25 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:43:25 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:43:25 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:43:25 vm1 lvm[1332]: Send local reply
Dec  2 07:43:25 vm1 lvm[1332]: Read on local socket 5, len = 0
Dec  2 07:43:25 vm1 lvm[1332]: EOF on local socket: inprogress=0
Dec  2 07:43:25 vm1 lvm[1332]: Waiting for child thread
Dec  2 07:43:25 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:43:25 vm1 lvm[1332]: Subthread finished
Dec  2 07:43:25 vm1 lvm[1332]: Joined child thread
Dec  2 07:43:25 vm1 lvm[1332]: ret == 0, errno = 0. removing client
Dec  2 07:43:25 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851900. client=0x8517f0, msg=(nil), len=0, csid=(nil), xid=39
Dec  2 07:43:25 vm1 lvm[1332]: process_work_item: free fd -1
Dec  2 07:43:25 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:40 vm1 attrd[1073]:   notice: attrd_trigger_update: Sending flush op to all hosts for: fail-count-vg (<null>)
Dec  2 07:44:40 vm1 crmd[1075]:   notice: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=abort_transition_graph ]
Dec  2 07:44:40 vm1 attrd[1073]:   notice: attrd_perform_update: Sent delete 16: node=1084783279, attr=fail-count-vg, id=<n/a>, set=(null), section=status
Dec  2 07:44:40 vm1 cib[1070]:   notice: cib:diff: Diff: --- 0.109.15
Dec  2 07:44:40 vm1 cib[1070]:   notice: cib:diff: Diff: +++ 0.110.1 ca82fa1d5517ed5d58fe06dce9b30d67
Dec  2 07:44:40 vm1 pengine[1074]:   notice: unpack_config: On loss of CCM Quorum: Ignore
Dec  2 07:44:40 vm1 pengine[1074]:   notice: LogActions: Start   vg#011(vm1)
Dec  2 07:44:40 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 6: monitor vg_monitor_0 on vm1 (local)
Dec  2 07:44:40 vm1 pengine[1074]:   notice: process_pe_message: Calculated Transition 4: /var/lib/pacemaker/pengine/pe-input-144.bz2
Dec  2 07:44:40 vm1 LVM(vg)[2032]: WARNING: LVM Volume vg is not available (stopped)
Dec  2 07:44:40 vm1 LVM(vg)[2032]: INFO: LVM Volume vg is offline
Dec  2 07:44:40 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation vg_monitor_0 (call=42, rc=7, cib-update=42, confirmed=true) not running
Dec  2 07:44:40 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 5: probe_complete probe_complete on vm1 (local) - no waiting
Dec  2 07:44:40 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 23: start vg_start_0 on vm1 (local)
Dec  2 07:44:40 vm1 LVM(vg)[2047]: INFO: Activating volume group vg
Dec  2 07:44:40 vm1 lvm[1332]: Got new connection on fd 5
Dec  2 07:44:40 vm1 lvm[1332]: Read on local socket 5, len = 29
Dec  2 07:44:40 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:44:40 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:44:40 vm1 lvm[1332]: creating pipe, [12, 13]
Dec  2 07:44:40 vm1 lvm[1332]: Creating pre&post thread
Dec  2 07:44:40 vm1 lvm[1332]: Created pre&post thread, state = 0
Dec  2 07:44:40 vm1 lvm[1332]: in sub thread: client = 0x8517f0
Dec  2 07:44:40 vm1 lvm[1332]: doing PRE command LOCK_VG 'P_#global' at 4 (client=0x8517f0)
Dec  2 07:44:40 vm1 lvm[1332]: lock_resource 'P_#global', flags=0, mode=4
Dec  2 07:44:40 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:44:40 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:44:40 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:40 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:40 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:40 vm1 lvm[1332]: distribute command: XID = 40, flags=0x0 ()
Dec  2 07:44:40 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:44:40 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=29, csid=(nil), xid=40
Dec  2 07:44:40 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:40 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851930, msglen =29, client=0x8517f0
Dec  2 07:44:40 vm1 lvm[1332]: do_lock_vg: resource 'P_#global', cmd = 0x4 LCK_VG (WRITE|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:40 vm1 lvm[1332]: Refreshing context
Dec  2 07:44:40 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:44:40 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 29
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 1 (client=0x8517f0)
Dec  2 07:44:41 vm1 lvm[1332]: lock_resource 'V_vm1-vg', flags=0, mode=3
Dec  2 07:44:41 vm1 lvm[1332]: lock_resource returning 0, lock_id=2
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 41, flags=0x1 (LOCAL)
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=41
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:41 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:44:41 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:44:41 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 42, flags=0x0 ()
Dec  2 07:44:41 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=42
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Syncing device names
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 5, len = 28
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vm1-vg' at 6 (client=0x8517f0)
Dec  2 07:44:41 vm1 lvm[1332]: unlock_resource: V_vm1-vg lockid: 2
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 43, flags=0x1 (LOCAL)
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851930. client=0x8517f0, msg=0x851900, len=28, csid=(nil), xid=43
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851970, msglen =28, client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_vg: resource 'V_vm1-vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:41 vm1 lvm[1332]: Invalidating cached metadata for VG vm1-vg
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 1 (client=0x8517f0)
Dec  2 07:44:41 vm1 lvm[1332]: lock_resource 'V_vg', flags=0, mode=3
Dec  2 07:44:41 vm1 lvm[1332]: lock_resource returning 0, lock_id=2
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 44, flags=0x1 (LOCAL)
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=44
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:41 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 5, len = 31
Dec  2 07:44:41 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:44:41 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 45, flags=0x0 ()
Dec  2 07:44:41 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=31, csid=(nil), xid=45
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x851930, msglen =31, client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Syncing device names
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 5, len = 24
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 6 (client=0x8517f0)
Dec  2 07:44:41 vm1 lvm[1332]: unlock_resource: V_vg lockid: 2
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 46, flags=0x1 (LOCAL)
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=0x851930, len=24, csid=(nil), xid=46
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:41 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 5, len = 29
Dec  2 07:44:41 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:44:41 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: doing PRE command LOCK_VG 'P_#global' at 6 (client=0x8517f0)
Dec  2 07:44:41 vm1 lvm[1332]: unlock_resource: P_#global lockid: 1
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 13
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 47, flags=0x0 ()
Dec  2 07:44:41 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851ed0. client=0x8517f0, msg=0x851900, len=29, csid=(nil), xid=47
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851930, msglen =29, client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_vg: resource 'P_#global', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:41 vm1 lvm[1332]: Refreshing context
Dec  2 07:44:41 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:44:41 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 29
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 12: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x8517f0
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 LVM(vg)[2047]: INFO: Reading all physical volumes. This may take a while... Found volume group "vm1-vg" using metadata type lvm2 Found volume group "vg" using metadata type lvm2
Dec  2 07:44:41 vm1 lvm[1332]: Got new connection on fd 15
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 15, len = 24
Dec  2 07:44:41 vm1 lvm[1332]: creating pipe, [16, 17]
Dec  2 07:44:41 vm1 lvm[1332]: Creating pre&post thread
Dec  2 07:44:41 vm1 lvm[1332]: Created pre&post thread, state = 0
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 5, len = 0
Dec  2 07:44:41 vm1 lvm[1332]: EOF on local socket: inprogress=0
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for child thread
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Subthread finished
Dec  2 07:44:41 vm1 lvm[1332]: Joined child thread
Dec  2 07:44:41 vm1 lvm[1332]: ret == 0, errno = 0. removing client
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x8517f0, msg=(nil), len=0, csid=(nil), xid=47
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: free fd -1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: in sub thread: client = 0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 1 (client=0x851c70)
Dec  2 07:44:41 vm1 lvm[1332]: lock_resource 'V_vg', flags=0, mode=3
Dec  2 07:44:41 vm1 lvm[1332]: lock_resource returning 0, lock_id=1
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 17
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 48, flags=0x1 (LOCAL)
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851950. client=0x851c70, msg=0x851930, len=24, csid=(nil), xid=48
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851990, msglen =24, client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x1 LCK_VG (READ|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:41 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 15, len = 84
Dec  2 07:44:41 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:44:41 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 17
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 49, flags=0x0 ()
Dec  2 07:44:41 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x852220. client=0x851c70, msg=0x851950, len=84, csid=(nil), xid=49
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_QUERY (0x34) msg=0x8519b0, msglen =84, client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_query: resource 'Y9s0qu8doBG5RzmdlanzhUeWenRLq30OwuDvJhYLEnPWcqlIqnearqNGu0l0OcNi', mode -1 (?)
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 84
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 15, len = 84
Dec  2 07:44:41 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:44:41 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 17
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 50, flags=0x0 ()
Dec  2 07:44:41 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x852220. client=0x851c70, msg=0x851950, len=84, csid=(nil), xid=50
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_QUERY (0x34) msg=0x8519b0, msglen =84, client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_query: resource 'Y9s0qu8doBG5RzmdlanzhUeWenRLq30OwuDvJhYLEnPWcqlIqnearqNGu0l0OcNi', mode -1 (?)
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 84
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 15, len = 84
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 17
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 51, flags=0x1 (LOCAL)
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x8519b0. client=0x851c70, msg=0x851950, len=84, csid=(nil), xid=51
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_LV (0x32) msg=0x852220, msglen =84, client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_lv: resource 'Y9s0qu8doBG5RzmdlanzhUeWenRLq30OwuDvJhYLEnPWcqlIqnearqNGu0l0OcNi', cmd = 0x9d LCK_LV_EXCLUSIVE (EXCL|LV|NONBLOCK|CLUSTER_VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:41 vm1 lvm[1332]: lock_resource 'Y9s0qu8doBG5RzmdlanzhUeWenRLq30OwuDvJhYLEnPWcqlIqnearqNGu0l0OcNi', flags=1, mode=5
Dec  2 07:44:41 vm1 lvm[1332]: lock_resource returning 0, lock_id=2
Dec  2 07:44:41 vm1 lvm[1332]: Command return is 0, critical_section is 0
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 15, len = 84
Dec  2 07:44:41 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:44:41 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 17
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 52, flags=0x0 ()
Dec  2 07:44:41 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x852220. client=0x851c70, msg=0x851950, len=84, csid=(nil), xid=52
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_QUERY (0x34) msg=0x8519b0, msglen =84, client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_query: resource 'Y9s0qu8doBG5RzmdlanzhUeWenRLq30OwuDvJhYLEnPWcqlIqnearqNGu0l0OcNi', mode 5 (EX)
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 3 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 84
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 15, len = 31
Dec  2 07:44:41 vm1 lvm[1332]: check_all_clvmds_running
Dec  2 07:44:41 vm1 lvm[1332]: down_callback. node 1084783279, state = 3
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 17
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 53, flags=0x0 ()
Dec  2 07:44:41 vm1 lvm[1332]: num_nodes = 1
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x852220. client=0x851c70, msg=0x8519b0, len=31, csid=(nil), xid=53
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: SYNC_NAMES (0x2d) msg=0x8519e0, msglen =31, client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Syncing device names
Dec  2 07:44:41 vm1 lvm[1332]: Sending message to all cluster nodes
Dec  2 07:44:41 vm1 lvm[1332]: 1084783279 got message from nodeid 1084783279 for 0. len 31
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 15, len = 24
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: doing PRE command LOCK_VG 'V_vg' at 6 (client=0x851c70)
Dec  2 07:44:41 vm1 lvm[1332]: unlock_resource: V_vg lockid: 1
Dec  2 07:44:41 vm1 lvm[1332]: Writing status 0 down pipe 17
Dec  2 07:44:41 vm1 lvm[1332]: Waiting to do post command - state = 0
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: distribute command: XID = 54, flags=0x1 (LOCAL)
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851b60. client=0x851c70, msg=0x84f870, len=24, csid=(nil), xid=54
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: local
Dec  2 07:44:41 vm1 lvm[1332]: process_local_command: LOCK_VG (0x33) msg=0x851ba0, msglen =24, client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: do_lock_vg: resource 'V_vg', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x0 ( ), critical_section = 0
Dec  2 07:44:41 vm1 lvm[1332]: Invalidating cached metadata for VG vg
Dec  2 07:44:41 vm1 lvm[1332]: Reply from node 40a87aaf: 0 bytes
Dec  2 07:44:41 vm1 lvm[1332]: Got 1 replies, expecting: 1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 lvm[1332]: Got post command condition...
Dec  2 07:44:41 vm1 lvm[1332]: read on PIPE 16: 4 bytes: status: 0
Dec  2 07:44:41 vm1 lvm[1332]: background routine status was 0, sock_client=0x851c70
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for next pre command
Dec  2 07:44:41 vm1 lvm[1332]: Send local reply
Dec  2 07:44:41 vm1 LVM(vg)[2047]: INFO: 1 logical volume(s) in volume group "vg" now active
Dec  2 07:44:41 vm1 lvm[1332]: Read on local socket 15, len = 0
Dec  2 07:44:41 vm1 lvm[1332]: EOF on local socket: inprogress=0
Dec  2 07:44:41 vm1 lvm[1332]: Waiting for child thread
Dec  2 07:44:41 vm1 lvm[1332]: Got pre command condition...
Dec  2 07:44:41 vm1 lvm[1332]: Subthread finished
Dec  2 07:44:41 vm1 lvm[1332]: Joined child thread
Dec  2 07:44:41 vm1 lvm[1332]: ret == 0, errno = 0. removing client
Dec  2 07:44:41 vm1 lvm[1332]: add_to_lvmqueue: cmd=0x851b60. client=0x851c70, msg=(nil), len=0, csid=(nil), xid=54
Dec  2 07:44:41 vm1 lvm[1332]: process_work_item: free fd -1
Dec  2 07:44:41 vm1 lvm[1332]: LVM thread waiting for work
Dec  2 07:44:41 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation vg_start_0 (call=45, rc=0, cib-update=43, confirmed=true) ok
Dec  2 07:44:41 vm1 crmd[1075]:   notice: te_rsc_command: Initiating action 24: monitor vg_monitor_60000 on vm1 (local)
Dec  2 07:44:41 vm1 crmd[1075]:   notice: process_lrm_event: LRM operation vg_monitor_60000 (call=48, rc=0, cib-update=44, confirmed=false) ok
Dec  2 07:44:41 vm1 crmd[1075]:   notice: run_graph: Transition 4 (Complete=5, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-144.bz2): Complete
Dec  2 07:44:41 vm1 crmd[1075]:   notice: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ]