- ceph-users - lists.ceph.io

bug in nfs-ganesha? and cephfs?
by Marc Roos 17 Jun '20

17 Jun '20

When rsyncing to a nfs-ganesha exported cephfs the process hangs, and escalates into "cache pressure" of other cephfs clients[1]. When testing the rsync with more debugging on, I noticed that rsync stalled at the 'set modtime of . '[2] After restarting the nfs-ganesha and doing a few successful ls -al on the nfs mount. I was able to create this 'stall' by doing only a 'touch /var/www/cobbler/ks_mirror/CentOS7-x86_64/' on the directory. As mentioned in the post[1]. The same xlock message is in the mds log[4] the nfs-ganesha log during this touch[5]. nfs-ganesha-2.8.1.2-0.1.el7.x86_64 nfs-ganesha-ceph-2.8.1.2-0.1.el7.x86_64 ceph version 14.2.9 (581f22da52345dba46ee232b73b990f06029a2a0) nautilus (stable) [1] https://www.mail-archive.com/ceph-users@ceph.io/msg04527.html [2] recv_file_name(Packages/zziplib-devel-0.13.62-12.el7.i686.rpm) recv_file_name(Packages/zziplib-devel-0.13.62-12.el7.x86_64.rpm) recv_file_name(Packages/zziplib-utils-0.13.62-12.el7.x86_64.rpm) recv_file_name(Packages/centos-release-7-8.2003.0.el7.centos.x86_64.rpm) recv_file_name(Packages/lorax-19.7.26-1.el7.centos.x86_64.rpm) received 10070 names recv_file_list done recv_generator(.,0) set modtime of . to (1587553127) Wed Apr 22 12:58:47 2020 [3] 2020-06-14 14:36:26.133 7fb5edd82700 0 log_channel(cluster) log [WRN] : slow request 60.157532 seconds old, received at 2020-06-14 14:35:25.977231: client_request(client.4022202:52 setattr mtime=2020-06-14 14:35:25.976975 atime =2020-06-14 14:35:25.976974 #0x100001b9177 2020-06-14 14:35:25.977014 caller_uid=500, caller_gid=500{500,1,2,3,4,6,10,}) currently failed to xlock, waiting 2020-06-14 14:36:26.133 7fb5edd82700 0 log_channel(cluster) log [WRN] : client.4022217 isn't responding to mclientcaps(revoke), ino 0x100001b9177 pending pAsLsXs issued pAsLsXsFs, sent 60.158122 seconds ago [4] 2020-06-14 14:35:56.133 7fb5edd82700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 30.156793 secs 2020-06-14 14:35:56.133 7fb5edd82700 0 log_channel(cluster) log [WRN] : slow request 30.156792 seconds old, received at 2020-06-14 14:35:25.977231: client_request(client.4022202:52 setattr mtime=2020-06-14 14:35:25.976975 atime =2020-06-14 14:35:25.976974 #0x100001b9177 2020-06-14 14:35:25.977014 caller_uid=500, caller_gid=500{500,1,2,3,4,6,10,}) currently failed to xlock, waiting [5] 14/06/2020 14:35:23 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[reaper] reaper_run :CLIENT ID :DEBUG :Now checking NFS4 clients for expiration 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] alloc_nfs_request :DISP :DEBUG :0x7feb40000ce0 fd 166 context 0x7feb14004b60 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.2 for Program 100003, Version 4, Function 1 has xid=4153280463 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb14006c50, tag = NO TAG 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 0: opcode 22 is OP_PUTFH 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 10 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 16063 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0x7feb2c006d70 type: 7, New type: 7 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 0 = NFS4_OK, op response size is 4 total response size is 40 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 1: opcode 3 is OP_ACCESS 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs_access_op :NFS3 :DEBUG :NFS3: DEBUG: Requested ACCESS=READ,LOOKUP,MODIFY,EXTEND,DELETE,- 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs_access_op :NFS3 :DEBUG :NFS3: DEBUG: access_mask = mode(rwx) ACL(list_dir,add_file,execute,add_subdirectory,delete_child) 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs_access_op :NFS3 :DEBUG :NFS3: DEBUG: Supported ACCESS=READ,LOOKUP,MODIFY,EXTEND,DELETE,- 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs_access_op :NFS3 :DEBUG :NFS3: DEBUG: Granted ACCESS=READ,LOOKUP,MODIFY,EXTEND,DELETE,- 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_ACCESS in position 1 = NFS4_OK, op response size is 12 total response size is 56 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0x7feb2c006da8 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] encode_fsid :NFS4 :DEBUG :fsid.major = 4294967295, fsid.minor = 4294967294 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 144 total response size is 204 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb40000ce0 fd 166 (::ffff:192.168.10.2:736) xid=4153280463 returned XPRT_IDLE 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] alloc_nfs_request :DISP :DEBUG :0x7feb40000ce0 fd 166 context 0x7feb4c005710 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.2 for Program 100003, Version 4, Function 1 has xid=4170057679 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb4c0078c0, tag = NO TAG 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] process_one_op :NFS4 :DEBUG :Request 0: opcode 22 is OP_PUTFH 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 10 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] cih_get_by_key_latch :HT CACHE :DEBUG :cih AVL hit slot 21342 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa8dd60 type: 7, New type: 7 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 0 = NFS4_OK, op response size is 4 total response size is 40 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] process_one_op :NFS4 :DEBUG :Request 1: opcode 34 is OP_SETATTR 14/06/2020 14:35:25 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_3] fsal_check_setattr_perms :FSAL :DEBUG :Access check returned No error (Ok for owner) 14/06/2020 14:35:33 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[reaper] reaper_run :CLIENT ID :DEBUG :Now checking NFS4 clients for expiration 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb18004c80 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4045722888 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb18003de0, tag = NO TAG 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 30 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] cih_get_by_key_latch :HT CACHE :DEBUG :cih AVL hit slot 11701 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91800 type: 7, New type: 7 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91838 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] encode_fsid :NFS4 :DEBUG :fsid.major = 4294967295, fsid.minor = 4294967294 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 144 total response size is 232 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4045722888 returned XPRT_IDLE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb24005ba0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4062500104 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb24007110, tag = NO TAG 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 35 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] cih_get_by_key_latch :HT CACHE :DEBUG :cih AVL hit slot 11885 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91c70 type: 7, New type: 7 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91ca8 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] encode_fsid :NFS4 :DEBUG :fsid.major = 4294967295, fsid.minor = 4294967294 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 144 total response size is 232 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4062500104 returned XPRT_IDLE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb14004b60 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4079277320 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb14007e30, tag = NO TAG 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 30 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 11701 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91800 type: 7, New type: 7 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91838 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 52 total response size is 140 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4079277320 returned XPRT_IDLE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb5800c180 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4096054536 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb5800bdb0, tag = NO TAG 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 35 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 11885 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91c70 type: 7, New type: 7 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91ca8 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 52 total response size is 140 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4096054536 returned XPRT_IDLE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] alloc_nfs_request :DISP :DEBUG :0x7feb4c001060 fd 161 context 0x7feb40003150 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.153 for Program 100003, Version 4, Function 1 has xid=225276012 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 1 operations, res = 0x7feb40006d40, tag = NO TAG 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb38003da0 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb4c001060 fd 161 (::ffff:192.168.10.153:920) xid=225276012 returned XPRT_IDLE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] alloc_nfs_request :DISP :DEBUG :0x7feb48000c90 fd 160 context 0x7feb1c005c50 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.151 for Program 100003, Version 4, Function 1 has xid=937363790 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 1 operations, res = 0x7feb1c006d40, tag = NO TAG 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb50002630 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:34 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb48000c90 fd 160 (::ffff:192.168.10.151:998) xid=937363790 returned XPRT_IDLE 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb48005240 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4112831752 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb4800a860, tag = NO TAG 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 30 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 11701 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91800 type: 7, New type: 7 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91838 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 52 total response size is 140 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4112831752 returned XPRT_IDLE 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb34006230 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4129608968 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb34005270, tag = NO TAG 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 35 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 11885 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91c70 type: 7, New type: 7 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91ca8 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 52 total response size is 140 14/06/2020 14:35:35 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4129608968 returned XPRT_IDLE 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb2c0044d0 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4146386184 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb2c006120, tag = NO TAG 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 30 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 11701 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91800 type: 7, New type: 7 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91838 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 52 total response size is 140 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4146386184 returned XPRT_IDLE 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb18004b90 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4163163400 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb18003de0, tag = NO TAG 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 35 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 11885 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91c70 type: 7, New type: 7 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91ca8 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 52 total response size is 140 14/06/2020 14:35:36 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_16] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4163163400 returned XPRT_IDLE 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb24005ba0 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4179940616 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb24007110, tag = NO TAG 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 30 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 11701 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91800 type: 7, New type: 7 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91838 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 52 total response size is 140 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_13] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4179940616 returned XPRT_IDLE 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] alloc_nfs_request :DISP :DEBUG :0x7feb44001060 fd 162 context 0x7feb14004b60 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] get_gsh_client :HT CACHE :DEBUG :client_mgr cache hit slot 0 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.113 for Program 100003, Version 4, Function 1 has xid=4196717832 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 3 operations, res = 0x7feb14007e30, tag = NO TAG 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb340023d0 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 1: opcode 22 is OP_PUTFH 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] get_gsh_export :HT CACHE :DEBUG :export_mgr cache hit slot 35 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] cih_get_by_key_latch :HT CACHE :DEBUG :fdcache MISS 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] cih_get_by_key_latch :HT CACHE :DEBUG :cih cache hit slot 11885 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] mdcache_new_entry :INODE :DEBUG :Trying to add an already existing entry. Found entry 0xa91c70 type: 7, New type: 7 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_PUTFH in position 1 = NFS4_OK, op response size is 4 total response size is 84 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] process_one_op :NFS4 :DEBUG :Request 2: opcode 9 is OP_GETATTR 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] file_To_Fattr :NFS4 ACL :DEBUG :No permission check for ACL for obj 0xa91ca8 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] complete_op :NFS4 :DEBUG :Status of OP_GETATTR in position 2 = NFS4_OK, op response size is 52 total response size is 140 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_14] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb44001060 fd 162 (::ffff:192.168.10.113:967) xid=4196717832 returned XPRT_IDLE 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] alloc_nfs_request :DISP :DEBUG :0x7feb400008c0 fd 164 context 0x7feb5800bdb0 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.152 for Program 100003, Version 4, Function 1 has xid=1500681607 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 1 operations, res = 0x7feb5800c180, tag = NO TAG 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb34006410 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_2] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb400008c0 fd 164 (::ffff:192.168.10.152:747) xid=1500681607 returned XPRT_IDLE 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] alloc_nfs_request :DISP :DEBUG :0x7feb4c003690 fd 165 context 0x7feb40003150 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.111 for Program 100003, Version 4, Function 1 has xid=1915990987 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 1 operations, res = 0x7feb40002f50, tag = NO TAG 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb48006360 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:37 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_24] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb4c003690 fd 165 (::ffff:192.168.10.111:977) xid=1915990987 returned XPRT_IDLE 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] alloc_nfs_request :DISP :DEBUG :0x7feb58000c90 fd 152 context 0x7feb1c005c50 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.103 for Program 100003, Version 4, Function 1 has xid=113039167 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 1 operations, res = 0x7feb1c006d40, tag = NO TAG 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] process_one_op :NFS4 :DEBUG :Request 0: opcode 30 is OP_RENEW 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] complete_op :NFS4 :DEBUG :Status of OP_RENEW in position 0 = NFS4_OK, op response size is 4 total response size is 40 14/06/2020 14:35:39 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_15] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb58000c90 fd 152 (::ffff:192.168.10.103:945) xid=113039167 returned XPRT_IDLE 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] alloc_nfs_request :DISP :DEBUG :0x7feb2c000c90 fd 159 context 0x7feb48005240 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.114 for Program 100003, Version 4, Function 1 has xid=3613830069 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 1 operations, res = 0x7feb4800a860, tag = NO TAG 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb2c002070 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_23] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb2c000c90 fd 159 (::ffff:192.168.10.114:687) xid=3613830069 returned XPRT_IDLE 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] alloc_nfs_request :DISP :DEBUG :0x7feb140008c0 fd 163 context 0x7feb34006230 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.112 for Program 100003, Version 4, Function 1 has xid=3310701715 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 1 operations, res = 0x7feb34005270, tag = NO TAG 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] process_one_op :NFS4 :DEBUG :Request 0: opcode 53 is OP_SEQUENCE 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] nfs4_op_sequence :SESSIONS :DEBUG :SEQUENCE session=0x7feb480022f0 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] complete_op :NFS4 :DEBUG :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40 total response size is 76 14/06/2020 14:35:40 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_18] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb140008c0 fd 163 (::ffff:192.168.10.112:729) xid=3310701715 returned XPRT_IDLE 14/06/2020 14:35:43 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[chunk_lru] chunk_lru_run :INODE LRU :DEBUG :After work, threadwait=90 totalwork=0 14/06/2020 14:35:43 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[cache_lru] lru_run :INODE LRU :DEBUG :FD count is 0 and low water mark is 2048: not reaping. 14/06/2020 14:35:43 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[cache_lru] lru_run :INODE LRU :DEBUG :After work, open_fd_count:0 count:41 fdrate:1 new_thread_wait=90 14/06/2020 14:35:43 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[reaper] reaper_run :CLIENT ID :DEBUG :Now checking NFS4 clients for expiration 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] alloc_nfs_request :DISP :DEBUG :0x7feb40000ce0 fd 166 context 0x7feb2c0044d0 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:192.168.10.2 for Program 100003, Version 4, Function 1 has xid=4186834895 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] dupreq_tcp_cmpf :DUPREQ :DEBUG :dupreq_tcp_cmpf 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] nfs4_Compound :NFS4 :DEBUG :COMPOUND: There are 1 operations, res = 0x7feb2c006120, tag = NO TAG 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] process_one_op :NFS4 :DEBUG :Request 0: opcode 30 is OP_RENEW 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] complete_op :NFS4 :DEBUG :Status of OP_RENEW in position 0 = NFS4_OK, op response size is 4 total response size is 40 14/06/2020 14:35:45 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[svc_25] free_nfs_request :DISP :DEBUG :SVC_DECODE on 0x7feb40000ce0 fd 166 (::ffff:192.168.10.2:736) xid=4186834895 returned XPRT_IDLE 14/06/2020 14:35:53 : epoch 5ee617d5 : c01 : ganesha.nfsd-481476[reaper] reaper_run :CLIENT ID :DEBUG :Now checking NFS4 clients for expiration

