[Gluster-users] FIle size error when restoring backups causes restore failure.

Wed Apr 27 07:55:37 UTC 2016

I'm getting the following file size error when restoring proxmox qemu
backups via gfapi. I don't think the issue is with proxmox as I have tested
the same restore process with other storages with no problem(nfs, cephfs,
ceph rbd). Also if I restore the the gluster *fuse* mount it works ok.

Have tested with:

performance.stat-prefetch: off
performance.strict-write-ordering: on

still same problem.

This is with sharded storage - as soon as I some time I'll test with
non-shared storage.

Error is bolded at the end of the logging

restore vma archive: lzop -d -c
/mnt/nas-backups-smb/dump/vzdump-qemu-910-2016_04_23-08_22_07.vma.lzo|vma
extract -v -r /var/tmp/vzdumptmp8999.fifo - /var/tmp/vzdumptmp8999
CFG: size: 391 name: qemu-server.conf
DEV: dev_id=1 size: 34359738368 devname: drive-scsi0
CTIME: Sat Apr 23 08:22:11 2016
[2016-04-27 07:02:21.688878] I [MSGID: 104045] [glfs-master.c:95:notify]
0-gfapi: New graph 766e622d-3930-3033-2d32-3031362d3034 (0) coming up
[2016-04-27 07:02:21.688921] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-0: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:21.689530] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-1: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:21.689793] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-0: changing port to 49156 (from 0)
[2016-04-27 07:02:21.689951] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-2: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:21.690608] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-0: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:21.690977] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-1: changing port to 49155 (from 0)
[2016-04-27 07:02:21.691032] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-0:
Connected to datastore4-client-0, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:21.691068] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-0:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:21.691148] I [MSGID: 108005]
[afr-common.c:4007:afr_notify] 0-datastore4-replicate-0: Subvolume
'datastore4-client-0' came back up; going online.
[2016-04-27 07:02:21.691235] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-0:
Server lk version = 1
[2016-04-27 07:02:21.691430] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-2: changing port to 49155 (from 0)
[2016-04-27 07:02:21.691867] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-1: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:21.692350] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-1:
Connected to datastore4-client-1, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:21.692369] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-1:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:21.692474] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-2: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:21.692590] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-1:
Server lk version = 1
[2016-04-27 07:02:21.692926] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-2:
Connected to datastore4-client-2, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:21.692942] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-2:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:21.708641] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-2:
Server lk version = 1
[2016-04-27 07:02:21.709796] I [MSGID: 108031]
[afr-common.c:1900:afr_local_discovery_cbk] 0-datastore4-replicate-0:
selecting local read_child datastore4-client-0
[2016-04-27 07:02:21.710401] I [MSGID: 104041]
[glfs-resolve.c:869:__glfs_active_subvol] 0-datastore4: switched to graph
766e622d-3930-3033-2d32-3031362d3034 (0)
[2016-04-27 07:02:21.828061] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-0: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:21.828125] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-1: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:21.828140] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-0: disconnected from
datastore4-client-0. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:21.828163] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-2: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:21.828181] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-1: disconnected from
datastore4-client-1. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:21.828205] W [MSGID: 108001]
[afr-common.c:4090:afr_notify] 0-datastore4-replicate-0: Client-quorum is
not met
[2016-04-27 07:02:21.828235] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-2: disconnected from
datastore4-client-2. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:21.828248] E [MSGID: 108006]
[afr-common.c:4046:afr_notify] 0-datastore4-replicate-0: All subvolumes are
down. Going offline until atleast one of them comes back up.
[2016-04-27 07:02:21.828442] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=84 max=3 total=3
[2016-04-27 07:02:21.829252] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=156 max=5 total=5
[2016-04-27 07:02:21.830686] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=108 max=1 total=1
[2016-04-27 07:02:21.830733] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=588 max=3
total=24
[2016-04-27 07:02:21.830747] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=124 max=3
total=24
[2016-04-27 07:02:21.830765] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=1300 max=2
total=13
[2016-04-27 07:02:21.830781] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=588 max=3
total=24
[2016-04-27 07:02:21.830856] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=124 max=3
total=24
[2016-04-27 07:02:21.830872] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=1300 max=3
total=13
[2016-04-27 07:02:21.830887] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=588 max=4
total=24
[2016-04-27 07:02:21.830899] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=124 max=4
total=24
[2016-04-27 07:02:21.830912] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=1300 max=2
total=13
[2016-04-27 07:02:21.830978] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-replicate-0: size=10524
max=2 total=13
[2016-04-27 07:02:21.831173] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-dht: size=1148 max=0 total=0
[2016-04-27 07:02:21.831240] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-dht: size=2284 max=2 total=9
[2016-04-27 07:02:21.831373] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-shard: size=1396 max=1
total=7
[2016-04-27 07:02:21.831392] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-readdir-ahead: size=52 max=0
total=0
[2016-04-27 07:02:21.831406] I [io-stats.c:2951:fini] 0-datastore4:
io-stats translator unloaded
[2016-04-27 07:02:21.831467] I [MSGID: 101191]
[event-epoll.c:663:event_dispatch_epoll_worker] 0-epoll: Exited thread with
index 1
[2016-04-27 07:02:21.831493] I [MSGID: 101191]
[event-epoll.c:663:event_dispatch_epoll_worker] 0-epoll: Exited thread with
index 2
[2016-04-27 07:02:22.688831] I [MSGID: 104045] [glfs-master.c:95:notify]
0-gfapi: New graph 766e622d-3930-3033-2d32-3031362d3034 (0) coming up
[2016-04-27 07:02:22.688873] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-0: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:22.689466] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-1: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:22.689732] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-0: changing port to 49156 (from 0)
[2016-04-27 07:02:22.689879] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-2: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:22.690547] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-0: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:22.690803] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-1: changing port to 49155 (from 0)
[2016-04-27 07:02:22.690923] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-0:
Connected to datastore4-client-0, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:22.690945] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-0:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:22.691002] I [MSGID: 108005]
[afr-common.c:4007:afr_notify] 0-datastore4-replicate-0: Subvolume
'datastore4-client-0' came back up; going online.
[2016-04-27 07:02:22.691033] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-0:
Server lk version = 1
[2016-04-27 07:02:22.691486] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-2: changing port to 49155 (from 0)
[2016-04-27 07:02:22.691749] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-1: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:22.692262] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-1:
Connected to datastore4-client-1, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:22.692279] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-1:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:22.692489] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-2: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:22.692497] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-1:
Server lk version = 1
[2016-04-27 07:02:22.693084] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-2:
Connected to datastore4-client-2, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:22.693102] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-2:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:22.708424] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-2:
Server lk version = 1
[2016-04-27 07:02:22.709613] I [MSGID: 108031]
[afr-common.c:1900:afr_local_discovery_cbk] 0-datastore4-replicate-0:
selecting local read_child datastore4-client-0
[2016-04-27 07:02:22.710086] I [MSGID: 104041]
[glfs-resolve.c:869:__glfs_active_subvol] 0-datastore4: switched to graph
766e622d-3930-3033-2d32-3031362d3034 (0)
[2016-04-27 07:02:22.850510] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-0: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:22.850579] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-1: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:22.850598] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-0: disconnected from
datastore4-client-0. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:22.850634] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-1: disconnected from
datastore4-client-1. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:22.850639] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-2: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:22.850679] W [MSGID: 108001]
[afr-common.c:4090:afr_notify] 0-datastore4-replicate-0: Client-quorum is
not met
[2016-04-27 07:02:22.850705] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-2: disconnected from
datastore4-client-2. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:22.850718] E [MSGID: 108006]
[afr-common.c:4046:afr_notify] 0-datastore4-replicate-0: All subvolumes are
down. Going offline until atleast one of them comes back up.
[2016-04-27 07:02:22.850832] W [inode.c:1792:inode_table_destroy]
(-->/usr/lib/x86_64-linux-gnu/libgfapi.so.0(glfs_fini+0x3f9)
[0x7f4f48434239]
-->/usr/lib/x86_64-linux-gnu/libglusterfs.so.0(inode_table_destroy_all+0x4e)
[0x7f4f481a584e]
-->/usr/lib/x86_64-linux-gnu/libglusterfs.so.0(inode_table_destroy+0xe3)
[0x7f4f481a5753] ) 0-gfapi: Active inode(0x7f4f334002cc) with refcount(1)
found during cleanup
[2016-04-27 07:02:22.851009] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=84 max=4 total=4
[2016-04-27 07:02:22.851785] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=156 max=5 total=5
[2016-04-27 07:02:22.853155] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=108 max=2 total=2
[2016-04-27 07:02:22.853203] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=588 max=3
total=47
[2016-04-27 07:02:22.853220] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=124 max=3
total=47
[2016-04-27 07:02:22.853239] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=1300 max=2
total=32
[2016-04-27 07:02:22.853257] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=588 max=4
total=46
[2016-04-27 07:02:22.853271] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=124 max=4
total=46
[2016-04-27 07:02:22.853287] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=1300 max=3
total=32
[2016-04-27 07:02:22.853305] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=588 max=4
total=46
[2016-04-27 07:02:22.853387] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=124 max=4
total=46
[2016-04-27 07:02:22.853407] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=1300 max=3
total=32
[2016-04-27 07:02:22.853424] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-replicate-0: size=10524
max=3 total=25
[2016-04-27 07:02:22.853598] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-dht: size=1148 max=0 total=0
[2016-04-27 07:02:22.853660] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-dht: size=2284 max=3 total=17
[2016-04-27 07:02:22.853841] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-shard: size=1396 max=1
total=8
[2016-04-27 07:02:22.853863] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-readdir-ahead: size=52 max=0
total=0
[2016-04-27 07:02:22.853879] I [io-stats.c:2951:fini] 0-datastore4:
io-stats translator unloaded
[2016-04-27 07:02:22.853951] I [MSGID: 101191]
[event-epoll.c:663:event_dispatch_epoll_worker] 0-epoll: Exited thread with
index 1
[2016-04-27 07:02:22.853951] I [MSGID: 101191]
[event-epoll.c:663:event_dispatch_epoll_worker] 0-epoll: Exited thread with
index 2
[2016-04-27 07:02:23.694923] I [MSGID: 104045] [glfs-master.c:95:notify]
0-gfapi: New graph 766e622d-3930-3033-2d32-3031362d3034 (0) coming up
[2016-04-27 07:02:23.694967] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-0: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:23.695603] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-1: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:23.695866] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-0: changing port to 49156 (from 0)
[2016-04-27 07:02:23.696034] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-2: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:23.696707] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-0: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:23.696940] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-1: changing port to 49155 (from 0)
[2016-04-27 07:02:23.697128] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-0:
Connected to datastore4-client-0, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:23.697148] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-0:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:23.697220] I [MSGID: 108005]
[afr-common.c:4007:afr_notify] 0-datastore4-replicate-0: Subvolume
'datastore4-client-0' came back up; going online.
[2016-04-27 07:02:23.697319] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-0:
Server lk version = 1
[2016-04-27 07:02:23.697510] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-2: changing port to 49155 (from 0)
[2016-04-27 07:02:23.697770] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-1: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:23.698338] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-1:
Connected to datastore4-client-1, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:23.698358] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-1:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:23.698451] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-2: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:23.698560] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-1:
Server lk version = 1
[2016-04-27 07:02:23.698993] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-2:
Connected to datastore4-client-2, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:23.699012] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-2:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:23.714625] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-2:
Server lk version = 1
[2016-04-27 07:02:23.715924] I [MSGID: 108031]
[afr-common.c:1900:afr_local_discovery_cbk] 0-datastore4-replicate-0:
selecting local read_child datastore4-client-0
[2016-04-27 07:02:23.716481] I [MSGID: 104041]
[glfs-resolve.c:869:__glfs_active_subvol] 0-datastore4: switched to graph
766e622d-3930-3033-2d32-3031362d3034 (0)
[2016-04-27 07:02:26.752833] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-0: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:26.752896] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-1: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:26.752913] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-0: disconnected from
datastore4-client-0. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:26.752938] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-2: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:26.752945] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-1: disconnected from
datastore4-client-1. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:26.752968] W [MSGID: 108001]
[afr-common.c:4090:afr_notify] 0-datastore4-replicate-0: Client-quorum is
not met
[2016-04-27 07:02:26.752972] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-2: disconnected from
datastore4-client-2. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:26.752988] E [MSGID: 108006]
[afr-common.c:4046:afr_notify] 0-datastore4-replicate-0: All subvolumes are
down. Going offline until atleast one of them comes back up.
[2016-04-27 07:02:26.753114] W [inode.c:1792:inode_table_destroy]
(-->/usr/lib/x86_64-linux-gnu/libgfapi.so.0(glfs_fini+0x3f9)
[0x7f4f48434239]
-->/usr/lib/x86_64-linux-gnu/libglusterfs.so.0(inode_table_destroy_all+0x4e)
[0x7f4f481a584e]
-->/usr/lib/x86_64-linux-gnu/libglusterfs.so.0(inode_table_destroy+0xe3)
[0x7f4f481a5753] ) 0-gfapi: Active inode(0x7f4f334002cc) with refcount(1)
found during cleanup
[2016-04-27 07:02:26.753377] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=84 max=68 total=68
[2016-04-27 07:02:26.754185] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=156 max=69 total=69
[2016-04-27 07:02:26.755549] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=108 max=65 total=70
[2016-04-27 07:02:26.755576] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=588 max=40
total=1319
[2016-04-27 07:02:26.755589] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=124 max=40
total=1319
[2016-04-27 07:02:26.755604] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=1300 max=40
total=1179
[2016-04-27 07:02:26.755618] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=588 max=40
total=1278
[2016-04-27 07:02:26.755672] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=124 max=40
total=1278
[2016-04-27 07:02:26.755686] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=1300 max=40
total=1139
[2016-04-27 07:02:26.755799] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=588 max=34
total=1278
[2016-04-27 07:02:26.755813] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=124 max=34
total=1278
[2016-04-27 07:02:26.755826] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=1300 max=34
total=1139
[2016-04-27 07:02:26.755840] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-replicate-0: size=10524
max=68 total=817
[2016-04-27 07:02:26.756044] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-dht: size=1148 max=0 total=0
[2016-04-27 07:02:26.756079] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-dht: size=2284 max=3
total=425
[2016-04-27 07:02:26.756198] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-shard: size=1396 max=2
total=353
[2016-04-27 07:02:26.756217] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-readdir-ahead: size=52 max=0
total=0
[2016-04-27 07:02:26.756240] I [io-stats.c:2951:fini] 0-datastore4:
io-stats translator unloaded
[2016-04-27 07:02:26.756301] I [MSGID: 101191]
[event-epoll.c:663:event_dispatch_epoll_worker] 0-epoll: Exited thread with
index 2
[2016-04-27 07:02:26.756307] I [MSGID: 101191]
[event-epoll.c:663:event_dispatch_epoll_worker] 0-epoll: Exited thread with
index 1
[2016-04-27 07:02:27.705915] I [MSGID: 104045] [glfs-master.c:95:notify]
0-gfapi: New graph 766e622d-3930-3033-2d32-3031362d3034 (0) coming up
[2016-04-27 07:02:27.705960] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-0: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:27.706592] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-1: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:27.706894] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-0: changing port to 49156 (from 0)
[2016-04-27 07:02:27.707080] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-2: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:27.707725] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-0: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:27.708041] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-1: changing port to 49155 (from 0)
[2016-04-27 07:02:27.708118] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-0:
Connected to datastore4-client-0, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:27.708136] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-0:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:27.708275] I [MSGID: 108005]
[afr-common.c:4007:afr_notify] 0-datastore4-replicate-0: Subvolume
'datastore4-client-0' came back up; going online.
[2016-04-27 07:02:27.708314] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-0:
Server lk version = 1
[2016-04-27 07:02:27.708572] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-2: changing port to 49155 (from 0)
[2016-04-27 07:02:27.708883] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-1: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:27.709394] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-1:
Connected to datastore4-client-1, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:27.709412] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-1:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:27.709500] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-2: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:27.709594] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-1:
Server lk version = 1
[2016-04-27 07:02:27.710035] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-2:
Connected to datastore4-client-2, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:27.710050] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-2:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:27.725555] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-2:
Server lk version = 1
[2016-04-27 07:02:27.726714] I [MSGID: 108031]
[afr-common.c:1900:afr_local_discovery_cbk] 0-datastore4-replicate-0:
selecting local read_child datastore4-client-0
[2016-04-27 07:02:27.727273] I [MSGID: 104041]
[glfs-resolve.c:869:__glfs_active_subvol] 0-datastore4: switched to graph
766e622d-3930-3033-2d32-3031362d3034 (0)
[2016-04-27 07:02:27.846128] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-0: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:27.846199] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-1: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:27.846218] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-0: disconnected from
datastore4-client-0. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:27.846240] I [MSGID: 114021] [client.c:2115:notify]
0-datastore4-client-2: current graph is no longer active, destroying
rpc_client
[2016-04-27 07:02:27.846262] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-1: disconnected from
datastore4-client-1. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:27.846280] I [MSGID: 114018]
[client.c:2030:client_rpc_notify] 0-datastore4-client-2: disconnected from
datastore4-client-2. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-04-27 07:02:27.846281] W [MSGID: 108001]
[afr-common.c:4090:afr_notify] 0-datastore4-replicate-0: Client-quorum is
not met
[2016-04-27 07:02:27.846321] E [MSGID: 108006]
[afr-common.c:4046:afr_notify] 0-datastore4-replicate-0: All subvolumes are
down. Going offline until atleast one of them comes back up.
[2016-04-27 07:02:27.846432] W [inode.c:1792:inode_table_destroy]
(-->/usr/lib/x86_64-linux-gnu/libgfapi.so.0(glfs_fini+0x3f9)
[0x7f4f48434239]
-->/usr/lib/x86_64-linux-gnu/libglusterfs.so.0(inode_table_destroy_all+0x4e)
[0x7f4f481a584e]
-->/usr/lib/x86_64-linux-gnu/libglusterfs.so.0(inode_table_destroy+0xe3)
[0x7f4f481a5753] ) 0-gfapi: Active inode(0x7f4f334002cc) with refcount(1)
found during cleanup
[2016-04-27 07:02:27.846595] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=84 max=4 total=4
[2016-04-27 07:02:27.847357] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=156 max=5 total=5
[2016-04-27 07:02:27.848715] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-gfapi: size=108 max=2 total=6
[2016-04-27 07:02:27.848759] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=588 max=3
total=34
[2016-04-27 07:02:27.848772] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=124 max=3
total=34
[2016-04-27 07:02:27.848787] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-0: size=1300 max=2
total=19
[2016-04-27 07:02:27.848801] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=588 max=3
total=29
[2016-04-27 07:02:27.848812] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=124 max=3
total=29
[2016-04-27 07:02:27.848825] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-1: size=1300 max=2
total=15
[2016-04-27 07:02:27.848838] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=588 max=4
total=29
[2016-04-27 07:02:27.848849] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=124 max=4
total=29
[2016-04-27 07:02:27.848861] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-client-2: size=1300 max=3
total=15
[2016-04-27 07:02:27.848875] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-replicate-0: size=10524
max=2 total=25
[2016-04-27 07:02:27.849040] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-dht: size=1148 max=0 total=0
[2016-04-27 07:02:27.849127] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-dht: size=2284 max=2 total=21
[2016-04-27 07:02:27.849227] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-shard: size=1396 max=1
total=10
[2016-04-27 07:02:27.849323] I [MSGID: 101053]
[mem-pool.c:616:mem_pool_destroy] 0-datastore4-readdir-ahead: size=52 max=0
total=0
[2016-04-27 07:02:27.849346] I [io-stats.c:2951:fini] 0-datastore4:
io-stats translator unloaded
[2016-04-27 07:02:27.849412] I [MSGID: 101191]
[event-epoll.c:663:event_dispatch_epoll_worker] 0-epoll: Exited thread with
index 1
Formatting
'gluster://vnb.proxmox.softlog/datastore4/images/910/vm-910-disk-1.qcow2',
fmt=qcow2 size=34359738368 encryption=off cluster_size=65536
preallocation=metadata lazy_refcounts=off refcount_bits=16
[2016-04-27 07:02:27.849412] I [MSGID: 101191]
[event-epoll.c:663:event_dispatch_epoll_worker] 0-epoll: Exited thread with
index 2
new volume ID is 'gluster4:910/vm-910-disk-1.qcow2'
map 'drive-scsi0' to
'gluster://vnb.proxmox.softlog/datastore4/images/910/vm-910-disk-1.qcow2'
(write zeros = 0)
[2016-04-27 07:02:28.733310] I [MSGID: 104045] [glfs-master.c:95:notify]
0-gfapi: New graph 766e622d-3930-3032-2d32-3031362d3034 (0) coming up
[2016-04-27 07:02:28.733357] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-0: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:28.733998] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-1: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:28.734250] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-0: changing port to 49156 (from 0)
[2016-04-27 07:02:28.734475] I [MSGID: 114020] [client.c:2106:notify]
0-datastore4-client-2: parent translators are ready, attempting connect on
transport
[2016-04-27 07:02:28.735120] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-0: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:28.735455] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-1: changing port to 49155 (from 0)
[2016-04-27 07:02:28.735567] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-0:
Connected to datastore4-client-0, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:28.735585] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-0:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:28.735653] I [MSGID: 108005]
[afr-common.c:4007:afr_notify] 0-datastore4-replicate-0: Subvolume
'datastore4-client-0' came back up; going online.
[2016-04-27 07:02:28.735722] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-0:
Server lk version = 1
[2016-04-27 07:02:28.735915] I [rpc-clnt.c:1868:rpc_clnt_reconfig]
0-datastore4-client-2: changing port to 49155 (from 0)
[2016-04-27 07:02:28.736400] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-1: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:28.736916] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-datastore4-client-2: Using Program GlusterFS 3.3, Num (1298437), Version
(330)
[2016-04-27 07:02:28.736950] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-1:
Connected to datastore4-client-1, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:28.736970] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-1:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:28.737195] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-1:
Server lk version = 1
[2016-04-27 07:02:28.737370] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-datastore4-client-2:
Connected to datastore4-client-2, attached to remote volume
'/tank/vmdata/datastore4'.
[2016-04-27 07:02:28.737389] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-datastore4-client-2:
Server and Client lk-version numbers are not same, reopening the fds
[2016-04-27 07:02:28.753072] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-datastore4-client-2:
Server lk version = 1
[2016-04-27 07:02:28.754705] I [MSGID: 108031]
[afr-common.c:1900:afr_local_discovery_cbk] 0-datastore4-replicate-0:
selecting local read_child datastore4-client-0
[2016-04-27 07:02:28.755138] I [MSGID: 104041]
[glfs-resolve.c:869:__glfs_active_subvol] 0-datastore4: switched to graph
766e622d-3930-3032-2d32-3031362d3034 (0)

*** (process:9002): ERROR **: vma_reader_register_bs for stream drive-scsi0
failed - unexpected size 34365243392 != 34359738368/bin/bash: line 1:  9001
Broken pipe             lzop -d -c
/mnt/nas-backups-smb/dump/vzdump-qemu-910-2016_04_23-08_22_07.vma.lzo
9002 Trace/breakpoint trap   | vma extract -v -r
/var/tmp/vzdumptmp8999.fifo - /var/tmp/vzdumptmp8999temporary volume
'gluster4:910/vm-910-disk-1.qcow2' sucessfuly removedTASK ERROR: command
'lzop -d -c
/mnt/nas-backups-smb/dump/vzdump-qemu-910-2016_04_23-08_22_07.vma.lzo|vma
extract -v -r /var/tmp/vzdumptmp8999.fifo - /var/tmp/vzdumptmp8999' failed:
exit code 133*

-- 
Lindsay
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.gluster.org/pipermail/gluster-users/attachments/20160427/39795965/attachment.html>