Attachment 1482096 Details for Bug 1627060 – patchy-rebalance.log for s390x

patchy-rebalance.log for s390x

rebalance_s390x.log (text/plain), 46.61 KB, created by abhays on 2018-09-10 11:08:57 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: abhays

Created: 2018-09-10 11:08:57 UTC

Size: 46.61 KB

patch

obsolete

>[2018-09-05 09:36:34.888926] I [MSGID: 100030] [glusterfsd.c:2741:main] 0-/usr/local/sbin/glusterfs: Started running /usr/local/sbin/glusterfs version 4.1.1 (args: /usr/local/sbin/glusterfs -s localhost --volfile-id rebalance/patchy --xlator-option *dht.use-readdirp=yes --xlator-option *dht.lookup-unhashed=yes --xlator-option *dht.assert-no-child-down=yes --xlator-option *dht.readdir-optimize=on --process-name rebalance --xlator-option *dht.rebalance-cmd=5 --xlator-option *dht.node-uuid=f60c13d9-dedb-44ca-ad7f-b89a1e184979 --xlator-option *dht.commit-hash=3699186961 --socket-file /var/run/gluster/gluster-rebalance-6dd0e966-80ba-496a-a01a-23c9461cac95.sock --pid-file /var/lib/glusterd/vols/patchy/rebalance/f60c13d9-dedb-44ca-ad7f-b89a1e184979.pid -l /var/log/glusterfs/patchy-rebalance.log)
>[2018-09-05 09:36:34.904662] I [MSGID: 101190] [event-epoll.c:617:event_dispatch_epoll_worker] 0-epoll: Started thread with index 1
>[2018-09-05 09:36:39.899181] I [MSGID: 109104] [dht-shared.c:710:dht_init] 0-patchy-dht: dht_init using commit hash 3699186961
>[2018-09-05 09:36:39.900846] I [MSGID: 114020] [client.c:2328:notify] 0-patchy-client-0: parent translators are ready, attempting connect on transport
>[2018-09-05 09:36:39.901072] I [MSGID: 101190] [event-epoll.c:617:event_dispatch_epoll_worker] 0-epoll: Started thread with index 2
>[2018-09-05 09:36:39.904978] I [MSGID: 114020] [client.c:2328:notify] 0-patchy-client-1: parent translators are ready, attempting connect on transport
>[2018-09-05 09:36:39.905042] W [rpc-clnt.c:1753:rpc_clnt_submit] 0-patchy-client-0: error returned while attempting to connect to host:(null), port:0
>[2018-09-05 09:36:39.905171] W [rpc-clnt.c:1753:rpc_clnt_submit] 0-patchy-client-0: error returned while attempting to connect to host:(null), port:0
>[2018-09-05 09:36:39.905228] I [rpc-clnt.c:2105:rpc_clnt_reconfig] 0-patchy-client-0: changing port to 49156 (from 0)
>Final graph:
>+------------------------------------------------------------------------------+
>  1: volume patchy-client-0
>  2:     type protocol/client
>  3:     option ping-timeout 42
>  4:     option remote-host hostname
>  5:     option remote-subvolume /d/backends/patchy1
>  6:     option transport-type socket
>  7:     option transport.address-family inet
>  8:     option username 1c9e845f-4ca9-4c41-b513-089e9097298e
>  9:     option password 00292176-62bb-49d3-9e4b-04222c8d7e16
> 10:     option transport.tcp-user-timeout 0
> 11:     option transport.socket.keepalive-time 20
> 12:     option transport.socket.keepalive-interval 2
> 13:     option transport.socket.keepalive-count 9
> 14: end-volume
> 15:  
> 16: volume patchy-client-1
> 17:     type protocol/client
> 18:     option ping-timeout 42
> 19:     option remote-host hostname
> 20:     option remote-subvolume /d/backends/patchy3
> 21:     option transport-type socket
> 22:     option transport.address-family inet
> 23:     option username 1c9e845f-4ca9-4c41-b513-089e9097298e
> 24:     option password 00292176-62bb-49d3-9e4b-04222c8d7e16
> 25:     option transport.tcp-user-timeout 0
> 26:     option transport.socket.keepalive-time 20
> 27:     option transport.socket.keepalive-interval 2
> 28:     option transport.socket.keepalive-count 9
> 29: end-volume
> 30:  
> 31: volume patchy-dht
> 32:     type cluster/distribute
> 33:     option use-readdirp yes
> 34:     option lookup-unhashed yes
> 35:     option assert-no-child-down yes
> 36:     option readdir-optimize on
> 37:     option rebalance-cmd 5
> 38:     option node-uuid f60c13d9-dedb-44ca-ad7f-b89a1e184979
> 39:     option commit-hash 3699186961
> 40:     option lock-migration off
> 41:     option force-migration off
> 42:     subvolumes patchy-client-0 patchy-client-1
> 43: end-volume
> 44:  
> 45: volume patchy
> 46:     type debug/io-stats
> 47:     option log-level INFO
> 48:     option latency-measurement off
> 49:     option count-fop-hits off
> 50:     subvolumes patchy-dht
> 51: end-volume
> 52:  
>+------------------------------------------------------------------------------+
>[2018-09-05 09:36:39.910693] W [rpc-clnt.c:1753:rpc_clnt_submit] 0-patchy-client-1: error returned while attempting to connect to host:(null), port:0
>[2018-09-05 09:36:39.910835] W [rpc-clnt.c:1753:rpc_clnt_submit] 0-patchy-client-1: error returned while attempting to connect to host:(null), port:0
>[2018-09-05 09:36:39.910894] I [rpc-clnt.c:2105:rpc_clnt_reconfig] 0-patchy-client-1: changing port to 49159 (from 0)
>[2018-09-05 09:36:39.911699] W [rpc-clnt.c:1753:rpc_clnt_submit] 0-patchy-client-0: error returned while attempting to connect to host:(null), port:0
>[2018-09-05 09:36:39.911869] W [rpc-clnt.c:1753:rpc_clnt_submit] 0-patchy-client-0: error returned while attempting to connect to host:(null), port:0
>[2018-09-05 09:36:39.912375] I [MSGID: 114046] [client-handshake.c:1176:client_setvolume_cbk] 0-patchy-client-0: Connected to patchy-client-0, attached to remote volume '/d/backends/patchy1'.
>[2018-09-05 09:36:39.916087] W [rpc-clnt.c:1753:rpc_clnt_submit] 0-patchy-client-1: error returned while attempting to connect to host:(null), port:0
>[2018-09-05 09:36:39.913479]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 195 0 rebalance_completed ++++++++++
>[2018-09-05 09:36:39.917174] W [rpc-clnt.c:1753:rpc_clnt_submit] 0-patchy-client-1: error returned while attempting to connect to host:(null), port:0
>[2018-09-05 09:36:39.917632] I [MSGID: 114046] [client-handshake.c:1176:client_setvolume_cbk] 0-patchy-client-1: Connected to patchy-client-1, attached to remote volume '/d/backends/patchy3'.
>[2018-09-05 09:36:39.919508] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.919519] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.919525] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.920885] I [MSGID: 109005] [dht-selfheal.c:2342:dht_selfheal_directory] 0-patchy-dht: Directory selfheal failed: Unable to form layout for directory /
>[2018-09-05 09:36:39.920968] I [dht-rebalance.c:4600:gf_defrag_start_crawl] 0-patchy-dht: gf_defrag_start_crawl using commit hash 3699186961
>[2018-09-05 09:36:39.921905] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /
>[2018-09-05 09:36:39.923853] E [MSGID: 109039] [dht-common.c:4080:dht_find_local_subvol_cbk] 0-patchy-dht: getxattr err for dir [No data available]
>[2018-09-05 09:36:39.923883] E [MSGID: 109039] [dht-common.c:4080:dht_find_local_subvol_cbk] 0-patchy-dht: getxattr err for dir [No data available]
>[2018-09-05 09:36:39.924482] I [MSGID: 0] [dht-rebalance.c:4674:gf_defrag_start_crawl] 0-patchy-dht: local subvols are patchy-client-0
>[2018-09-05 09:36:39.924505] I [MSGID: 0] [dht-rebalance.c:4680:gf_defrag_start_crawl] 0-patchy-dht: node uuids are f60c13d9-dedb-44ca-ad7f-b89a1e184979
>[2018-09-05 09:36:39.924512] I [MSGID: 0] [dht-rebalance.c:4674:gf_defrag_start_crawl] 0-patchy-dht: local subvols are patchy-client-1
>[2018-09-05 09:36:39.924520] I [MSGID: 0] [dht-rebalance.c:4680:gf_defrag_start_crawl] 0-patchy-dht: node uuids are f60c13d9-dedb-44ca-ad7f-b89a1e184979
>[2018-09-05 09:36:39.924808] I [MSGID: 0] [dht-rebalance.c:4358:gf_defrag_total_file_size] 0-patchy-dht: local subvol: patchy-client-0,cnt = 5000048640
>[2018-09-05 09:36:39.925080] I [MSGID: 0] [dht-rebalance.c:4358:gf_defrag_total_file_size] 0-patchy-dht: local subvol: patchy-client-1,cnt = 5000048640
>[2018-09-05 09:36:39.925090] I [MSGID: 0] [dht-rebalance.c:4362:gf_defrag_total_file_size] 0-patchy-dht: Total size files = 10000097280
>[2018-09-05 09:36:39.925350] I [MSGID: 0] [dht-rebalance.c:4387:gf_defrag_total_file_cnt] 0-patchy-dht: local subvol: patchy-client-0,cnt = 87986
>[2018-09-05 09:36:39.925622] I [MSGID: 0] [dht-rebalance.c:4387:gf_defrag_total_file_cnt] 0-patchy-dht: local subvol: patchy-client-1,cnt = 87986
>[2018-09-05 09:36:39.925632] I [MSGID: 0] [dht-rebalance.c:4398:gf_defrag_total_file_cnt] 0-patchy-dht: Total number of files = 175972
>[2018-09-05 09:36:39.925789] I [dht-rebalance.c:4756:gf_defrag_start_crawl] 0-DHT: Thread[0] creation successful
>[2018-09-05 09:36:39.925832] I [dht-rebalance.c:4756:gf_defrag_start_crawl] 0-DHT: Thread[1] creation successful
>[2018-09-05 09:36:39.925863] I [dht-rebalance.c:4756:gf_defrag_start_crawl] 0-DHT: Thread[2] creation successful
>[2018-09-05 09:36:39.925895] I [dht-rebalance.c:4756:gf_defrag_start_crawl] 0-DHT: Thread[3] creation successful
>[2018-09-05 09:36:39.925911] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.925917] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.925923] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.926487] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.926497] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.926999] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.927009] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.927762] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.927817] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:39.928494] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:39.928953] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.928961] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.929333] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.929341] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.929943] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.929973] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.930600] I [MSGID: 109063] [dht-layout.c:693:dht_layout_normalize] 0-patchy-dht: Found anomalies in /.trashcan/1 (gfid = 1b90a8ef-45c6-4660-9f21-eff8ec682f3a). Holes=1 overlaps=0
>[2018-09-05 09:36:39.931045] I [dict.c:491:dict_get] (-->/usr/local/lib/glusterfs/4.1.1/xlator/protocol/client.so(+0x630a4) [0x3ff897630a4] -->/usr/local/lib/glusterfs/4.1.1/xlator/cluster/distribute.so(+0x2443e) [0x3ff8962443e] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x116) [0x3ff94b1cb2e] ) 0-dict: !this || key=trusted.glusterfs.dht.mds [Invalid argument]
>[2018-09-05 09:36:39.932789] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.933310] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.933319] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.933699] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.933707] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.934232] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.934263] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.934854] I [MSGID: 109063] [dht-layout.c:693:dht_layout_normalize] 0-patchy-dht: Found anomalies in /.trashcan/1/2 (gfid = 34e3ae28-2957-4267-b534-177d3fb9c59b). Holes=1 overlaps=0
>[2018-09-05 09:36:39.935240] I [dict.c:491:dict_get] (-->/usr/local/lib/glusterfs/4.1.1/xlator/protocol/client.so(+0x630a4) [0x3ff897630a4] -->/usr/local/lib/glusterfs/4.1.1/xlator/cluster/distribute.so(+0x2443e) [0x3ff8962443e] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x116) [0x3ff94b1cb2e] ) 0-dict: !this || key=trusted.glusterfs.dht.mds [Invalid argument]
>[2018-09-05 09:36:39.936759] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.937267] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.937276] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.937663] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.937672] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.938214] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.938241] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.938936] I [MSGID: 109063] [dht-layout.c:693:dht_layout_normalize] 0-patchy-dht: Found anomalies in /.trashcan/1/2/3 (gfid = f847c954-6e2c-41f8-89cc-c426261b8ad8). Holes=1 overlaps=0
>[2018-09-05 09:36:39.939341] I [dict.c:491:dict_get] (-->/usr/local/lib/glusterfs/4.1.1/xlator/protocol/client.so(+0x630a4) [0x3ff897630a4] -->/usr/local/lib/glusterfs/4.1.1/xlator/cluster/distribute.so(+0x2443e) [0x3ff8962443e] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x116) [0x3ff94b1cb2e] ) 0-dict: !this || key=trusted.glusterfs.dht.mds [Invalid argument]
>[2018-09-05 09:36:39.940893] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.941402] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.941410] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.941801] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.941810] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.942380] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.942403] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.942410] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.943163] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.943202] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /.trashcan/1/2/3
>[2018-09-05 09:36:39.943859] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /.trashcan/1/2/3
>[2018-09-05 09:36:39.943873] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.943885] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.945794] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /.trashcan/1/2/3 took 0.00 secs
>[2018-09-05 09:36:39.946725] I [dht-rebalance.c:2770:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() calling gf_defrag_should_i_migrate()
>[2018-09-05 09:36:39.946735] I [dht-rebalance.c:2778:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside gf_defrag_should_i_migrate()
>[2018-09-05 09:36:39.946763] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.948101] I [dht-rebalance.c:2794:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside syncop_lookup()
>[2018-09-05 09:36:39.948116] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.948123] I [dht-rebalance.c:2808:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_hashed()
>[2018-09-05 09:36:39.948130] I [dht-rebalance.c:2819:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_cached()
>[2018-09-05 09:36:39.948137] I [dht-rebalance.c:2823:gf_defrag_migrate_single_file] 0-patchy-dht: Attempting to migrate data 3 with gfid f847c954-6e2c-41f8-89cc-c426261b8ad8 from patchy-client-0 -> patchy-client-0
>[2018-09-05 09:36:39.948145] I [dht-rebalance.c:2827:gf_defrag_migrate_single_file] 0-patchy-dht: hashed_subvol == cached_subvol
>[2018-09-05 09:36:39.948432] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.948440] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.948932] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.948972] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /.trashcan/1/2
>[2018-09-05 09:36:39.950749] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /.trashcan/1/2
>[2018-09-05 09:36:39.950766] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.950772] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.952789] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /.trashcan/1/2 took 0.00 secs
>[2018-09-05 09:36:39.953800] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.953810] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.954304] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.954342] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /.trashcan/1
>[2018-09-05 09:36:39.955123] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /.trashcan/1
>[2018-09-05 09:36:39.955144] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.955151] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.957088] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /.trashcan/1 took 0.00 secs
>[2018-09-05 09:36:39.957991] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.958865] I [MSGID: 109063] [dht-layout.c:693:dht_layout_normalize] 0-patchy-dht: Found anomalies in /.trashcan/internal_op (gfid = 00000000-0000-0000-0000-000000000006). Holes=1 overlaps=0
>[2018-09-05 09:36:39.958890] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.959977] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.960491] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.960500] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.961202] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.961213] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.961765] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.961787] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.961794] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.962267] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.962289] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /.trashcan/internal_op
>[2018-09-05 09:36:39.963173] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /.trashcan/internal_op
>[2018-09-05 09:36:39.963190] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.963197] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.965187] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /.trashcan/internal_op took 0.00 secs
>[2018-09-05 09:36:39.966100] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.966110] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.966555] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.966593] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /.trashcan
>[2018-09-05 09:36:39.967563] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /.trashcan
>[2018-09-05 09:36:39.967579] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.967586] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.969352] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /.trashcan took 0.00 secs
>[2018-09-05 09:36:39.970330] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:39.971365] I [MSGID: 109063] [dht-layout.c:693:dht_layout_normalize] 0-patchy-dht: Found anomalies in /1 (gfid = 05286a46-26eb-4cb1-b1c4-54500c21e23c). Holes=1 overlaps=0
>[2018-09-05 09:36:39.971833] I [dict.c:491:dict_get] (-->/usr/local/lib/glusterfs/4.1.1/xlator/protocol/client.so(+0x630a4) [0x3ff897630a4] -->/usr/local/lib/glusterfs/4.1.1/xlator/cluster/distribute.so(+0x2443e) [0x3ff8962443e] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x116) [0x3ff94b1cb2e] ) 0-dict: !this || key=trusted.glusterfs.dht.mds [Invalid argument]
>[2018-09-05 09:36:39.973451] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:39.974110] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.974121] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.974562] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.974572] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.975225] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.975298] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.975964] I [MSGID: 109063] [dht-layout.c:693:dht_layout_normalize] 0-patchy-dht: Found anomalies in /1/2 (gfid = 0f7f2fae-1827-411e-8bbd-3fd2106985d1). Holes=1 overlaps=0
>[2018-09-05 09:36:39.976440] I [dict.c:491:dict_get] (-->/usr/local/lib/glusterfs/4.1.1/xlator/protocol/client.so(+0x630a4) [0x3ff897630a4] -->/usr/local/lib/glusterfs/4.1.1/xlator/cluster/distribute.so(+0x2443e) [0x3ff8962443e] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x116) [0x3ff94b1cb2e] ) 0-dict: !this || key=trusted.glusterfs.dht.mds [Invalid argument]
>[2018-09-05 09:36:39.978026] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.978608] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.978619] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.979105] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.979115] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.979716] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.979769] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:39.980611] I [MSGID: 109063] [dht-layout.c:693:dht_layout_normalize] 0-patchy-dht: Found anomalies in /1/2/3 (gfid = 2d024ca2-a921-4463-b34a-fdcb5ad88fbe). Holes=1 overlaps=0
>[2018-09-05 09:36:39.982353] I [dict.c:491:dict_get] (-->/usr/local/lib/glusterfs/4.1.1/xlator/protocol/client.so(+0x630a4) [0x3ff897630a4] -->/usr/local/lib/glusterfs/4.1.1/xlator/cluster/distribute.so(+0x2443e) [0x3ff8962443e] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x116) [0x3ff94b1cb2e] ) 0-dict: !this || key=trusted.glusterfs.dht.mds [Invalid argument]
>[2018-09-05 09:36:39.983848] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:39.984404] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:39.984625] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.984638] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.985149] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.985160] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.985798] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.985837] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.985849] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.986322] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.986355] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /1/2/3
>[2018-09-05 09:36:39.987184] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /1/2/3
>[2018-09-05 09:36:39.987206] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.987213] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.988331] I [dht-rebalance.c:2770:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() calling gf_defrag_should_i_migrate()
>[2018-09-05 09:36:39.988342] I [dht-rebalance.c:2778:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside gf_defrag_should_i_migrate()
>[2018-09-05 09:36:39.988365] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.988836] I [dht-rebalance.c:2794:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside syncop_lookup()
>[2018-09-05 09:36:39.988849] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:39.988855] I [dht-rebalance.c:2808:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_hashed()
>[2018-09-05 09:36:39.988862] I [dht-rebalance.c:2819:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_cached()
>[2018-09-05 09:36:39.988868] I [dht-rebalance.c:2823:gf_defrag_migrate_single_file] 0-patchy-dht: Attempting to migrate data 3 with gfid 2d024ca2-a921-4463-b34a-fdcb5ad88fbe from patchy-client-0 -> patchy-client-0
>[2018-09-05 09:36:39.988875] I [dht-rebalance.c:2827:gf_defrag_migrate_single_file] 0-patchy-dht: hashed_subvol == cached_subvol
>[2018-09-05 09:36:39.989381] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /1/2/3 took 0.00 secs
>[2018-09-05 09:36:39.990319] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.990328] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.990839] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.990878] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /1/2
>[2018-09-05 09:36:39.991715] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /1/2
>[2018-09-05 09:36:39.991740] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.991748] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.993902] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /1/2 took 0.00 secs
>[2018-09-05 09:36:39.994848] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.994859] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.995390] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:39.995429] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /1
>[2018-09-05 09:36:39.996220] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /1
>[2018-09-05 09:36:39.996239] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:39.996250] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:39.998135] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /1 took 0.00 secs
>[2018-09-05 09:36:39.999108] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:40.000041] I [MSGID: 109063] [dht-layout.c:693:dht_layout_normalize] 0-patchy-dht: Found anomalies in /a (gfid = c7accffe-a497-4f9d-ba89-dab3b4092960). Holes=1 overlaps=0
>[2018-09-05 09:36:40.000551] I [dict.c:491:dict_get] (-->/usr/local/lib/glusterfs/4.1.1/xlator/protocol/client.so(+0x630a4) [0x3ff897630a4] -->/usr/local/lib/glusterfs/4.1.1/xlator/cluster/distribute.so(+0x2443e) [0x3ff8962443e] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x116) [0x3ff94b1cb2e] ) 0-dict: !this || key=trusted.glusterfs.dht.mds [Invalid argument]
>[2018-09-05 09:36:40.002107] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-1
>[2018-09-05 09:36:40.002754] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:40.002766] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:40.003174] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:40.003182] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:40.003831] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:40.003874] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:40.003881] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:40.004276] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:40.004300] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /a
>[2018-09-05 09:36:40.005019] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /a
>[2018-09-05 09:36:40.005036] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:40.005042] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:40.006140] I [dht-rebalance.c:2770:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() calling gf_defrag_should_i_migrate()
>[2018-09-05 09:36:40.006149] I [dht-rebalance.c:2778:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside gf_defrag_should_i_migrate()
>[2018-09-05 09:36:40.006163] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:40.006337] I [dht-rebalance.c:2794:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside syncop_lookup()
>[2018-09-05 09:36:40.006346] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:40.006352] I [dht-rebalance.c:2808:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_hashed()
>[2018-09-05 09:36:40.006358] I [dht-rebalance.c:2819:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_cached()
>[2018-09-05 09:36:40.006364] I [dht-rebalance.c:2823:gf_defrag_migrate_single_file] 0-patchy-dht: Attempting to migrate data a with gfid c7accffe-a497-4f9d-ba89-dab3b4092960 from patchy-client-0 -> patchy-client-0
>[2018-09-05 09:36:40.006371] I [dht-rebalance.c:2827:gf_defrag_migrate_single_file] 0-patchy-dht: hashed_subvol == cached_subvol
>[2018-09-05 09:36:40.007121] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir /a took 0.00 secs
>[2018-09-05 09:36:40.008215] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:40.008225] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:40.008754] I [dht-helper.c:934:dht_last_up_subvol] 0-patchy-dht: dht_last_up_subvol() returns with child = patchy-client-1
>[2018-09-05 09:36:40.008795] I [MSGID: 109081] [dht-common.c:5628:dht_setxattr] 0-patchy-dht: fixing the layout of /
>[2018-09-05 09:36:40.009632] I [dht-rebalance.c:3354:gf_defrag_process_dir] 0-patchy-dht: migrate data called on /
>[2018-09-05 09:36:40.009652] I [dht-helper.c:903:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with time = Wed Sep  5 09:36:39 2018
>
>[2018-09-05 09:36:40.009660] I [dht-helper.c:905:dht_first_up_subvol] 0-patchy-dht: dht_first_up_subvol() returns with child = patchy-client-0
>[2018-09-05 09:36:40.010903] I [dht-rebalance.c:2770:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() calling gf_defrag_should_i_migrate()
>[2018-09-05 09:36:40.010912] I [dht-rebalance.c:2778:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside gf_defrag_should_i_migrate()
>[2018-09-05 09:36:40.010937] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:40.011987] I [dht-rebalance.c:2794:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside syncop_lookup()
>[2018-09-05 09:36:40.012003] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:40.012010] I [dht-rebalance.c:2808:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_hashed()
>[2018-09-05 09:36:40.012020] I [dht-rebalance.c:2819:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_cached()
>[2018-09-05 09:36:40.012027] I [dht-rebalance.c:2823:gf_defrag_migrate_single_file] 0-patchy-dht: Attempting to migrate data (null) with gfid 00000000-0000-0000-0000-000000000001 from patchy-client-0 -> patchy-client-0
>[2018-09-05 09:36:40.012034] I [dht-rebalance.c:2827:gf_defrag_migrate_single_file] 0-patchy-dht: hashed_subvol == cached_subvol
>[2018-09-05 09:36:40.012552] I [dht-rebalance.c:2770:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() calling gf_defrag_should_i_migrate()
>[2018-09-05 09:36:40.012562] I [dht-rebalance.c:2778:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside gf_defrag_should_i_migrate()
>[2018-09-05 09:36:40.012584] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:40.013305] I [dht-rebalance.c:3568:gf_defrag_process_dir] 0-patchy-dht: Migration operation on dir / took 0.00 secs
>[2018-09-05 09:36:40.013289] I [dht-rebalance.c:2794:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside syncop_lookup()
>[2018-09-05 09:36:40.013789] I [dht-helper.c:986:dht_subvol_get_hashed] 0-patchy-dht: dht_subvol_get_hashed() returns with hashed_subvol = patchy-client-0
>[2018-09-05 09:36:40.013797] I [dht-rebalance.c:2808:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_hashed()
>[2018-09-05 09:36:40.013821] I [dht-rebalance.c:2819:gf_defrag_migrate_single_file] 0-patchy-dht: gf_defrag_migrate_single_file() outside dht_subvol_get_cached()
>[2018-09-05 09:36:40.013828] I [dht-rebalance.c:2823:gf_defrag_migrate_single_file] 0-patchy-dht: Attempting to migrate data (null) with gfid 00000000-0000-0000-0000-000000000001 from patchy-client-0 -> patchy-client-0
>[2018-09-05 09:36:40.013835] I [dht-rebalance.c:2827:gf_defrag_migrate_single_file] 0-patchy-dht: hashed_subvol == cached_subvol
>[2018-09-05 09:36:40.016128] I [MSGID: 0] [dht-rebalance.c:4979:gf_defrag_get_estimates_based_on_size] 0-glusterfs: Rebalance estimates will not be available for the first 600 seconds.
>[2018-09-05 09:36:40.016142] I [dht-rebalance.c:5150:gf_defrag_status_get] 0-glusterfs: TIME: Estimated total time to complete (size)= 0 seconds, seconds left = 0
>[2018-09-05 09:36:40.016161] I [MSGID: 109028] [dht-rebalance.c:5230:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 1.00 secs
>[2018-09-05 09:36:40.016171] I [MSGID: 109028] [dht-rebalance.c:5234:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 5, failures: 0, skipped: 0
>[2018-09-05 09:36:40.040632] I [dht-rebalance.c:4805:gf_defrag_start_crawl] 0-DHT: crawling file-system completed
>[2018-09-05 09:36:40.041136] I [MSGID: 109028] [dht-rebalance.c:5230:gf_defrag_status_get] 0-patchy-dht: Rebalance is completed. Time taken is 1.00 secs
>[2018-09-05 09:36:40.041158] I [MSGID: 109028] [dht-rebalance.c:5234:gf_defrag_status_get] 0-patchy-dht: Files migrated: 0, size: 0, lookups: 5, failures: 0, skipped: 0
>[2018-09-05 09:36:40.041374] W [glusterfsd.c:1514:cleanup_and_exit] (-->/lib64/libpthread.so.0(+0x81e2) [0x3ff946081e2] -->/usr/local/sbin/glusterfs(glusterfs_sigwaiter+0xce) [0x8000adfe] -->/usr/local/sbin/glusterfs(cleanup_and_exit+0x72) [0x8000ac22] ) 0-: received signum (15), shutting down
>[2018-09-05 09:36:41.144432]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 201 Y wildcard_exists /d/backends/patchy3/1 /d/backends/patchy3/a ++++++++++
>[2018-09-05 09:36:41.160284]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 202 Y wildcard_exists /d/backends/patchy1/.trashcan/internal_op/* ++++++++++
>[2018-09-05 09:36:41.176537]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 205 Y force_umount /mnt/glusterfs/0 ++++++++++
>[2018-09-05 09:36:41.225964]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 208 gluster --mode=script --wignore volume stop patchy force ++++++++++
>[2018-09-05 09:36:43.596828]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 211 gluster --mode=script --wignore volume create patchy1 replica 2 hostname:/d/backends/patchy11 hostname:/d/backends/patchy12 ++++++++++
>[2018-09-05 09:36:43.713735]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 214 patchy1 volinfo_field patchy1 Volume Name ++++++++++
>[2018-09-05 09:36:43.794104]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 215 Replicate volinfo_field patchy1 Type ++++++++++
>[2018-09-05 09:36:43.869928]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 216 Created volinfo_field patchy1 Status ++++++++++
>[2018-09-05 09:36:43.950705]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 217 2 brick_count patchy1 ++++++++++
>[2018-09-05 09:36:44.036682]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 220 gluster --mode=script --wignore volume set patchy1 features.trash on ++++++++++
>[2018-09-05 09:36:44.161818]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 221 gluster --mode=script --wignore volume set patchy1 features.trash-internal-op on ++++++++++
>[2018-09-05 09:36:44.274591]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 222 on volinfo_field patchy1 features.trash ++++++++++
>[2018-09-05 09:36:44.352908]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 223 on volinfo_field patchy1 features.trash-internal-op ++++++++++
>[2018-09-05 09:36:44.439223]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 224 start_vol patchy1 /mnt/glusterfs/1 /mnt/glusterfs/1/.trashcan ++++++++++
>[2018-09-05 09:36:45.695292]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 227 [ -d /mnt/glusterfs/1/.trashcan/internal_op ] ++++++++++
>[2018-09-05 09:36:45.724053]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 231 [ -e /d/backends/patchy11/self -a -e /d/backends/patchy12/self ] ++++++++++
>[2018-09-05 09:36:48.769720]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 235 1 online_brick_count ++++++++++
>[2018-09-05 09:36:49.225432]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 237 Y wildcard_exists /d/backends/patchy12/.trashcan/self_2018-09-05_093649 ++++++++++
>[2018-09-05 09:36:49.239155]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 240 gluster --mode=script --wignore volume start patchy1 force ++++++++++
>[2018-09-05 09:36:50.399074]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 241 2 online_brick_count ++++++++++
>[2018-09-05 09:36:50.975772]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 242 Y glustershd_up_status ++++++++++
>[2018-09-05 09:36:54.337154]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 247 Y wildcard_exists /d/backends/patchy11/.trashcan/internal_op/self_2018-09-05_093650 ++++++++++
>[2018-09-05 09:36:54.353665]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 250 gluster --mode=script --wignore volume set patchy trash-dir abc ++++++++++
>[2018-09-05 09:36:54.475067]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 251 start_vol patchy /mnt/glusterfs/0 /mnt/glusterfs/0/abc ++++++++++
>[2018-09-05 09:36:54.723357]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 252 [ -e /mnt/glusterfs/0/abc -a ! -e /mnt/glusterfs/0/.trashcan ] ++++++++++
>[2018-09-05 09:36:54.741233]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 253 Y wildcard_exists /d/backends/patchy1/abc/internal_op/rebal* ++++++++++
>[2018-09-05 09:36:54.797406]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 257 [ -e /mnt/glusterfs/0/abc/internal_op ] ++++++++++
>[2018-09-05 09:36:54.875165]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 259 [ -e /mnt/glusterfs/0/abc ] ++++++++++
>[2018-09-05 09:36:54.914684]:++++++++++ G_LOG:./tests/features/trash.t: TEST: 261 [ -e /mnt/glusterfs/0/abc ] ++++++++++

Actions: View

Attachments on bug 1627060: 1482096 | 1482106 | 1504554 | 1504577 | 1534338 | 1534784