2 3

advantage separate cluster network on single interface
by Marcel Kuiper 17 Jun '20

17 Jun '20

Hi I wonder if there is any (theoretical) advantage running a separate backend network next to the public network (through vlan separation) over a single interface I googled a lot and while some blogs advice to do so, they do not give any argument that supports this statement Any insights on this is much appreciated Thanks Marcel

4 3

Re: Combining erasure coding and replication?
by Darren Soothill 17 Jun '20

17 Jun '20

Hi Brett, So how far apart are your buildings and what is the network connectivity between the buildings? I am going to assume they are close and you have lots of bandwidth. There are a couple of options depending on the protocol and the distance between the buildings. You could build an EC cluster with something like 4:6 so 4 data pieces and 6 parity pieces (Assuming you have 5 nodes in each DC). With this setup you can then have a failure of an entire DC and still have access to your data with protection. This is basically achieved by building the correct crush map rules which place half the data in one DC and the other half in the other DC. You would need to think about where you would put a third monitor in this case. The down side of this is you could be reading data from either DC. Not sure where your workloads are. There is another alternative of this which is to use LRC which creates the ability to rebuild the data with a DC this helps when it comes to rebuilds but doesn't help with where to read data from. The other option would be replication. So build two separate clusters and you can configure S3 to replicate to the second site. Or setup rsync to replicate if using CephFS, not pretty but an option. Darren From: Brett Randall <brett.randall(a)gmail.com> Date: Wednesday, 10 June 2020 at 15:20 To: ceph-users(a)ceph.io <ceph-users(a)ceph.io> Subject: [ceph-users] Combining erasure coding and replication? Hi all We are looking at setting up our first ever Ceph cluster to replace Gluster as our media asset storage and production system. The Ceph cluster will have 5pb of usable storage. Whether we use it as object-storage, or put CephFS in front of it, is still TBD. Obviously we’re keen to protect this data well. Our current Gluster setup utilises RAID-6 on each of the nodes and then we have a single replica of each brick. The Gluster bricks are split between buildings so that the replica is guaranteed to be in another premises. By doing it this way, we guarantee that we can have a decent number of disk or node failures (even an entire building) before we lose both connectivity and data. Our concern with Ceph is the cost of having three replicas. Storage may be cheap but I’d rather not buy ANOTHER 5pb for a third replica if there are ways to do this more efficiently. Site-level redundancy is important to us so we can’t simply create an erasure-coded volume across two buildings – if we lose power to a building, the entire array would become unavailable. Likewise, we can’t simply have a single replica – our fault tolerance would drop way down on what it is right now. Is there a way to use both erasure coding AND replication at the same time in Ceph to mimic the architecture we currently have in Gluster? I know we COULD just create RAID6 volumes on each node and use the entire volume as a single OSD, but that this is not the recommended way to use Ceph. So is there some other way? Apologies if this is a nonsensical question, I’m still trying to wrap my head around Ceph, CRUSH maps, placement rules, volume types, etc etc! TIA Brett _______________________________________________ ceph-users mailing list -- ceph-users(a)ceph.io To unsubscribe send an email to ceph-users-leave(a)ceph.io

