Bug 1215596

+++ This bug was initially created as a clone of Bug #1204140 +++

+++ This bug was initially created as a clone of Bug #1202456 +++

Description of problem:
When we have the options "case sensitive = no" and "preserve case = yes" in /etc/samba/smb.conf, renaming a file to a variation of upper and lower case letters of an existing file causes the file that was being renamed to dissapear in the client, and the change to succeed. After umounting and mounting again the samba share from the RHS server, the two versions of the file are visible but only the content of the first one (the one all lowercase) is shown whenever any of them is accessed.

For all my tests I first created a file "test.txt" with a very distinctive content, i.e. test1, and followed up with renaming some other files:
"test2.txt" with content test2 to "tesT.txt"
"tes3.txt" with content test3 to "Test.txt"

In both of these cases, the renamed files disappeared, showing only the file "test.txt". 
When not using the gluster samba vfs plugin, the Windows 7 client is prevented the creation of any file with variations of upper and lower cases of an existing file, showing a windows that reads ' There is already a file with the same name in this location. Do you want to rename "test2.txt" to "new test (2).txt"?'

Version-Release number of selected component (if applicable):
samba-glusterfs-3.6.509-169.6.el6rhs
glusterfs-3.6.0.42.1-1.el6rhs

I've also reproduced in vms with glusterfs-3.6.3beta1-0.11.gitd494bec.el6 (and the same version of samba).

How reproducible:
Always.

Steps to Reproduce:
0. Mount a samba share in a Windows 7 client.
1. Create a file test.txt with any content.
2. Create a second file test2.txt with some different content.
3. Rename test2.txt to tesT.txt.

Actual results:
test2.txt dissapears completely with both the old name and the new tesT.txt name. Only test.txt is visible.

Expected results:
A warning is shown that prevents the file to be renamed as a result of the caseless comparison between the existing test.txt and the attempt to rename test2.txt to tesT.txt.

Additional info:
Originally I thought that it could have been related to the following commit and upstream bugzilla:

af9ec9fea5a730023cdee6e236f9585e3a18b0e6

https://lists.samba.org/archive/samba-cvs/2014-December/110218.html

https://bugzilla.samba.org/show_bug.cgi?id=11057

But it does not seem to be the same issue, because the patch is already included in RHS 3.0 from what I've seen in the code, and when I enable tracing for the volume and a higher verbosity for smb.conf I can see that we call "glusterfs.get_real_filename:" instead of "user.glusterfs.get_real_filename:"

I've manipulated the glusterfs package and added gf_log() lines around various functions to complement what the log level TRACE was showing. I'll attach soon a snip of the logs with comments regarding each step taken, so that it can be analyzed. Let me know if any more data is needed. I guess full logs, and a sosreport of each of the two node RHS 3.0 enviroment I created locally with virtual machines will be useful?

--- Additional comment from Jose Castillo on 2015-03-16 22:03:10 IST ---



--- Additional comment from Jose Castillo on 2015-03-16 22:07:11 IST ---



--- Additional comment from Jose Castillo on 2015-03-16 22:08:52 IST ---



--- Additional comment from Jose Castillo on 2015-03-16 22:10:11 IST ---

Attached two log files that logged the problem being reproduced. Each step I took is denoted by the following strings:

bricks-brick1.log:Starting new tests with more verbosity in dht_getxattr
bricks-brick1.log:Trying to rename test2.txt to test.txt in second tests
bricks-brick1.log:Trying to rename test2.txt to test.txt in second tests FAILED
bricks-brick1.log:Trying to rename test2.txt to tesT.txt in second tests
bricks-brick1.log:Trying to rename test2.txt to tesT.txt in second tests SUCCEDED
glusterfs-mediaset.192.168.122.39.log:Starting new tests with more verbosity in dht_getxattr
glusterfs-mediaset.192.168.122.39.log:Trying to rename test2.txt to test.txt in second tests
glusterfs-mediaset.192.168.122.39.log:Trying to rename test2.txt to test.txt in second tests FAILED
glusterfs-mediaset.192.168.122.39.log:Trying to rename test2.txt to tesT.txt in second tests
glusterfs-mediaset.192.168.122.39.log:Trying to rename test2.txt to tesT.txt in second tests SUCCEDED

That I hope are clear enough. But let me know if I need to clarify any of the tests I ran.

--- Additional comment from Jose Castillo on 2015-03-16 22:26:19 IST ---



--- Additional comment from Jose Castillo on 2015-03-16 22:27:07 IST ---



--- Additional comment from Jose Castillo on 2015-03-16 22:28:52 IST ---

