Mar 19 13:28:28 bill daemon.debug clvmd[5069]: CLVMD started
Mar 19 13:28:28 bill user.debug kernel: [  120.315423] dlm: clvmd: joining the lockspace group...
Mar 19 13:28:28 bill user.debug kernel: [  120.318426] dlm: clvmd: dlm_recover 1
Mar 19 13:28:28 bill user.debug kernel: [  120.318433] dlm: clvmd: group event done 0 0
Mar 19 13:28:28 bill user.debug kernel: [  120.318495] dlm: clvmd: add member 1088840714
Mar 19 13:28:28 bill user.debug kernel: [  120.318497] dlm: clvmd: add member 837182474
Mar 19 13:28:28 bill user.debug kernel: [  120.319338] dlm: clvmd: dlm_recover_members 2 nodes
Mar 19 13:28:28 bill user.debug kernel: [  120.319342] dlm: clvmd: join complete
Mar 19 13:28:28 bill user.debug kernel: [  120.541014] dlm: clvmd: generation 4 slots 2 1:837182474 2:1088840714
Mar 19 13:28:28 bill user.debug kernel: [  120.541018] dlm: clvmd: dlm_recover_directory
Mar 19 13:28:28 bill user.debug kernel: [  120.582024] dlm: clvmd: dlm_recover_directory 0 in 0 new
Mar 19 13:28:28 bill user.debug kernel: [  120.663905] dlm: clvmd: dlm_recover_directory 0 out 1 messages
Mar 19 13:28:29 bill user.debug kernel: [  120.966946] dlm: clvmd: dlm_recover 1 generation 4 done: 425 ms
Mar 19 13:28:29 bill daemon.debug clvmd[5069]: Created DLM lockspace for CLVMD.
Mar 19 13:28:29 bill daemon.debug clvmd[5069]: DLM initialisation complete
Mar 19 13:28:29 bill daemon.debug clvmd[5069]: Our local node id is 1088840714
Mar 19 13:28:29 bill daemon.debug clvmd[5069]: Connected to Corosync
Mar 19 13:28:29 bill daemon.debug clvmd[5069]: Cluster ready, doing some more initialisation
Mar 19 13:28:29 bill daemon.debug clvmd[5069]: starting LVM thread
Mar 19 13:28:29 bill daemon.debug clvmd[5069]: LVM thread function started
Mar 19 13:28:29 bill user.debug lvm[5069]: clvmd ready for work
Mar 19 13:28:29 bill user.debug lvm[5069]: Sub thread ready for work.
Mar 19 13:28:29 bill user.debug lvm[5069]: Using timeout of 60 seconds
Mar 19 13:28:29 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:28:29 bill user.debug lvm[5069]: confchg callback. 1 joined, 0 left, 2 members
Mar 19 13:28:30 bill user.debug kernel: [  122.629171] qla2xxx 0000:0e:00.0: irq 117 for MSI/MSI-X
Mar 19 13:28:30 bill user.debug kernel: [  122.629184] qla2xxx 0000:0e:00.0: irq 118 for MSI/MSI-X
Mar 19 13:28:31 bill user.debug kernel: [  123.805164] qla2xxx 0000:0e:00.1: irq 119 for MSI/MSI-X
Mar 19 13:28:31 bill user.debug kernel: [  123.805174] qla2xxx 0000:0e:00.1: irq 120 for MSI/MSI-X
Mar 19 13:28:36 bill user.debug iscsi-scstd: max_data_seg_len 1048576, max_queued_cmds 2048
Mar 19 13:29:26 bill user.debug kernel: [  178.402539] dlm: clvmd: dlm_recover 3
Mar 19 13:29:26 bill user.debug kernel: [  178.402628] dlm: clvmd: remove member 837182474
Mar 19 13:29:26 bill user.debug kernel: [  178.402632] dlm: clvmd: dlm_recover_members 1 nodes
Mar 19 13:29:26 bill user.debug kernel: [  178.402636] dlm: clvmd: generation 5 slots 1 2:1088840714
Mar 19 13:29:26 bill user.debug kernel: [  178.402638] dlm: clvmd: dlm_recover_directory
Mar 19 13:29:26 bill user.debug kernel: [  178.402639] dlm: clvmd: dlm_recover_directory 0 in 0 new
Mar 19 13:29:26 bill user.debug kernel: [  178.402641] dlm: clvmd: dlm_recover_directory 0 out 0 messages
Mar 19 13:29:26 bill user.debug kernel: [  178.402644] dlm: clvmd: dlm_recover_masters
Mar 19 13:29:26 bill user.debug kernel: [  178.402645] dlm: clvmd: dlm_recover_masters 0 of 0
Mar 19 13:29:26 bill user.debug kernel: [  178.402647] dlm: clvmd: dlm_recover_locks 0 out
Mar 19 13:29:26 bill user.debug kernel: [  178.402648] dlm: clvmd: dlm_recover_locks 0 in
Mar 19 13:29:26 bill user.debug kernel: [  178.402671] dlm: clvmd: dlm_recover 3 generation 5 done: 0 ms
Mar 19 13:29:26 bill user.debug lvm[5069]: confchg callback. 0 joined, 1 left, 1 members
Mar 19 13:34:09 bill user.debug kernel: [  461.552920] dlm: clvmd: dlm_recover 5
Mar 19 13:34:09 bill user.debug kernel: [  461.553014] dlm: clvmd: add member 837182474
Mar 19 13:34:09 bill user.debug kernel: [  461.553948] dlm: clvmd: dlm_recover_members 2 nodes
Mar 19 13:34:10 bill user.debug kernel: [  462.153397] dlm: clvmd: generation 6 slots 2 1:837182474 2:1088840714
Mar 19 13:34:10 bill user.debug kernel: [  462.153400] dlm: clvmd: dlm_recover_directory
Mar 19 13:34:10 bill user.debug kernel: [  462.153684] dlm: clvmd: dlm_recover_directory 0 in 0 new
Mar 19 13:34:10 bill user.debug lvm[5069]: confchg callback. 1 joined, 0 left, 2 members
Mar 19 13:34:11 bill user.debug kernel: [  462.953140] dlm: clvmd: dlm_recover_directory 0 out 1 messages
Mar 19 13:34:12 bill user.debug kernel: [  463.974428] dlm: clvmd: dlm_recover 5 generation 6 done: 1821 ms
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 24
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x242d3f0. client=0x6940a0, msg=0x7fff41373c7c, len=24, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command LOCK_VG (0x33) for clientid 0x5000000 XID 1 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: do_lock_vg: resource 'P_r0', cmd = 0x104 LCK_VG (WRITE|VG|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:55 bill user.debug lvm[5069]: Invalidating cached metadata for VG r0
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 24
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x242d3f0. client=0x6940a0, msg=0x7fff41373c7c, len=24, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command LOCK_VG (0x33) for clientid 0x5000000 XID 2 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: do_lock_vg: resource 'P_r0', cmd = 0x124 LCK_VG (WRITE|VG|HOLD|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:55 bill user.debug lvm[5069]: vg_commit notification for VG r0
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 22
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x242d3f0. client=0x6940a0, msg=0x7fff41373c7c, len=22, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command VG_BACKUP (0x2b) for clientid 0x5000000 XID 3 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: Triggering backup of VG metadata for r0.
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 84
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=84, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command LOCK_LV (0x32) for clientid 0x5000000 XID 4 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: do_lock_lv: resource 'bZ6A3DuNVyQTbWKDtWgP9vQIzopLKfBNYJAvWMwODeOKqbAarOjbvzhzHE5f3Pus', cmd = 0x99 LCK_LV_ACTIVATE (READ|LV|NONBLOCK|CLUSTER_VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:55 bill user.debug lvm[5069]: lock_resource 'bZ6A3DuNVyQTbWKDtWgP9vQIzopLKfBNYJAvWMwODeOKqbAarOjbvzhzHE5f3Pus', flags=1, mode=1
Mar 19 13:34:55 bill user.debug lvm[5069]: dlm_ls_lock returned 22
Mar 19 13:34:55 bill user.debug lvm[5069]: hold_lock. lock at 1 failed: Invalid argument
Mar 19 13:34:55 bill user.debug lvm[5069]: Command return is 22, critical_section is 0
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 35
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 84
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2447380. client=0x6940a0, msg=0x7fff41373c7c, len=84, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command LOCK_LV (0x32) for clientid 0x5000000 XID 5 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: do_lock_lv: resource 'bZ6A3DuNVyQTbWKDtWgP9vQIzopLKfBNYJAvWMwODeOKqbAarOjbvzhzHE5f3Pus', cmd = 0x98 LCK_LV_DEACTIVATE (NULL|LV|NONBLOCK|CLUSTER_VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:55 bill user.debug lvm[5069]: do_deactivate_lock, lock not already held
Mar 19 13:34:55 bill user.debug lvm[5069]: Command return is 0, critical_section is 0
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 24
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2447380. client=0x6940a0, msg=0x7fff41373c7c, len=24, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command LOCK_VG (0x33) for clientid 0x5000000 XID 6 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: do_lock_vg: resource 'P_r0', cmd = 0x104 LCK_VG (WRITE|VG|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:55 bill user.debug lvm[5069]: Invalidating cached metadata for VG r0
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 24
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=24, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command LOCK_VG (0x33) for clientid 0x5000000 XID 7 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: do_lock_vg: resource 'P_r0', cmd = 0x124 LCK_VG (WRITE|VG|HOLD|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:55 bill user.debug lvm[5069]: vg_commit notification for VG r0
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 22
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=22, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command VG_BACKUP (0x2b) for clientid 0x5000000 XID 8 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: Triggering backup of VG metadata for r0.
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 31
Mar 19 13:34:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=31, csid=0x7fff41373b2c, xid=0
Mar 19 13:34:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 13:34:55 bill user.debug lvm[5069]: process_remote_command SYNC_NAMES (0x2d) for clientid 0x5000000 XID 9 on node 31e6640a
Mar 19 13:34:55 bill user.debug lvm[5069]: Syncing device names
Mar 19 13:34:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 13:34:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 24
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=24, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command LOCK_VG (0x33) for clientid 0x5000000 XID 12 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: do_lock_vg: resource 'P_r0', cmd = 0x104 LCK_VG (WRITE|VG|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:37:02 bill user.debug lvm[5069]: Invalidating cached metadata for VG r0
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 24
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=24, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command LOCK_VG (0x33) for clientid 0x5000000 XID 13 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: do_lock_vg: resource 'P_r0', cmd = 0x124 LCK_VG (WRITE|VG|HOLD|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:37:02 bill user.debug lvm[5069]: vg_commit notification for VG r0
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 22
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=22, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command VG_BACKUP (0x2b) for clientid 0x5000000 XID 14 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: Triggering backup of VG metadata for r0.
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 84
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=84, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command LOCK_LV (0x32) for clientid 0x5000000 XID 15 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: do_lock_lv: resource 'bZ6A3DuNVyQTbWKDtWgP9vQIzopLKfBNSzatwqVGb32qIU1v00DBvD3nZmiaNYbh', cmd = 0x99 LCK_LV_ACTIVATE (READ|LV|NONBLOCK|CLUSTER_VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:37:02 bill user.debug lvm[5069]: lock_resource 'bZ6A3DuNVyQTbWKDtWgP9vQIzopLKfBNSzatwqVGb32qIU1v00DBvD3nZmiaNYbh', flags=1, mode=1
Mar 19 16:37:02 bill user.debug lvm[5069]: dlm_ls_lock returned 22
Mar 19 16:37:02 bill user.debug lvm[5069]: hold_lock. lock at 1 failed: Invalid argument
Mar 19 16:37:02 bill user.debug lvm[5069]: Command return is 22, critical_section is 0
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 35
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 84
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=84, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command LOCK_LV (0x32) for clientid 0x5000000 XID 16 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: do_lock_lv: resource 'bZ6A3DuNVyQTbWKDtWgP9vQIzopLKfBNSzatwqVGb32qIU1v00DBvD3nZmiaNYbh', cmd = 0x98 LCK_LV_DEACTIVATE (NULL|LV|NONBLOCK|CLUSTER_VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:37:02 bill user.debug lvm[5069]: do_deactivate_lock, lock not already held
Mar 19 16:37:02 bill user.debug lvm[5069]: Command return is 0, critical_section is 0
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 24
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=24, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command LOCK_VG (0x33) for clientid 0x5000000 XID 17 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: do_lock_vg: resource 'P_r0', cmd = 0x104 LCK_VG (WRITE|VG|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:37:02 bill user.debug lvm[5069]: Invalidating cached metadata for VG r0
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 24
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=24, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command LOCK_VG (0x33) for clientid 0x5000000 XID 18 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: do_lock_vg: resource 'P_r0', cmd = 0x124 LCK_VG (WRITE|VG|HOLD|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:37:02 bill user.debug lvm[5069]: vg_commit notification for VG r0
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 22
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=22, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command VG_BACKUP (0x2b) for clientid 0x5000000 XID 19 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: Triggering backup of VG metadata for r0.
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 31
Mar 19 16:37:02 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x6940a0, msg=0x7fff41373c7c, len=31, csid=0x7fff41373b2c, xid=0
Mar 19 16:37:02 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:37:02 bill user.debug lvm[5069]: process_remote_command SYNC_NAMES (0x2d) for clientid 0x5000000 XID 20 on node 31e6640a
Mar 19 16:37:02 bill user.debug lvm[5069]: Syncing device names
Mar 19 16:37:02 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:37:02 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:39:52 bill user.debug lvm[5069]: Got new connection on fd 5
Mar 19 16:39:52 bill user.debug lvm[5069]: Read on local socket 5, len = 24
Mar 19 16:39:52 bill user.debug lvm[5069]: creating pipe, [12, 13]
Mar 19 16:39:52 bill user.debug lvm[5069]: Creating pre&post thread
Mar 19 16:39:52 bill user.debug lvm[5069]: Created pre&post thread, state = 0
Mar 19 16:39:52 bill user.debug lvm[5069]: in sub thread: client = 0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: doing PRE command LOCK_VG 'V_r0' at 1 (client=0x2445560)
Mar 19 16:39:52 bill user.debug lvm[5069]: lock_resource 'V_r0', flags=0, mode=3
Mar 19 16:39:52 bill user.debug lvm[5069]: lock_resource returning 0, lock_id=1
Mar 19 16:39:52 bill user.debug lvm[5069]: Writing status 0 down pipe 13
Mar 19 16:39:52 bill user.debug lvm[5069]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:52 bill user.debug lvm[5069]: background routine status was 0, sock_client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: Waiting to do post command - state = 0
Mar 19 16:39:52 bill user.debug lvm[5069]: distribute command: XID = 0, flags=0x1 (LOCAL)
Mar 19 16:39:52 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x2445560, msg=0x24464e0, len=24, csid=(nil), xid=0
Mar 19 16:39:52 bill user.debug lvm[5069]: process_work_item: local
Mar 19 16:39:52 bill user.debug lvm[5069]: process_local_command: LOCK_VG (0x33) msg=0x2445a70, msglen =24, client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: do_lock_vg: resource 'V_r0', cmd = 0x1 LCK_VG (READ|VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:39:52 bill user.debug lvm[5069]: Invalidating cached metadata for VG r0
Mar 19 16:39:52 bill user.debug lvm[5069]: Reply from node 40e6640a: 0 bytes
Mar 19 16:39:52 bill user.debug lvm[5069]: Got 1 replies, expecting: 1
Mar 19 16:39:52 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:39:52 bill user.debug lvm[5069]: Got post command condition...
Mar 19 16:39:52 bill user.debug lvm[5069]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:52 bill user.debug lvm[5069]: background routine status was 0, sock_client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: Waiting for next pre command
Mar 19 16:39:52 bill user.debug lvm[5069]: Send local reply
Mar 19 16:39:52 bill user.debug lvm[5069]: Read on local socket 5, len = 31
Mar 19 16:39:52 bill user.debug lvm[5069]: check_all_clvmds_running
Mar 19 16:39:52 bill user.debug lvm[5069]: down_callback. node 1088840714, state = 3
Mar 19 16:39:52 bill user.debug lvm[5069]: down_callback. node 837182474, state = 3
Mar 19 16:39:52 bill user.debug lvm[5069]: Got pre command condition...
Mar 19 16:39:52 bill user.debug lvm[5069]: Writing status 0 down pipe 13
Mar 19 16:39:52 bill user.debug lvm[5069]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:52 bill user.debug lvm[5069]: background routine status was 0, sock_client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: Waiting to do post command - state = 0
Mar 19 16:39:52 bill user.debug lvm[5069]: distribute command: XID = 1, flags=0x0 ()
Mar 19 16:39:52 bill user.debug lvm[5069]: num_nodes = 2
Mar 19 16:39:52 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x244b420. client=0x2445560, msg=0x2446790, len=31, csid=(nil), xid=1
Mar 19 16:39:52 bill user.debug lvm[5069]: Sending message to all cluster nodes
Mar 19 16:39:52 bill user.debug lvm[5069]: process_work_item: local
Mar 19 16:39:52 bill user.debug lvm[5069]: process_local_command: SYNC_NAMES (0x2d) msg=0x2446e00, msglen =31, client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: Syncing device names
Mar 19 16:39:52 bill user.debug lvm[5069]: Reply from node 40e6640a: 0 bytes
Mar 19 16:39:52 bill user.debug lvm[5069]: Got 1 replies, expecting: 2
Mar 19 16:39:52 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:39:52 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 0. len 31
Mar 19 16:39:52 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 1088840714. len 18
Mar 19 16:39:52 bill user.debug lvm[5069]: Reply from node 31e6640a: 0 bytes
Mar 19 16:39:52 bill user.debug lvm[5069]: Got 2 replies, expecting: 2
Mar 19 16:39:52 bill user.debug lvm[5069]: Got post command condition...
Mar 19 16:39:52 bill user.debug lvm[5069]: Waiting for next pre command
Mar 19 16:39:52 bill user.debug lvm[5069]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:52 bill user.debug lvm[5069]: background routine status was 0, sock_client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: Send local reply
Mar 19 16:39:52 bill user.debug lvm[5069]: Read on local socket 5, len = 24
Mar 19 16:39:52 bill user.debug lvm[5069]: Got pre command condition...
Mar 19 16:39:52 bill user.debug lvm[5069]: doing PRE command LOCK_VG 'V_r0' at 6 (client=0x2445560)
Mar 19 16:39:52 bill user.debug lvm[5069]: unlock_resource: V_r0 lockid: 1
Mar 19 16:39:52 bill user.debug lvm[5069]: Writing status 0 down pipe 13
Mar 19 16:39:52 bill user.debug lvm[5069]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:52 bill user.debug lvm[5069]: background routine status was 0, sock_client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: Waiting to do post command - state = 0
Mar 19 16:39:52 bill user.debug lvm[5069]: distribute command: XID = 2, flags=0x1 (LOCAL)
Mar 19 16:39:52 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x2446790. client=0x2445560, msg=0x2445a70, len=24, csid=(nil), xid=2
Mar 19 16:39:52 bill user.debug lvm[5069]: process_work_item: local
Mar 19 16:39:52 bill user.debug lvm[5069]: process_local_command: LOCK_VG (0x33) msg=0x24464e0, msglen =24, client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: do_lock_vg: resource 'V_r0', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:39:52 bill user.debug lvm[5069]: Invalidating cached metadata for VG r0
Mar 19 16:39:52 bill user.debug lvm[5069]: Reply from node 40e6640a: 0 bytes
Mar 19 16:39:52 bill user.debug lvm[5069]: Got 1 replies, expecting: 1
Mar 19 16:39:52 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:39:52 bill user.debug lvm[5069]: Got post command condition...
Mar 19 16:39:52 bill user.debug lvm[5069]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:52 bill user.debug lvm[5069]: background routine status was 0, sock_client=0x2445560
Mar 19 16:39:52 bill user.debug lvm[5069]: Waiting for next pre command
Mar 19 16:39:52 bill user.debug lvm[5069]: Send local reply
Mar 19 16:39:52 bill user.debug lvm[5069]: Read on local socket 5, len = 0
Mar 19 16:39:52 bill user.debug lvm[5069]: EOF on local socket: inprogress=0
Mar 19 16:39:52 bill user.debug lvm[5069]: Waiting for child thread
Mar 19 16:39:52 bill user.debug lvm[5069]: Got pre command condition...
Mar 19 16:39:52 bill user.debug lvm[5069]: Subthread finished
Mar 19 16:39:52 bill user.debug lvm[5069]: Joined child thread
Mar 19 16:39:52 bill user.debug lvm[5069]: ret == 0, errno = 0. removing client
Mar 19 16:39:52 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x24472e0. client=0x2445560, msg=(nil), len=0, csid=(nil), xid=2
Mar 19 16:39:52 bill user.debug lvm[5069]: process_work_item: free fd -1
Mar 19 16:39:52 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:39:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 837182474 for 0. len 31
Mar 19 16:39:55 bill user.debug lvm[5069]: add_to_lvmqueue: cmd=0x24472e0. client=0x6940a0, msg=0x7fff41373c7c, len=31, csid=0x7fff41373b2c, xid=0
Mar 19 16:39:55 bill user.debug lvm[5069]: process_work_item: remote
Mar 19 16:39:55 bill user.debug lvm[5069]: process_remote_command SYNC_NAMES (0x2d) for clientid 0x5000000 XID 23 on node 31e6640a
Mar 19 16:39:55 bill user.debug lvm[5069]: Syncing device names
Mar 19 16:39:55 bill user.debug lvm[5069]: LVM thread waiting for work
Mar 19 16:39:55 bill user.debug lvm[5069]: 1088840714 got message from nodeid 1088840714 for 837182474. len 18