2 1

struct crush_bucket **buckets in Ceph CRUSH
by Bobby 17 Jun '20

17 Jun '20

Hi, I have a question regarding Ceph CRUSH. I have been going through Crush.h file. It says that *struct crush_bucket **buckets * (below) is an array of pointers. My understanding is that this particular array of pointers is a collection of addresses of six scalar values namely __s32 id; __u16 type; __u8 alg, __u8 hash, __u32 weight, __u32 size and the reason it has double pointer **buckets because it also points to another pointer namely __s32 *items? Please correct me if I am wrong. /** @ingroup API * * A crush map define a hierarchy of crush_bucket that end with leaves * (buckets and leaves are called items) and a set of crush_rule to * map an integer to items with the crush_do_rule() function. * */ struct crush_map { /*! An array of crush_bucket pointers of size __max_buckets__. * An element of the array may be NULL if the bucket was removed with * crush_remove_bucket(). The buckets must be added with crush_add_bucket(). * The bucket found at __buckets[i]__ must have a crush_bucket.id == -1-i. */ struct crush_bucket **buckets; /*! An array of crush_rule pointers of size __max_rules__. * An element of the array may be NULL if the rule was removed (there is * no API to do so but there may be one in the future). The rules must be added * with crush_add_rule(). */ struct crush_rule **rules; __s32 max_buckets; /*!< the size of __buckets__ */ __u32 max_rules; /*!< the size of __rules__ */ /*! The value of the highest item stored in the crush_map + 1 */ __s32 max_devices; /*! Backward compatibility tunable. It implements a bad solution * and must always be set to 0 except for backward compatibility * purposes */ __u32 choose_local_tries; /*! Backward compatibility tunable. It implements a bad solution * and must always be set to 0 except for backward compatibility * purposes */ __u32 choose_local_fallback_tries; /*! Tunable. The default value when the CHOOSE_TRIES or * CHOOSELEAF_TRIES steps are omitted in a rule. See the * documentation for crush_rule_set_step() for more * information */ __u32 choose_total_tries; /*! Backward compatibility tunable. It should always be set * to 1 except for backward compatibility. Implemented in 2012 * it was generalized late 2013 and is mostly unused except * in one border case, reason why it must be set to 1. * * Attempt chooseleaf inner descent once for firstn mode; on * reject retry outer descent. Note that this does *not* * apply to a collision: in that case we will retry as we * used to. */ __u32 chooseleaf_descend_once; /*! Backward compatibility tunable. It is a fix for bad * mappings implemented in 2014 at * https://github.com/ceph/ceph/pull/1185. It should always * be set to 1 except for backward compatibility. * * If non-zero, feed r into chooseleaf, bit-shifted right by * (r-1) bits. a value of 1 is best for new clusters. for * legacy clusters that want to limit reshuffling, a value of * 3 or 4 will make the mappings line up a bit better with * previous mappings. */ __u8 chooseleaf_vary_r; /*! Backward compatibility tunable. It is an improvement that * avoids unnecessary mapping changes, implemented at * https://github.com/ceph/ceph/pull/6572 and explained in * this post: "chooseleaf may cause some unnecessary pg * migrations" in October 2015 * https://www.mail-archive.com/ceph-devel@vger.kernel.org/msg26075.html * It should always be set to 1 except for backward compatibility. */ __u8 chooseleaf_stable; /*! @cond INTERNAL */ /* This value is calculated after decode or construction by the builder. It is exposed here (rather than having a 'build CRUSH working space' function) so that callers can reserve a static buffer, allocate space on the stack, or otherwise avoid calling into the heap allocator if they want to. The size of the working space depends on the map, while the size of the scratch vector passed to the mapper depends on the size of the desired result set. Nothing stops the caller from allocating both in one swell foop and passing in two points, though. */ size_t working_size; #ifndef __KERNEL__ /*! @endcond */ /*! Backward compatibility tunable. It is a fix for the straw * scaler values for the straw algorithm which is deprecated * (straw2 replaces it) implemented at * https://github.com/ceph/ceph/pull/3057. It should always * be set to 1 except for backward compatibility. * */ __u8 straw_calc_version; /*! @cond INTERNAL */ /* * allowed bucket algs is a bitmask, here the bit positions * are CRUSH_BUCKET_*. note that these are *bits* and * CRUSH_BUCKET_* values are not, so we need to or together (1 * << CRUSH_BUCKET_WHATEVER). The 0th bit is not used to * minimize confusion (bucket type values start at 1). */ __u32 allowed_bucket_algs; __u32 *choose_tries; #endif /*! @endcond */ }; BR

1 0

Slow Ops start piling up, Mon Corruption ?
by Daniel Poelzleithner 16 Jun '20

16 Jun '20

Hi, we had bad blocks on one OSD and around the same time a network switch outage, which seems to have caused some corruption on the mon service. > # ceph -s cluster: id: d7c5c9c7-a227-4e33-ab43-3f4aa1eb0630 health: HEALTH_WARN 1 daemons have recently crashed 14097 slow ops, oldest one blocked for 56417 sec, mon.server6 has slow ops mon server6 is low on available space services: mon: 3 daemons, quorum server6,server3,server5 (age 15h) mgr: server4(active, since 3w), standbys: server6, server5 mds: xpool:1 {0=server6=up:active} 1 up:standby osd: 21 osds: 21 up (since 15h), 20 in (since 16h) data: pools: 17 pools, 941 pgs objects: 6.80M objects, 18 TiB usage: 34 TiB used, 20 TiB / 54 TiB avail pgs: 940 active+clean 1 active+clean+scrubbing+deep io: client: 23 MiB/s rd, 980 KiB/s wr, 30 op/s rd, 141 op/s wr 14097 slow ops, oldest one blocked for 56417 sec, mon.server6 has slow ops The mon ops log looks like: https://gist.github.com/poelzi/45f31f26f6a83f6406bb43553e0c237a It seems, that the mds transactions don't finish, while waiting for mdsmap. In the mds server, there are no ops in flight, nor any errors in the log file. What is the proper way to repair this ? kind regards poelzi

1 0

Error initializing cluster client: ObjectNotFound('RADOS object not found (error calling conf_read_file)')
by cemzafer 16 Jun '20

16 Jun '20

I have installed simple ceph system with two nodes (ceph100, ceph101) with cephadm and ceph orch host add command. I put the ssh-copy-id -f -i /etc/ceph/ceph.pub key to the second host (ceph101). I can execute the ceph -s command from the first host(ceph100) but when I execute the command in the second host(ceph101), I get the following error. Error initializing cluster client: ObjectNotFound('RADOS object not found (error calling conf_read_file)') Also, when I execute the 'ceph orch ps' command the output seems suspicious to me. NAME HOST STATUS REFRESHED AGE VERSION IMAGE NAME IMAGE ID CONTAINER ID mon.ceph101 ceph101 starting - - <unknown> <unknown> <unknown> <unknown> Has anyone any idea what could be the problem or anyone give me a fine link for the octopus cephadm installation? Regards.

3 2

Announcing go-ceph v0.4.0
by John Mulligan 16 Jun '20

16 Jun '20

I'm happy to announce the another release of the go-ceph API bindings. This is a regular release following our every-two-months release cadence. https://github.com/ceph/go-ceph/releases/tag/v0.4.0 The bindings aim to play a similar role to the "pybind" python bindings in the ceph tree but for the Go language. These API bindings require the use of cgo. There are already a few consumers of this library in the wild and the ceph-csi project is starting to make use of this library. Specific questions, comments, bugs etc are best directed at our github issues tracker. --- John Mulligan phlogistonjohn(a)asynchrono.us jmulligan(a)redhat.com

1 0

Ceph Tech Talk for June 25th
by Mike Perez 16 Jun '20

16 Jun '20

Hi everyone, I'm looking for a proposal for this month's Tech Talk on the 25th at 17:00 UTC. If you have something you want to share with the Ceph community, consider sending me your proposal: https://ceph.io/ceph-tech-talks/ -- Mike Perez He/Him Ceph Community Manager Red Hat Los Angeles <https://www.redhat.com> thingee(a)redhat.com <mailto:thingee@redhat.com> M: 1-951-572-2633 <tel:1-951-572-2633> IM: IRC Freenode/OFTC: thingee 494C 5D25 2968 D361 65FB 3829 94BC D781 ADA8 8AEA @Thingee <https://twitter.com/thingee> <https://www.redhat.com> <https://redhat.com/summit>

1 0

Current status of multipe cephfs
by Simon Sutter 16 Jun '20

16 Jun '20

Hello, What is the current status, of using multiple cephfs? In octopuss I get lots of warnings, that this feature is still not fully tested, but the latest entry regarding multiple cephfs in the mailinglist is from about 2018. Is someone using multiple cephfs in production? Thanks in Advance, Simon

2 1

CephFS health error dir_frag recovery process
by Christopher Wieringa 16 Jun '20

16 Jun '20

Hello helpful mailing list folks! After a networking outage, I had a MDS rank failure (originally 3 MDS ranks) that has left my CephFS cluster in a bad shape. I worked through most of the Disaster Recovery guide (https://docs.ceph.com/docs/nautilus/cephfs/disaster-recovery-experts/#disas…) and got my CephFS remounted and (mostly) available. I have additionally completed the lengthy extents and inodes scan. For the most part, I am working fine, but for now have reduced my max MDS down to 1. However, it looks however that I have a MDS dir_frag issue and damaged metadata on a specific directory when accessed. Here's the appropriate commands/outputs: # ceph version ceph version 14.2.9 (581f22da52345dba46ee232b73b990f06029a2a0) nautilus (stable) # ceph -s cluster: id: <redacted> health: HEALTH_ERR 1 MDSs report damaged metadata services: mon: 3 daemons, quorum katz-c1,katz-c2,katz-c3 (age 6d) mgr: katz-c2(active, since 10d), standbys: katz-c1, katz-c3 mds: cephfs-katz:1 {0=katz-mds-3=up:active} 5 up:standby osd: 9 osds: 9 up (since 6d), 9 in (since 6d) data: pools: 7 pools, 312 pgs objects: 19.82M objects, 1.5 TiB usage: 6.6 TiB used, 11 TiB / 17 TiB avail pgs: 311 active+clean 1 active+clean+scrubbing+deep # ceph health detail HEALTH_ERR 1 MDSs report damaged metadata MDS_DAMAGE 1 MDSs report damaged metadata mdskatz-mds-3(mds.0): Metadata damage detected # ceph tell mds.0 damage ls [ { "damage_type": "dir_frag", "id": 575440387, "ino": 1099550285476, "frag": "*", "path": "/bad/TSAL/conf8N5LVl" } ] # ceph tell mds.0 scrub start /bad recursive repair { "return_code": 0, "scrub_tag": "887fa41d-4643-4b2d-bb7d-8f96c02c2b4d", "mode": "asynchronous" } After a few seconds, # ceph tell mds.0 scrub status { "status": "no active scrubs running", "scrubs": {} } The scrub appears to not do anything to fix the issue. I have isolated the directory in my file system (/bad) and do not need the contents of the directory anymore (backups woo!), however a typical "rm -rf" command on the directory fails. The next steps for recovery is where I am struggling. There have been other emails to this list before about this topic ( https://www.spinics.net/lists/ceph-users/msg53211.html ) but the commands referenced are a bit foreign to me, and I was wondering if you all could provide some additional insight on the exact commands needed. From what I can gathered in the previous thread, I need to: 1. Get the inode for the parent directory ( /bad/TSAL ) # cd /mnt/cephfs/bad # stat TSAL File: TSAL Size: 3 Blocks: 0 IO Block: 65536 directory Device: 2eh/46d Inode: 1099550201759 Links: 4 Access: (0700/drwx------) Uid: ( 0/ root) Gid: ( 0/ root) Access: 2020-06-01 15:50:41.000000000 -0400 Modify: 2020-06-11 15:21:42.079970103 -0400 Change: 2020-06-11 15:21:42.079970103 -0400 Birth: - (So in this case, /bad/TSAL inode: 1099550201759) 2. Check if omap key '1_head' exists in object <inode of directory in hex>.00000000. If it exists, remove it. This is where I am clueless on how to continue. How do I check if the omap key '1_head' exists, and if so, remove it? What commands am I working with here? (Inode decimal to hex: 1099550201759 -> 100024C979F) Thank you much! Chris Wieringa

1 0