Description of problem: Input/Output Error seen while running iozone test on nfs-ganesha+mdcache enabled volume. Version-Release number of selected component (if applicable): nfs-ganesha-gluster-2.4.1-1.el7rhgs.x86_64 glusterfs-ganesha-3.8.4-3.el7rhgs.x86_64 How reproducible: Always Steps to Reproduce: 1. Create ganesha cluster and create a volume. 2. Enable nfs-ganesha and mdcache on the volume 3. Mount the volume 4. Run iozone. /opt/qa/tools/system_light/run.sh -w /mnt/nfs_v4 -t iozone -l /var/tmp/iozone.log Actual results: iozone test fails with IO error Expected results: iozone test should succeed without any error Additional info: [root@dhcp46-42 ~]# gluster vol info vol1 Volume Name: vol1 Type: Distributed-Replicate Volume ID: ae86ded9-bfb7-4100-8ecf-d63c51376cc4 Status: Started Snapshot Count: 0 Number of Bricks: 6 x 2 = 12 Transport-type: tcp Bricks: Brick1: dhcp46-42.lab.eng.blr.redhat.com:/bricks/brick0/br0 Brick2: dhcp46-101.lab.eng.blr.redhat.com:/bricks/brick0/br0 Brick3: dhcp47-155.lab.eng.blr.redhat.com:/bricks/brick0/br0 Brick4: dhcp47-167.lab.eng.blr.redhat.com:/bricks/brick0/br0 Brick5: dhcp46-42.lab.eng.blr.redhat.com:/bricks/brick1/br1 Brick6: dhcp46-101.lab.eng.blr.redhat.com:/bricks/brick1/br1 Brick7: dhcp47-155.lab.eng.blr.redhat.com:/bricks/brick1/br1 Brick8: dhcp47-167.lab.eng.blr.redhat.com:/bricks/brick1/br1 Brick9: dhcp46-42.lab.eng.blr.redhat.com:/bricks/brick2/br2 Brick10: dhcp46-101.lab.eng.blr.redhat.com:/bricks/brick2/br2 Brick11: dhcp47-155.lab.eng.blr.redhat.com:/bricks/brick2/br2 Brick12: dhcp47-167.lab.eng.blr.redhat.com:/bricks/brick2/br2 Options Reconfigured: performance.md-cache-timeout: 600 performance.cache-invalidation: on performance.stat-prefetch: on features.cache-invalidation-timeout: 600 ganesha.enable: on features.cache-invalidation: on transport.address-family: inet performance.readdir-ahead: on nfs.disable: on nfs-ganesha: enable cluster.enable-shared-storage: enable [root@dhcp46-42 ~]# [root@dhcp47-176 ~]# /opt/qa/tools/system_light/run.sh -w /mnt/nfs_v4 -t iozone -l /var/tmp/iozone.log ===========================TESTS RUNNING=========================== Changing to the specified mountpoint /mnt/nfs_v4/run22576 executing iozone start:13:59:45 read: Input/output error real 17m16.234s user 0m1.876s sys 0m42.307s end:14:17:02 iozone failed 0 Total 0 tests were successful Switching over to the previous working directory Removing /mnt/nfs_v4/run22576/ rmdir: failed to remove ‘/mnt/nfs_v4/run22576/’: Remote I/O error rmdir failed:Directory not empty
Arthy has reproduced this with following steps : 1.) Mount the volume using v4 on two clients 2.) On one client run iozone -a 3.) On the second client run fileop And both clients ended in remote I/O error while trying to remove test directory. From the ganesha-gfapi.logs The message "W [MSGID: 108008] [afr-read-txn.c:244:afr_read_txn] 0-vol1_new-replicate-1: Unreadable subvolume -1 found with event generation 5 for gfid 00000000-0000-0000-0000-000000000001. (Possible split-brain)" repeated 2 times between [2016-11-16 11:59:31.472371] and [2016-11-16 11:59:31.475652] The message "W [MSGID: 114031] [client-rpc-fops.c:2938:client3_3_lookup_cbk] 0-vol1_new-client-2: remote operation failed. Path: / (00000000-0000-0000-0000-000000000001) [Transport endpoint is not connected]" repeated 2 times between [2016-11-16 11:59:31.472493] and [2016-11-16 11:59:31.475672] [2016-11-16 11:59:31.504158] E [MSGID: 114031] [client-rpc-fops.c:2847:client3_3_opendir_cbk] 0-vol1_new-client-2: remote operation failed. Path: /run15413 (859a3b6d-9ea8-48e7-9d03-108d0ba009c5) [Transport endpoint is not connected] It is clear that open dir call failed on 0-vol1_new-client-2 and hence the removal ended in failure. When checked via gdb "client3_3opendir" on the client machine, request is never send to this server because in the client context the server is disconnected. But brick process up and running. Another thing which noted it is not broadcasted to other subvol(I mean vol1_new-client-3). The end result is that opendir got called hence the rmdir. I can also see following messages in brick log as well : (Don't when it got created) [2016-11-16 10:46:18.740750] E [server.c:202:server_submit_reply] (-->/usr/lib64/glusterfs/3.8.4/xlator/debug/io-stats.so(+0x15dce) [0x7f2506b3cdce] -->/usr/lib64/glusterfs/3.8.4/xlator/protocol/server.so(+0x196d0) [0x7f25066e06d0] -->/usr/lib64/glusterfs/3.8.4/xlator/protocol/server.so(+0x9186) [0x7f25066d0186] ) 0-: Reply submission failed [2016-11-16 10:46:18.744106] E [MSGID: 113040] [posix-helpers.c:1622:__posix_fd_ctx_get] 0-vol1_new-posix: Failed to get fd context for a non-anonymous fd, file: (null), gfid: 952e9ac0-3700-4ee5-835e-54fc9e60116a [2016-11-16 10:46:18.744145] W [MSGID: 113006] [posix.c:3506:posix_flush] 0-vol1_new-posix: pfd is NULL on fd=0x7f251ba460f8 [Invalid argument] [2016-11-16 10:46:18.744207] I [MSGID: 101055] [client_t.c:415:gf_client_unref] 0-vol1_new-server: Shutting down connection dhcp46-124.lab.eng.blr.redhat.com-22631-2016/11/15-10:32:57:485838-vol1_new-client-2-0-1 [2016-11-16 10:46:18.744462] E [server-helpers.c:395:server_alloc_frame] (-->/lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325) [0x7f251b51d765] -->/usr/lib64/glusterfs/3.8.4/xlator/protocol/server.so(+0x2da3c) [0x7f25066f4a3c] -->/usr/lib64/glusterfs/3.8.4/xlator/protocol/server.so(+0xd7f4) [0x7f25066d47f4] ) 0-server: invalid argument: client [Invalid argument] [2016-11-16 10:46:18.744487] E [rpcsvc.c:557:rpcsvc_check_and_reply_error] 0-rpcsvc: rpc actor failed to complete successfully [2016-11-16 10:46:18.745188] I [MSGID: 101055] [client_t.c:415:gf_client_unref] 0-vol1_new-server: Shutting down connection dhcp46-139.lab.eng.blr.redhat.com-24725-2016/11/15-10:32:57:435295-vol1_new-client-2-0-0
After discussing with Pranith, he mentioned it is race in client layer. Following logs confirm the same : [2016-11-16 05:38:40.512423] I [MSGID: 114046] [client-handshake.c:1222:client_setvolume_cbk] 0-vol1_new-client-2: Connected to vol1_new-client-2, attached to remote volume '/bricks/brick0/br0'. [2016-11-16 05:38:40.512464] I [MSGID: 114047] [client-handshake.c:1233:client_setvolume_cbk] 0-vol1_new-client-2: Server and Client lk-version numbers are not same, reopening the fds [2016-11-16 06:00:40.351777] I [MSGID: 114018] [client.c:2280:client_rpc_notify] 0-vol1_new-client-2: disconnected from vol1_new-client-2. Client process will keep trying to connect to glusterd until brick's port is available [2016-11-16 06:00:40.352534] I [MSGID: 114046] [client-handshake.c:1222:client_setvolume_cbk] 0-vol1_new-client-2: Connected to vol1_new-client-2, attached to remote volume '/bricks/brick0/br0'. [2016-11-16 06:00:40.352556] I [MSGID: 114047] [client-handshake.c:1233:client_setvolume_cbk] 0-vol1_new-client-2: Server and Client lk-version numbers are not same, reopening the fds Here disconnection and connection came with in span of milliseconds. *** This bug has been marked as a duplicate of bug 1385605 ***
Since use case is different.For the time being, the change component of bug and retest this issue with fix
Patch posted upstream at http://review.gluster.org/#/c/15916
Tested and verified the fix in build, nfs-ganesha-2.4.1-2.el7rhgs.x86_64 nfs-ganesha-gluster-2.4.1-2.el7rhgs.x86_64 glusterfs-ganesha-3.8.4-8.el7rhgs.x86_64
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHSA-2017-0486.html