I have the problem, that editors (eclipse, gedit, jed) report a change of the file while nothing was changed. I observe the same problem on Windows, so I'm not sure this isn't a bug in the Samba server.
Created attachment 4994 [details] strace of gedit while reproducing this bug While the kernel reports at 18:17:35.88 this 3262 18:17:35.882825 lstat64("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php", {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=0, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:35, st_ctime=2009/11/24-18:17:35}) = 0 a second later it says: 3262 18:17:36.898671 lstat64("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php", {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=16, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:39, st_ctime=2009/11/24-18:17:39}) = 0 But gedit does not seem to observe this. It detects the change at 18:17:44.54 3262 18:17:44.543854 lstat64("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php", {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=16, st_size=6558, st_atime=2009/11/24-18:17:43, st_mtime=2009/11/24-18:17:39, st_ctime=2009/11/24-18:17:39}) = 0 Then it opens the warning icon and so on. In the time gap between 18:17:36 and 18:17:44 I've reloaded the page so Apache accessed the file on the server. Apache and Samba access the same filesystem (ext3). I think you get a good picture of what's going on with the grep expression grep -E '(lstat.*/(busine|\.gedit)|fstat|open|rename|close)'
Created attachment 4995 [details] strace of smbd while reproducing this bug
Created attachment 4996 [details] Network traffic while reproducing this bug In the time gap between 18:17:36 and 18:17:44 I've reloaded the web page in Firefox to make Apache access' the file. Samba and Apache access the same filesystem (ext3) at the server.
I'm using Samba 3.4.3 on the server and running Ubuntu Linux 2.6.28-16 on the client. But I have the same problem with (vanilla) Linux 2.6.31-rc5. This bug isn't surely reproducible. If you are the only person accessing the server I've never seen this problem. But I guess when a Windows client connects to this share this problem arises. When three or more clients are connected to the server this problem arises permanently and this is very annoying.
Now, I'm sure this is a bug in the Samba server. I've downgraded to 3.0.24 and the problem vanished. The Windows and the Linux client didn't suffer from permanent changes of timestamps anymore. I plan to do an bisect between 3.0.24 and 3.2.5 where I've first saw this problem. Can someone reassign this bug to the Samba server?
I've digged somewhat into the data and I'm sure it's a bug in the Samba server. Here's what goes on at the server side (stripped down smbd.st): 18:17:39.029656 open("magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE|O_NOFOLLOW, 0777) = 31 18:17:39.044431 lstat64("magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", {st_dev=makedev(3, 5), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=4096, st_blocks=0, st_size=0, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:39, st_ctime=2009/11/24-18:17:39}) = 0 18:17:39.044616 utimes("magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", {{1259083059, 0}, {1259083056, 0}}) = 0 18:17:39.046559 fstat64(31, {st_dev=makedev(3, 5), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=4096, st_blocks=0, st_size=0, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:36, st_ctime=2009/11/24-18:17:39}) = 0 18:17:39.046853 pwrite64(31, "<?php\r\nclass MA_ControllerBusines"..., 6558, 0) = 6558 18:17:39.054049 lstat64("magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", {st_dev=makedev(3, 5), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=4096, st_blocks=16, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:39, st_ctime=2009/11/24-18:17:39}) = 0 18:17:39.056329 rename("magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", "magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php") = 0 18:17:39.064066 close(31) = 0 18:17:39.064218 lstat64("magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php", {st_dev=makedev(3, 5), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=4096, st_blocks=16, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:39, st_ctime=2009/11/24-18:17:39}) = 0 And this goes on at the client side (stripped down gedit.st): 18:17:35.716992 open("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) = 21 18:17:35.735133 write(21, "<?php\r\nclass MA_ControllerBusines"..., 6557) = 6557 18:17:35.735340 write(21, "\n"..., 1) = 1 18:17:35.741610 rename("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", "/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php") = 0 18:17:35.747722 fstat64(21, {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=0, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:35, st_ctime=2009/11/24-18:17:35}) = 0 18:17:35.748040 lstat64("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php", {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=0, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:35, st_ctime=2009/11/24-18:17:35}) = 0 18:17:35.753111 close(21) = 0 18:17:36.898671 lstat64("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php", {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=16, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:39, st_ctime=2009/11/24-18:17:39}) = 0 As you can see, the server opens the file, updates the timestamps and then writes the data to the file. The update of the timestamps works, as you can see in the fstat64 call. But the pwrite64 destroys these timestamps, because the kernel updates them, as you can see in the next lstat64 call. In the last lstat64 call on the client these timestamps arise and make the client think something has changed. IMO the utimes call should happen after the pwrite64 call. BTW: The client sends to the server in packet 74 the timestamp 18:17:35.731796100, but the server sets the timestamp 18:17:36 which looks like another source of time differences and confusions. BTW 2: Why does the server not set the fraction part (tv_usec) of the timestamp?
Today I've digged further through the data and the code. I saw the utimes call by smbd was triggered by package 74. Either this package was triggered by the ftrunc64 call of the application gedit or the kernel send out this package in preparation for the write. But after the write the client (Linux kernel) does not refresh the mtime of the written file. Here's a stripped down version of the gedit.st: 18:17:35.716992 open("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) = 21 18:17:35.725731 umask(022) = 077 18:17:35.725833 fchown32(21, 1008, 1000) = 0 18:17:35.727222 fchmod(21, 0100774) = 0 18:17:35.732773 ftruncate64(21, 0) = 0 18:17:35.735133 write(21, "<?php\r\nclass MA_ControllerBusines"..., 6557) = 6557 18:17:35.735340 write(21, "\n"..., 1) = 1 18:17:35.735434 fsync(21) = 0 18:17:35.741610 rename("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/.gedit-save-4RIP3U", "/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php") = 0 18:17:35.747722 fstat64(21, {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=0, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:35, st_ctime=2009/11/24-18:17:35}) = 0 18:17:35.748040 lstat64("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php", {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=0, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:35, st_ctime=2009/11/24-18:17:35}) = 0 18:17:35.753111 close(21) = 0 18:17:36.898671 lstat64("/mnt/projects/magdeburger-allee/html/gen_default/lib/classes/controller/businesscard.php", {st_dev=makedev(0, 24), st_ino=1009589, st_mode=S_IFREG|0774, st_nlink=1, st_uid=1008, st_gid=1000, st_blksize=16384, st_blocks=16, st_size=6558, st_atime=2009/11/24-18:17:39, st_mtime=2009/11/24-18:17:39, st_ctime=2009/11/24-18:17:39}) = 0 I think this happens: application: open <... client (linux kernel): assigns ctime and mtime to an inode in its cache application: ...> application: write <... client: write_to_server <... server: write_to_fs (pwrite64) <... kernel of server: writes data to disk and update mtime on its fs server: ...> client: ...> (*) application: ...> application: lstat <... client: takes mtime from its cache application: ...> IMO after (*) the client should fetch the mtime from the server or push its mtime to the server.
I would expect a utimes() call before the close, that resets the times, but it's somehow missing. What exact samba version are you using? Jeremy, can you take a look at this you know much more about the posix stuff
Currently, I'm running Samba 3.4.3, but I can reproduce this problem with version 3.2.5 and 3.0.24. BTW: What should happen when the client keeps the file open? Shouldn't the update/reset happen after each write? open() utimes() write() lstat() --> What should lstat report here? ... more operations. close()
Created attachment 5063 [details] A short test program Current time: Mon Dec 7 21:39:22 2009 open succeed stat : mtime=Mon Dec 7 21:38:45 2009 ctime=Mon Dec 7 21:38:45 2009 atime=Mon Dec 7 21:38:44 2009 fstat : mtime=Mon Dec 7 21:38:45 2009 ctime=Mon Dec 7 21:38:45 2009 atime=Mon Dec 7 21:38:44 2009 utimes succeed stat : mtime=Mon Dec 7 21:39:06 2009 ctime=Mon Dec 7 21:39:06 2009 atime=Mon Dec 7 21:39:22 2009 fstat : mtime=Mon Dec 7 21:39:06 2009 ctime=Mon Dec 7 21:39:06 2009 atime=Mon Dec 7 21:39:22 2009 write succeed stat : mtime=Mon Dec 7 21:39:06 2009 ctime=Mon Dec 7 21:39:06 2009 atime=Mon Dec 7 21:39:22 2009 fstat : mtime=Mon Dec 7 21:39:06 2009 ctime=Mon Dec 7 21:39:06 2009 atime=Mon Dec 7 21:39:22 2009 close succeed stat : mtime=Mon Dec 7 21:39:24 2009 ctime=Mon Dec 7 21:39:24 2009 atime=Mon Dec 7 21:39:22 2009 You can see, the mtime changes after the close call to a different time the client has set before with utimes. This makes the client (and the application) think something has changed, while nobody touched the file.
Can you also attach a network capture and level 10 log of a run of the test program?
Created attachment 5265 [details] Logging output of Samba while running the test program
Created attachment 5266 [details] Dump of the network traffic while running the test program
As you can see in the samba log something add an update_write_time_handler that causes the update of the time on close.
This behavior is correct. There's no SET_FILE_INFO, which would trigger the behavior to not updating the write time on close. But there's only a SET_PATH_INFO, which doesn't operate on the file handle.
At least it's no Samba server bug... Maybe a missing libsmbclient feature or a cifs.ok bug...
(In reply to comment #16) > At least it's no Samba server bug... > > Maybe a missing libsmbclient feature > or a cifs.ok bug... Hence, the kernel has to send a SET_PATH_INFO request to the server, setting the time stamp he announce to the application, after each write. Is this correct? And the other question is, why doesn't Windows act this way? I'm having the same problem on Windows XP, that after the client send the file to the server, the application sees a magical change of the modification time (the time update after close). This vanishes when the clocks of the client and the server are in sync, but that's only an ugly workaround.
Windows uses SET_FILE_INFO instead of SET_PATH_INFO. If there's a SET_FILE_INFO on the same file handle the close will skip the time update.
(In reply to comment #18) > Windows uses SET_FILE_INFO instead of SET_PATH_INFO. > > If there's a SET_FILE_INFO on the same file handle the close > will skip the time update. Is it possible to use the write_time field of the close request? If the Linux client sets the value of this field to the write time he announce to the application, would Samba change this value on close?
Looking
Or can cifs client flush timestamps using a still valid filehandle during close before returning to the caller thus keeping consistent timestamps amongst app, cifs client, and server?
> Is it possible to use the write_time field of the close request? If the Linux > client sets the value of this field to the write time he announce to the > application, would Samba change this value on close? I think this is worth trying against both, Samba and Windows server. I will make a code change but probably have to wait for couple of days to get started on this.
Need to convert unix time to 32 bit NT time (LastWriteTime is 32 bits long). But even while sending mtime as (incorrect) LastWriteTime, when read back, I could see that only mtime and not atime and ctime get updated on the server i.e. mtime on the server inode could lag atime and ctime.