Mar 19 13:34:09 ben daemon.debug clvmd[2845]: CLVMD started
Mar 19 13:34:09 ben user.debug kernel: [  116.726390] dlm: clvmd: joining the lockspace group...
Mar 19 13:34:09 ben user.debug kernel: [  116.730069] dlm: clvmd: dlm_recover 1
Mar 19 13:34:09 ben user.debug kernel: [  116.730082] dlm: clvmd: group event done 0 0
Mar 19 13:34:09 ben user.debug kernel: [  116.730116] dlm: clvmd: add member 1088840714
Mar 19 13:34:09 ben user.debug kernel: [  116.730117] dlm: clvmd: add member 837182474
Mar 19 13:34:09 ben user.debug kernel: [  116.730943] dlm: clvmd: dlm_recover_members 2 nodes
Mar 19 13:34:09 ben user.debug kernel: [  116.730948] dlm: clvmd: join complete
Mar 19 13:34:10 ben user.debug kernel: [  117.130123] dlm: clvmd: generation 6 slots 2 1:837182474 2:1088840714
Mar 19 13:34:10 ben user.debug kernel: [  117.130126] dlm: clvmd: dlm_recover_directory
Mar 19 13:34:10 ben user.debug kernel: [  117.330327] dlm: clvmd: dlm_recover_directory 0 in 0 new
Mar 19 13:34:10 ben user.debug kernel: [  117.730100] dlm: clvmd: dlm_recover_directory 0 out 1 messages
Mar 19 13:34:10 ben daemon.debug clvmd[2845]: Created DLM lockspace for CLVMD.
Mar 19 13:34:10 ben daemon.debug clvmd[2845]: DLM initialisation complete
Mar 19 13:34:10 ben daemon.debug clvmd[2845]: Our local node id is 837182474
Mar 19 13:34:10 ben daemon.debug clvmd[2845]: Connected to Corosync
Mar 19 13:34:10 ben daemon.debug clvmd[2845]: Cluster ready, doing some more initialisation
Mar 19 13:34:10 ben daemon.debug clvmd[2845]: starting LVM thread
Mar 19 13:34:10 ben daemon.debug clvmd[2845]: LVM thread function started
Mar 19 13:34:10 ben user.debug lvm[2845]: clvmd ready for work
Mar 19 13:34:10 ben user.debug lvm[2845]: Using timeout of 60 seconds
Mar 19 13:34:10 ben user.debug lvm[2845]: Sub thread ready for work.
Mar 19 13:34:10 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:10 ben user.debug lvm[2845]: confchg callback. 1 joined, 0 left, 2 members
Mar 19 13:34:11 ben user.debug kernel: [  118.951590] dlm: clvmd: dlm_recover 1 generation 6 done: 1821 ms
Mar 19 13:34:12 ben user.debug kernel: [  119.053187] qla2xxx 0000:03:00.0: irq 309 for MSI/MSI-X
Mar 19 13:34:13 ben user.debug kernel: [  120.185166] qla2xxx 0000:03:00.1: irq 310 for MSI/MSI-X
Mar 19 13:34:18 ben user.debug iscsi-scstd: max_data_seg_len 1048576, max_queued_cmds 2048
Mar 19 13:34:55 ben user.debug lvm[2845]: Got new connection on fd 5
Mar 19 13:34:55 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 13:34:55 ben user.debug lvm[2845]: creating pipe, [12, 13]
Mar 19 13:34:55 ben user.debug lvm[2845]: Creating pre&post thread
Mar 19 13:34:55 ben user.debug lvm[2845]: Created pre&post thread, state = 0
Mar 19 13:34:55 ben user.debug lvm[2845]: in sub thread: client = 0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: doing PRE command LOCK_VG 'V_r0' at 4 (client=0x19523f0)
Mar 19 13:34:55 ben user.debug lvm[2845]: lock_resource 'V_r0', flags=0, mode=4
Mar 19 13:34:55 ben user.debug lvm[2845]: lock_resource returning 0, lock_id=1
Mar 19 13:34:55 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:55 ben user.debug lvm[2845]: distribute command: XID = 0, flags=0x1 (LOCAL)
Mar 19 13:34:55 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952750. client=0x19523f0, msg=0x1952500, len=24, csid=(nil), xid=0
Mar 19 13:34:55 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:55 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x1952790, msglen =24, client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: do_lock_vg: resource 'V_r0', cmd = 0x4 LCK_VG (WRITE|VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:55 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 13:34:55 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:55 ben user.debug lvm[2845]: Got 1 replies, expecting: 1
Mar 19 13:34:55 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:55 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:55 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:55 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 13:34:55 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:55 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:55 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:55 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:55 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:55 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: distribute command: XID = 1, flags=0x0 ()
Mar 19 13:34:55 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:55 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x19529b0. client=0x19523f0, msg=0x1952500, len=24, csid=(nil), xid=1
Mar 19 13:34:55 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:55 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:55 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x1952750, msglen =24, client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: 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 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 13:34:55 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:55 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:55 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:55 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 24
Mar 19 13:34:55 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 13:34:55 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:55 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:55 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:55 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 13:34:55 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:55 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:55 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:55 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:55 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:55 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: distribute command: XID = 2, flags=0x0 ()
Mar 19 13:34:55 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:55 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x19529b0. client=0x19523f0, msg=0x1952500, len=24, csid=(nil), xid=2
Mar 19 13:34:55 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:55 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:55 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x1952750, msglen =24, client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: 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 ben user.debug lvm[2845]: vg_commit notification for VG r0
Mar 19 13:34:55 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:55 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:55 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:55 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 24
Mar 19 13:34:55 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:55 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 13:34:55 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:55 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:55 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:55 ben user.debug lvm[2845]: Read on local socket 5, len = 22
Mar 19 13:34:55 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:55 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:55 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:55 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:55 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:55 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: distribute command: XID = 3, flags=0x0 ()
Mar 19 13:34:55 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:55 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x19529b0. client=0x19523f0, msg=0x1952500, len=22, csid=(nil), xid=3
Mar 19 13:34:55 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:55 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:55 ben user.debug lvm[2845]: process_local_command: VG_BACKUP (0x2b) msg=0x1952750, msglen =22, client=0x19523f0
Mar 19 13:34:55 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:55 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:55 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:55 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 22
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:56 ben user.debug lvm[2845]: Read on local socket 5, len = 84
Mar 19 13:34:56 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: distribute command: XID = 4, flags=0x0 ()
Mar 19 13:34:56 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:56 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x19523f0, msg=0x1952750, len=84, csid=(nil), xid=4
Mar 19 13:34:56 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:56 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:56 ben user.debug lvm[2845]: process_local_command: LOCK_LV (0x32) msg=0x19527b0, msglen =84, client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: 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:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 84
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 35
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 40e6640a: 17 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: lock_resource 'bZ6A3DuNVyQTbWKDtWgP9vQIzopLKfBNYJAvWMwODeOKqbAarOjbvzhzHE5f3Pus', flags=1, mode=1
Mar 19 13:34:56 ben user.debug lvm[2845]: dlm_ls_lock returned 22
Mar 19 13:34:56 ben user.debug lvm[2845]: hold_lock. lock at 1 failed: Invalid argument
Mar 19 13:34:56 ben user.debug lvm[2845]: Command return is 22, critical_section is 0
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 31e6640a: 17 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:56 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:56 ben user.debug lvm[2845]: Read on local socket 5, len = 84
Mar 19 13:34:56 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: distribute command: XID = 5, flags=0x0 ()
Mar 19 13:34:56 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:56 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x19707f0. client=0x19523f0, msg=0x1952750, len=84, csid=(nil), xid=5
Mar 19 13:34:56 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:56 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:56 ben user.debug lvm[2845]: process_local_command: LOCK_LV (0x32) msg=0x19527b0, msglen =84, client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: 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:56 ben user.debug lvm[2845]: do_deactivate_lock, lock not already held
Mar 19 13:34:56 ben user.debug lvm[2845]: Command return is 0, critical_section is 0
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 84
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:56 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 13:34:56 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: distribute command: XID = 6, flags=0x0 ()
Mar 19 13:34:56 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:56 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x19707f0. client=0x19523f0, msg=0x196bcf0, len=24, csid=(nil), xid=6
Mar 19 13:34:56 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:56 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:56 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x196b6a0, msglen =24, client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: do_lock_vg: resource 'P_r0', cmd = 0x104 LCK_VG (WRITE|VG|CACHE), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 24
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:56 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 13:34:56 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: distribute command: XID = 7, flags=0x0 ()
Mar 19 13:34:56 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:56 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x19523f0, msg=0x196bcf0, len=24, csid=(nil), xid=7
Mar 19 13:34:56 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:56 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:56 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x196bb80, msglen =24, client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: 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:56 ben user.debug lvm[2845]: vg_commit notification for VG r0
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 24
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:56 ben user.debug lvm[2845]: Read on local socket 5, len = 22
Mar 19 13:34:56 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: distribute command: XID = 8, flags=0x0 ()
Mar 19 13:34:56 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:56 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x19523f0, msg=0x196bcf0, len=22, csid=(nil), xid=8
Mar 19 13:34:56 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:56 ben user.debug lvm[2845]: process_local_command: VG_BACKUP (0x2b) msg=0x196acd0, msglen =22, client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:56 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 22
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:56 ben user.debug lvm[2845]: Read on local socket 5, len = 31
Mar 19 13:34:56 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 13:34:56 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: distribute command: XID = 9, flags=0x0 ()
Mar 19 13:34:56 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 13:34:56 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x19523f0, msg=0x1952750, len=31, csid=(nil), xid=9
Mar 19 13:34:56 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:56 ben user.debug lvm[2845]: process_local_command: SYNC_NAMES (0x2d) msg=0x1952780, msglen =31, client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Syncing device names
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:56 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 31
Mar 19 13:34:56 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 13:34:56 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:56 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 13:34:56 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: doing PRE command LOCK_VG 'V_r0' at 6 (client=0x19523f0)
Mar 19 13:34:56 ben user.debug lvm[2845]: unlock_resource: V_r0 lockid: 1
Mar 19 13:34:56 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: distribute command: XID = 10, flags=0x1 (LOCAL)
Mar 19 13:34:56 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952750. client=0x19523f0, msg=0x1952840, len=24, csid=(nil), xid=10
Mar 19 13:34:56 ben user.debug lvm[2845]: process_work_item: local
Mar 19 13:34:56 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x196b6a0, msglen =24, client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: do_lock_vg: resource 'V_r0', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 13:34:56 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 13:34:56 ben user.debug lvm[2845]: Got 1 replies, expecting: 1
Mar 19 13:34:56 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 13:34:56 ben user.debug lvm[2845]: Got post command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 13:34:56 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 13:34:56 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x19523f0
Mar 19 13:34:56 ben user.debug lvm[2845]: Send local reply
Mar 19 13:34:56 ben user.debug lvm[2845]: Read on local socket 5, len = 0
Mar 19 13:34:56 ben user.debug lvm[2845]: EOF on local socket: inprogress=0
Mar 19 13:34:56 ben user.debug lvm[2845]: Waiting for child thread
Mar 19 13:34:56 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 13:34:56 ben user.debug lvm[2845]: Subthread finished
Mar 19 13:34:56 ben user.debug lvm[2845]: Joined child thread
Mar 19 13:34:56 ben user.debug lvm[2845]: ret == 0, errno = 0. removing client
Mar 19 13:34:56 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952750. client=0x19523f0, msg=(nil), len=0, csid=(nil), xid=10
Mar 19 13:34:56 ben user.debug lvm[2845]: process_work_item: free fd -1
Mar 19 13:34:56 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: Got new connection on fd 5
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 16:37:02 ben user.debug lvm[2845]: creating pipe, [12, 13]
Mar 19 16:37:02 ben user.debug lvm[2845]: Creating pre&post thread
Mar 19 16:37:02 ben user.debug lvm[2845]: Created pre&post thread, state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: in sub thread: client = 0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: doing PRE command LOCK_VG 'V_r0' at 4 (client=0x1952520)
Mar 19 16:37:02 ben user.debug lvm[2845]: lock_resource 'V_r0', flags=0, mode=4
Mar 19 16:37:02 ben user.debug lvm[2845]: lock_resource returning 0, lock_id=1
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 11, flags=0x1 (LOCAL)
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1962b10. client=0x1952520, msg=0x196bb80, len=24, csid=(nil), xid=11
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x196bcf0, msglen =24, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: do_lock_vg: resource 'V_r0', cmd = 0x4 LCK_VG (WRITE|VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 1
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 12, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x1952520, msg=0x196bb80, len=24, csid=(nil), xid=12
Mar 19 16:37:02 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x196b6a0, msglen =24, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: 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 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 24
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 13, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x1952520, msg=0x196bb80, len=24, csid=(nil), xid=13
Mar 19 16:37:02 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x1952840, msglen =24, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: 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 ben user.debug lvm[2845]: vg_commit notification for VG r0
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 24
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 22
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 14, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x1952520, msg=0x196bb80, len=22, csid=(nil), xid=14
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: VG_BACKUP (0x2b) msg=0x196bcf0, msglen =22, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 22
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 84
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 15, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x1952520, msg=0x1962b10, len=84, csid=(nil), xid=15
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: LOCK_LV (0x32) msg=0x1962b70, msglen =84, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: 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 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 84
Mar 19 16:37:02 ben user.debug lvm[2845]: lock_resource 'bZ6A3DuNVyQTbWKDtWgP9vQIzopLKfBNSzatwqVGb32qIU1v00DBvD3nZmiaNYbh', flags=1, mode=1
Mar 19 16:37:02 ben user.debug lvm[2845]: dlm_ls_lock returned 22
Mar 19 16:37:02 ben user.debug lvm[2845]: hold_lock. lock at 1 failed: Invalid argument
Mar 19 16:37:02 ben user.debug lvm[2845]: Command return is 22, critical_section is 0
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 17 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 35
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 17 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 84
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 16, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x1952520, msg=0x1962b10, len=84, csid=(nil), xid=16
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: LOCK_LV (0x32) msg=0x1947120, msglen =84, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: 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 ben user.debug lvm[2845]: do_deactivate_lock, lock not already held
Mar 19 16:37:02 ben user.debug lvm[2845]: Command return is 0, critical_section is 0
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 84
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 17, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x1952520, msg=0x1952840, len=24, csid=(nil), xid=17
Mar 19 16:37:02 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x196bcf0, msglen =24, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: 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 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 24
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 18, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x1952a10. client=0x1952520, msg=0x1952840, len=24, csid=(nil), xid=18
Mar 19 16:37:02 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x196bb80, msglen =24, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: 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 ben user.debug lvm[2845]: vg_commit notification for VG r0
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 24
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 22
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 19, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa8980113d0. client=0x1952520, msg=0x1952840, len=22, csid=(nil), xid=19
Mar 19 16:37:02 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: VG_BACKUP (0x2b) msg=0x7fa8980008e0, msglen =22, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 22
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 31
Mar 19 16:37:02 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 20, flags=0x0 ()
Mar 19 16:37:02 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa898011400. client=0x1952520, msg=0x7fa898011170, len=31, csid=(nil), xid=20
Mar 19 16:37:02 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: SYNC_NAMES (0x2d) msg=0x7fa8980111a0, msglen =31, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Syncing device names
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 31
Mar 19 16:37:02 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: doing PRE command LOCK_VG 'V_r0' at 6 (client=0x1952520)
Mar 19 16:37:02 ben user.debug lvm[2845]: unlock_resource: V_r0 lockid: 1
Mar 19 16:37:02 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: distribute command: XID = 21, flags=0x1 (LOCAL)
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa898011170. client=0x1952520, msg=0x7fa8980008e0, len=24, csid=(nil), xid=21
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:37:02 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x7fa8980111b0, msglen =24, client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: do_lock_vg: resource 'V_r0', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 16:37:02 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:37:02 ben user.debug lvm[2845]: Got 1 replies, expecting: 1
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:37:02 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:37:02 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:37:02 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x1952520
Mar 19 16:37:02 ben user.debug lvm[2845]: Send local reply
Mar 19 16:37:02 ben user.debug lvm[2845]: Read on local socket 5, len = 0
Mar 19 16:37:02 ben user.debug lvm[2845]: EOF on local socket: inprogress=0
Mar 19 16:37:02 ben user.debug lvm[2845]: Waiting for child thread
Mar 19 16:37:02 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:37:02 ben user.debug lvm[2845]: Subthread finished
Mar 19 16:37:02 ben user.debug lvm[2845]: Joined child thread
Mar 19 16:37:02 ben user.debug lvm[2845]: ret == 0, errno = 0. removing client
Mar 19 16:37:02 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa898011170. client=0x1952520, msg=(nil), len=0, csid=(nil), xid=21
Mar 19 16:37:02 ben user.debug lvm[2845]: process_work_item: free fd -1
Mar 19 16:37:02 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:39:52 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 0. len 31
Mar 19 16:39:52 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa898011170. client=0x6940a0, msg=0x7fff3ab71bdc, len=31, csid=0x7fff3ab71a8c, xid=0
Mar 19 16:39:52 ben user.debug lvm[2845]: process_work_item: remote
Mar 19 16:39:52 ben user.debug lvm[2845]: process_remote_command SYNC_NAMES (0x2d) for clientid 0x5000000 XID 1 on node 40e6640a
Mar 19 16:39:52 ben user.debug lvm[2845]: Syncing device names
Mar 19 16:39:52 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:39:52 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 1088840714. len 18
Mar 19 16:39:55 ben user.debug lvm[2845]: Got new connection on fd 5
Mar 19 16:39:55 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 16:39:55 ben user.debug lvm[2845]: creating pipe, [12, 13]
Mar 19 16:39:55 ben user.debug lvm[2845]: Creating pre&post thread
Mar 19 16:39:55 ben user.debug lvm[2845]: Created pre&post thread, state = 0
Mar 19 16:39:55 ben user.debug lvm[2845]: in sub thread: client = 0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: doing PRE command LOCK_VG 'V_r0' at 1 (client=0x7fa898011170)
Mar 19 16:39:55 ben user.debug lvm[2845]: lock_resource 'V_r0', flags=0, mode=3
Mar 19 16:39:55 ben user.debug lvm[2845]: lock_resource returning 0, lock_id=1
Mar 19 16:39:55 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:39:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:39:55 ben user.debug lvm[2845]: distribute command: XID = 22, flags=0x1 (LOCAL)
Mar 19 16:39:55 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa898011390. client=0x7fa898011170, msg=0x7fa8980008e0, len=24, csid=(nil), xid=22
Mar 19 16:39:55 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:39:55 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x7fa8980113d0, msglen =24, client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: do_lock_vg: resource 'V_r0', cmd = 0x1 LCK_VG (READ|VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:39:55 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 16:39:55 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:39:55 ben user.debug lvm[2845]: Got 1 replies, expecting: 1
Mar 19 16:39:55 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:39:55 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:39:55 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:39:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: Send local reply
Mar 19 16:39:55 ben user.debug lvm[2845]: Read on local socket 5, len = 31
Mar 19 16:39:55 ben user.debug lvm[2845]: check_all_clvmds_running
Mar 19 16:39:55 ben user.debug lvm[2845]: down_callback. node 1088840714, state = 3
Mar 19 16:39:55 ben user.debug lvm[2845]: down_callback. node 837182474, state = 3
Mar 19 16:39:55 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:39:55 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:39:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:39:55 ben user.debug lvm[2845]: distribute command: XID = 23, flags=0x0 ()
Mar 19 16:39:55 ben user.debug lvm[2845]: num_nodes = 2
Mar 19 16:39:55 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa898011620. client=0x7fa898011170, msg=0x7fa898011390, len=31, csid=(nil), xid=23
Mar 19 16:39:55 ben user.debug lvm[2845]: Sending message to all cluster nodes
Mar 19 16:39:55 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:39:55 ben user.debug lvm[2845]: process_local_command: SYNC_NAMES (0x2d) msg=0x7fa8980113c0, msglen =31, client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: Syncing device names
Mar 19 16:39:55 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:39:55 ben user.debug lvm[2845]: Got 1 replies, expecting: 2
Mar 19 16:39:55 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:39:55 ben user.debug lvm[2845]: 837182474 got message from nodeid 837182474 for 0. len 31
Mar 19 16:39:55 ben user.debug lvm[2845]: 837182474 got message from nodeid 1088840714 for 837182474. len 18
Mar 19 16:39:55 ben user.debug lvm[2845]: Reply from node 40e6640a: 0 bytes
Mar 19 16:39:55 ben user.debug lvm[2845]: Got 2 replies, expecting: 2
Mar 19 16:39:55 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:39:55 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:39:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: Send local reply
Mar 19 16:39:55 ben user.debug lvm[2845]: Read on local socket 5, len = 24
Mar 19 16:39:55 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:39:55 ben user.debug lvm[2845]: doing PRE command LOCK_VG 'V_r0' at 6 (client=0x7fa898011170)
Mar 19 16:39:55 ben user.debug lvm[2845]: unlock_resource: V_r0 lockid: 1
Mar 19 16:39:55 ben user.debug lvm[2845]: Writing status 0 down pipe 13
Mar 19 16:39:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: Waiting to do post command - state = 0
Mar 19 16:39:55 ben user.debug lvm[2845]: distribute command: XID = 24, flags=0x1 (LOCAL)
Mar 19 16:39:55 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa898011390. client=0x7fa898011170, msg=0x7fa8980008e0, len=24, csid=(nil), xid=24
Mar 19 16:39:55 ben user.debug lvm[2845]: process_work_item: local
Mar 19 16:39:55 ben user.debug lvm[2845]: process_local_command: LOCK_VG (0x33) msg=0x7fa8980113d0, msglen =24, client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: do_lock_vg: resource 'V_r0', cmd = 0x6 LCK_VG (UNLOCK|VG), flags = 0x4 ( DMEVENTD_MONITOR ), critical_section = 0
Mar 19 16:39:55 ben user.debug lvm[2845]: Invalidating cached metadata for VG r0
Mar 19 16:39:55 ben user.debug lvm[2845]: Reply from node 31e6640a: 0 bytes
Mar 19 16:39:55 ben user.debug lvm[2845]: Got 1 replies, expecting: 1
Mar 19 16:39:55 ben user.debug lvm[2845]: LVM thread waiting for work
Mar 19 16:39:55 ben user.debug lvm[2845]: Got post command condition...
Mar 19 16:39:55 ben user.debug lvm[2845]: read on PIPE 12: 4 bytes: status: 0
Mar 19 16:39:55 ben user.debug lvm[2845]: background routine status was 0, sock_client=0x7fa898011170
Mar 19 16:39:55 ben user.debug lvm[2845]: Waiting for next pre command
Mar 19 16:39:55 ben user.debug lvm[2845]: Send local reply
Mar 19 16:39:55 ben user.debug lvm[2845]: Read on local socket 5, len = 0
Mar 19 16:39:55 ben user.debug lvm[2845]: EOF on local socket: inprogress=0
Mar 19 16:39:55 ben user.debug lvm[2845]: Waiting for child thread
Mar 19 16:39:55 ben user.debug lvm[2845]: Got pre command condition...
Mar 19 16:39:55 ben user.debug lvm[2845]: Subthread finished
Mar 19 16:39:55 ben user.debug lvm[2845]: Joined child thread
Mar 19 16:39:55 ben user.debug lvm[2845]: ret == 0, errno = 0. removing client
Mar 19 16:39:55 ben user.debug lvm[2845]: add_to_lvmqueue: cmd=0x7fa898011280. client=0x7fa898011170, msg=(nil), len=0, csid=(nil), xid=24
Mar 19 16:39:55 ben user.debug lvm[2845]: process_work_item: free fd -1
Mar 19 16:39:55 ben user.debug lvm[2845]: LVM thread waiting for work