(In reply to Jose Castillo from comment #4)
> Attached two log files that logged the problem being reproduced. Each step I
> took is denoted by the following strings:
> 
Sorry, the strings are actually:

bricks-brick1.log:Trying to rename test2.txt to test.txt in third tests
bricks-brick1.log:Trying to rename test2.txt to test.txt in third tests FAILED
bricks-brick1.log:Trying to rename test2.txt to tesT.txt in third tests
bricks-brick1.log:Trying to rename test2.txt to tesT.txt in third tests SUCCEDED
glusterfs-mediaset.192.168.122.39.log:Trying to rename test2.txt to test.txt in third tests
glusterfs-mediaset.192.168.122.39.log:Trying to rename test2.txt to test.txt in third tests FAILED
glusterfs-mediaset.192.168.122.39.log:Trying to rename test2.txt to tesT.txt in third tests
glusterfs-mediaset.192.168.122.39.log:Trying to rename test2.txt to tesT.txt in third tests SUCCEDED


The third tests actually contain more verbosity as a result of more gf_log() lines added.

--- Additional comment from Jose Castillo on 2015-03-16 22:34:29 IST ---

One last note: The lines I added with gf_log() are the ones in the logs that start with "01362725:", with that number being the red hat customer portal case number.

With these lines I could see that the code flow was:

dht-common.c:1147:dht_lookup_everywhere_done
   -> dht-common.c:1086:dht_lookup_everywhere_done
	-> dht-common.c:2762:dht_getxattr 
		-> dht-common.c:2716:dht_getxattr_get_real_filename 
			-> posix.c:3160:posix_xattr_get_real_filename 


We go down to posix_xattr_get_real_filename() where we do the caseless comparison of the file we are renaming to, and the content of the directory. Disregard the line numbers there, since they are different from upstream's code because of the debug lines I added.

With these lines I think we can see that it actually finds that there is a file already with name test.txt, i.e.:

[2015-03-10 12:19:21.696522] D [marker.c:388:marker_getxattr] 0-mediaset-marker: USER:PID = 1902
[2015-03-10 12:19:21.696548] D [io-threads.c:351:iot_schedule] 0-mediaset-io-threads: GETXATTR scheduled as normal fop
[2015-03-10 12:19:21.696602] E [posix.c:3160:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: Inside posix_xattr_get_real_filename with key glusterfs.get_real_filename:tesT.txt
[2015-03-10 12:19:21.696641] E [posix.c:3168:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: After opendir, key is glusterfs.get_real_filename:tesT.txt
[2015-03-10 12:19:21.696662] E [posix.c:3173:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: After fname, fname is tesT.txt
[2015-03-10 12:19:21.696686] E [posix.c:3177:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: After while, dirent is .
[2015-03-10 12:19:21.696706] E [posix.c:3177:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: After while, dirent is ..
[2015-03-10 12:19:21.696724] E [posix.c:3177:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: After while, dirent is .glusterfs
[2015-03-10 12:19:21.696758] E [posix.c:3177:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: After while, dirent is test.txt
[2015-03-10 12:19:21.696816] E [posix.c:3181:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: Inside while, strcasecmp founda match, where dirent is test.txt and fname is tesT.txt
[2015-03-10 12:19:21.696837] E [posix.c:3190:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: Inside if after while, before break
[2015-03-10 12:19:21.696862] E [posix.c:3211:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725:Returning from posix_xattr_get_real_filename with ret 9

This happens just in the last test, i.e.:

bricks-brick1.log:Trying to rename test2.txt to tesT.txt in third tests
bricks-brick1.log:[2015-03-10 12:19:21.696816] E [posix.c:3181:posix_xattr_get_real_filename] 0-mediaset-posix: 01362725: Inside while, strcasecmp founda match, where dirent is test.txt and fname is tesT.txt
bricks-brick1.log:Trying to rename test2.txt to tesT.txt in third tests SUCCEDED

Corresponding to the following part in the code:

int
posix_xattr_get_real_filename (call_frame_t *frame, xlator_t *this, loc_t *loc,
                               const char *key, dict_t *dict, dict_t *xdata)
{
[...]
        while ((dirent = readdir (fd))) {
               gf_log (this->name, GF_LOG_ERROR, "01362725: After while, dirent is %s",
                       dirent->d_name);
                if (strcasecmp (dirent->d_name, fname) == 0) {
                        gf_log (this->name, GF_LOG_ERROR, "01362725: Inside while, strcasecmp found"
                                "a match, where dirent is %s and fname is %s",
                                dirent->d_name, fname);
                        found = gf_strdup (dirent->d_name);
                        if (!found) {
                                closedir (fd);
                                gf_log (this->name, GF_LOG_ERROR, "01362725: Returning ENOMEM because found is %s",
                                       found);
                                return -ENOMEM;
                        }

                        gf_log (this->name, GF_LOG_ERROR, "01362725: Inside if after while, before break");
                        break;
                }
        }

        closedir (fd);

        if (!found) {
                gf_log (this->name, GF_LOG_ERROR, "01362725: Returning ENOENT");
                return -ENOENT;
        }
        ret = dict_set_dynstr (dict, (char *)key, found);
        if (ret) {
                GF_FREE (found);
               gf_log (this->name, GF_LOG_ERROR, "01362725: Returning ENOMEM after dict_set_dynstr %s",
                       dirent->d_name);

                return -ENOMEM;
        }
        ret = strlen (found) + 1;
        gf_log (this->name, GF_LOG_ERROR, "01362725:Returning from posix_xattr_get_real_filename with ret %d",
                       ret);

        return ret;
}

Sorry for doing the analysis this way - I tried first with gdb but couldn't get the breakpoints to work properly when attached to glusterd or glusterfsd processes.

--- Additional comment from Raghavendra Talur on 2015-03-18 14:19:05 IST ---

Here is what I did

Machine details:
[root@rhs3 ~]# rpm -qa | grep gluster
gluster-nagios-common-0.1.3-2.el6rhs.noarch
glusterfs-cli-3.6.0.42.1-1.el6rhs.x86_64
glusterfs-api-devel-3.6.0.42.1-1.el6rhs.x86_64
glusterfs-devel-3.6.0.42.1-1.el6rhs.x86_64
samba-glusterfs-3.6.509-169.6.el6rhs.x86_64
gluster-nagios-addons-0.1.10-2.el6rhs.x86_64
glusterfs-libs-3.6.0.42.1-1.el6rhs.x86_64
glusterfs-fuse-3.6.0.42.1-1.el6rhs.x86_64
glusterfs-3.6.0.42.1-1.el6rhs.x86_64
glusterfs-server-3.6.0.42.1-1.el6rhs.x86_64
glusterfs-api-3.6.0.42.1-1.el6rhs.x86_64
vdsm-gluster-4.14.7.2-1.el6rhs.noarch
glusterfs-geo-replication-3.6.0.42.1-1.el6rhs.x86_64
glusterfs-rdma-3.6.0.42.1-1.el6rhs.x86_64

[root@rhs3 ~]# rpm -qa | grep samba
samba-swat-3.6.509-169.6.el6rhs.x86_64
samba-3.6.509-169.6.el6rhs.x86_64
samba-glusterfs-3.6.509-169.6.el6rhs.x86_64
samba-common-3.6.509-169.6.el6rhs.x86_64
samba-winbind-devel-3.6.509-169.6.el6rhs.x86_64
samba-client-3.6.509-169.6.el6rhs.x86_64
samba-winbind-clients-3.6.509-169.6.el6rhs.x86_64
samba-doc-3.6.509-169.6.el6rhs.x86_64
samba-winbind-3.6.509-169.6.el6rhs.x86_64
samba-domainjoin-gui-3.6.509-169.6.el6rhs.x86_64
samba-winbind-krb5-locator-3.6.509-169.6.el6rhs.x86_64

[root@rhs3 ~]# tail -n20 /etc/samba/smb.conf 
;	[public]
;	comment = Public Stuff
;	path = /home/samba
;	public = yes
;	writable = yes
;	printable = no
;	write list = +staff


[gluster-xcube]
comment = For samba share of volume xcube
vfs objects = glusterfs
glusterfs:volume = xcube
glusterfs:logfile = /var/log/samba/glusterfs-xcube.%M.log
glusterfs:loglevel = 7
path = /
read only = no
guest ok = yes
case sensitive = no
preserve case = yes


Steps On windows 7:
1. create new.txt having content "abcdef"
2. create text.txt having content "123456"
3. rename text.txt to NEW.txt

I get warning saying there is already a file with same name in same location.

I have looked into smb.conf and it seems fine.
Trying to determine what other variables could be different here.

What are the volume details? gluster vol info would be useful here.

--- Additional comment from Jose Castillo on 2015-03-18 14:51:12 IST ---

Here you go:

# gluster volume info
 
Volume Name: mediaset
Type: Distribute
Volume ID: 17531190-92c4-4201-a2d9-3e25de7f7905
Status: Started
Number of Bricks: 2
Transport-type: tcp
Bricks:
Brick1: rhs3a:/bricks/brick1
Brick2: rhs3b:/bricks/brick2
Options Reconfigured:
diagnostics.brick-log-level: TRACE
diagnostics.client-log-level: TRACE
snap-max-hard-limit: 256
snap-max-soft-limit: 90
auto-delete: disable

I've just tried your test and failed for me as well

--- Additional comment from Jose Castillo on 2015-03-18 16:27:55 IST ---

[2015-03-18 10:42:16.212457] E [client-rpc-fops.c:1091:client3_3_getxattr_cbk] 0-mediaset-client-0: 01362725: After secondGF_PROTOCOL_DICT_UNSERIALIZE rsp.op_ret = 0 and op_errno = 0
[2015-03-18 10:42:16.212471] E [dht-common.c:2679:dht_getxattr_get_real_filename_cbk] 0-mediaset-dht: 01362725: Inside dht_getxattr_get_real_filename_cbk
[2015-03-18 10:42:16.212481] E [dht-common.c:2687:dht_getxattr_get_real_filename_cbk] 0-mediaset-dht: 01362725: Inside dht_getxattr_get_real_filename_cbk before dict_ref xattr
[2015-03-18 10:42:16.212490] E [dht-common.c:2693:dht_getxattr_get_real_filename_cbk] 0-mediaset-dht: 01362725: Inside dht_getxattr_get_real_filename_cbk before dict_ref xdata
[2015-03-18 10:42:16.212706] W [dict.c:499:dict_ref] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1e0)[0x7f6aff6cb550] (--> /usr/lib64/libglusterfs.so.0(dict_ref+0x6e)[0x7f6aff6c42de] 
(--> /usr/lib64/glusterfs/3.6.3beta1/xlator/cluster/distribute.so(dht_getxattr_get_real_filename_cbk+0xfb)[0x7f6aefb3d48b] (--> /usr/lib64/glusterfs/3.6.3beta1/xlator/protocol/client.so(client3
_3_getxattr_cbk+0x239)[0x7f6aefd90289] (--> /usr/lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0xa5)[0x7f6aff49fa75] ))))) 0-dict: dict is NULL


For the modified source code:

--- a/xlators/cluster/dht/src/dht-common.c
+++ b/xlators/cluster/dht/src/dht-common.c
@@ -2675,16 +2675,22 @@ dht_getxattr_get_real_filename_cbk (call_frame_t *frame, void *cookie,
         int             this_call_cnt = 0;
         dht_local_t     *local = NULL;
 
+       gf_log (this->name, GF_LOG_ERROR, "01362725: Inside " 
+                               "dht_getxattr_get_real_filename_cbk");
 
         local = frame->local;
 
        if (op_ret != -1) {
                if (local->xattr)
                        dict_unref (local->xattr);
+               gf_log(this->name, GF_LOG_ERROR, "01362725: Inside "
+                               "dht_getxattr_get_real_filename_cbk before dict_ref xattr");
                local->xattr = dict_ref (xattr);
 
                if (local->xattr_req)
                        dict_unref (local->xattr_req);
+                gf_log(this->name, GF_LOG_ERROR, "01362725: Inside "
+                                "dht_getxattr_get_real_filename_cbk before dict_ref xdata");
                local->xattr_req = dict_ref (xdata);
        }

If xattr was NULL then we should've seen the order slightly changed, right? Something like this:

[2015-03-18 10:42:16.212471] E [dht-common.c:2679:dht_getxattr_get_real_filename_cbk] 0-mediaset-dht: 01362725: Inside dht_getxattr_get_real_filename_cbk
[2015-03-18 10:42:16.212481] E [dht-common.c:2687:dht_getxattr_get_real_filename_cbk] 0-mediaset-dht: 01362725: Inside dht_getxattr_get_real_filename_cbk before dict_ref xattr
[2015-03-18 10:42:16.212706] W [dict.c:499:dict_ref] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1e0)[0x7f6aff6cb550] (--> /usr/lib64/libglusterfs.so.0(dict_ref+0x6e)[0x7f6aff6c42de] 
(--> /usr/lib64/glusterfs/3.6.3beta1/xlator/cluster/distribute.so(dht_getxattr_get_real_filename_cbk+0xfb)[0x7f6aefb3d48b] (--> /usr/lib64/glusterfs/3.6.3beta1/xlator/protocol/client.so(client3
_3_getxattr_cbk+0x239)[0x7f6aefd90289] (--> /usr/lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0xa5)[0x7f6aff49fa75] ))))) 0-dict: dict is NULL
[2015-03-18 10:42:16.212490] E [dht-common.c:2693:dht_getxattr_get_real_filename_cbk] 0-mediaset-dht: 01362725: Inside dht_getxattr_get_real_filename_cbk before dict_ref xdata

--- Additional comment from Raghavendra Talur on 2015-03-20 18:55:57 IST ---

Description of problem:
When we have the options "case sensitive = no" and "preserve case = yes" in /etc/samba/smb.conf, renaming a file to a variation of upper and lower case letters of an existing file causes the file that was being renamed to dissapear in the client, and the change to succeed. After umounting and mounting again the samba share, the two versions of the file are visible but only the content of the first one (the one all lowercase) is shown whenever any of them is accessed.

For all my tests I first created a file "test.txt" with a very distinctive content, i.e. test1, and followed up with renaming some other files:
"test2.txt" with content test2 to "tesT.txt"
"tes3.txt" with content test3 to "Test.txt"

In both of these cases, the renamed files disappeared, showing only the file "test.txt". 
When not using the gluster samba vfs plugin, the Windows 7 client is prevented the creation of any file with variations of upper and lower cases of an existing file, showing a windows that reads ' There is already a file with the same name in this location. Do you want to rename "test2.txt" to "new test (2).txt"?'

Version: glusterfs-3.6.3beta1-0.11.gitd494bec.el6

How reproducible:
Always.

Steps to Reproduce:
0. Mount a samba share in a Windows 7 client.
1. Create a file test.txt with any content.
2. Create a second file test2.txt with some different content.
3. Rename test2.txt to tesT.txt.

Actual results:
test2.txt dissapears completely with both the old name and the new tesT.txt name. Only test.txt is visible.

Expected results:
A warning is shown that prevents the file to be renamed as a result of the caseless comparison between the existing test.txt and the attempt to rename test2.txt to tesT.txt.

--- Additional comment from Anand Avati on 2015-03-20 19:06:22 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret.) posted (#1) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-03-20 19:14:22 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret.) posted (#2) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-03-20 19:16:38 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret.) posted (#3) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-03-22 18:45:10 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret.) posted (#4) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-03-23 01:32:08 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret.) posted (#5) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-03-23 01:33:50 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret.) posted (#6) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-03-25 17:47:29 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret.) posted (#7) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-03-26 01:39:35 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret) posted (#8) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-04-01 14:30:12 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret) posted (#9) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-04-02 18:10:20 IST ---

REVIEW: http://review.gluster.org/9956 (cluster/dht: Unwind with proper op_ret) posted (#10) for review on master by Raghavendra Talur (rtalur)

--- Additional comment from Anand Avati on 2015-04-06 18:57:23 IST ---

COMMIT: http://review.gluster.org/9956 committed in master by Shyamsundar Ranganathan (srangana) 
------
commit 331e705b6a458600c0b5cbcf2b0f7b9e1167bdc2
Author: Raghavendra Talur <rtalur>
Date:   Fri Mar 20 18:35:26 2015 +0530

    cluster/dht: Unwind with proper op_ret
    
    1. Expected behavior of get_real_filename feature.
    
    A getxattr on a existing dir with glusterfs.get_real_filename:<filename>
    as key should result in one of the following things.
    
    a. A value returned for that key having the real filename (a file whose
    match is a case insensitive match to the filename passed in key).
    b. op_ret = -1 and errno set to ENOENT meaning that no such file exists
    under the specified dir in any case.
    c. op_ret = -1 and errno set to ENODATA. This is a case assuming no
    xlator interprets the glusterfs.get_real_filename key and it get
    passed down to the posix xlator. Naturally, posix xlator would not
    find any xattr with this key and would return ENODATA. This will be
    interpreted specially by the caller as the feature not being supported
    by underlying glusterfs.
    
    2. What assumptions are wrong?
    Initially the key used to be user.glusterfs.get_real_filename.
    In that case, when posix xlator did a getxattr call it would have
    received ENODATA as error. However, the key has now changed to
    glusterfs.get_real_filename. This leads to a EOPNOTSUPP error instead.
    
    Considering the above information, this is a rewrite of
    get_real_filename logic in dht.
    
    Change-Id: I012e9150047fc8563be91b0d112a368ac1cbf598
    BUG: 1204140
    Signed-off-by: Raghavendra Talur <rtalur>
    Reviewed-on: http://review.gluster.org/9956
    Tested-by: Gluster Build System <jenkins.com>
    Reviewed-by: N Balachandran <nbalacha>
    Reviewed-by: Shyamsundar Ranganathan <srangana>