Bug 6925 - Kernel does not refresh mtime after write
Kernel does not refresh mtime after write
Status: NEW
Product: CifsVFS
Classification: Unclassified
Component: kernel fs
2.6
Other Linux
: P3 normal
: ---
Assigned To: Steve French
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2009-11-24 12:15 UTC by Jörg Sommer
Modified: 2010-02-23 04:28 UTC (History)
3 users (show)

See Also:


Attachments
strace of gedit while reproducing this bug (736.53 KB, text/plain)
2009-11-24 12:23 UTC, Jörg Sommer
no flags Details
strace of smbd while reproducing this bug (133.66 KB, text/plain)
2009-11-24 12:25 UTC, Jörg Sommer
no flags Details
Network traffic while reproducing this bug (48.38 KB, application/octet-stream)
2009-11-24 12:31 UTC, Jörg Sommer
no flags Details
A short test program (2.55 KB, text/plain)
2009-12-07 14:47 UTC, Jörg Sommer
no flags Details
Logging output of Samba while running the test program (58.50 KB, text/plain)
2010-02-03 11:48 UTC, Jörg Sommer
no flags Details
Dump of the network traffic while running the test program (7.06 KB, application/octet-stream)
2010-02-03 11:49 UTC, Jörg Sommer
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Jörg Sommer 2009-11-24 12:15:39 UTC
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.
Comment 1 Jörg Sommer 2009-11-24 12:23:42 UTC
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)'
Comment 2 Jörg Sommer 2009-11-24 12:25:07 UTC
Created attachment 4995 [details]
strace of smbd while reproducing this bug
Comment 3 Jörg Sommer 2009-11-24 12:31:46 UTC
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.
Comment 4 Jörg Sommer 2009-11-24 12:39:19 UTC
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.
Comment 5 Jörg Sommer 2009-11-29 06:48:42 UTC
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?
Comment 6 Jörg Sommer 2009-12-02 09:39:13 UTC
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?
Comment 7 Jörg Sommer 2009-12-03 09:17:55 UTC
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.
Comment 8 Stefan Metzmacher 2009-12-07 11:01:23 UTC
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
Comment 9 Jörg Sommer 2009-12-07 11:21:26 UTC
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()
Comment 10 Jörg Sommer 2009-12-07 14:47:37 UTC
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.
Comment 11 Stefan Metzmacher 2010-02-01 11:29:29 UTC
Can you also attach a network capture and level 10 log of a run of the test program?
Comment 12 Jörg Sommer 2010-02-03 11:48:11 UTC
Created attachment 5265 [details]
Logging output of Samba while running the test program
Comment 13 Jörg Sommer 2010-02-03 11:49:14 UTC
Created attachment 5266 [details]
Dump of the network traffic while running the test program
Comment 14 Jörg Sommer 2010-02-03 11:53:01 UTC
As you can see in the samba log something add an update_write_time_handler that causes the update of the time on close.
Comment 15 Stefan Metzmacher 2010-02-11 06:20:11 UTC
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.
Comment 16 Stefan Metzmacher 2010-02-11 06:23:59 UTC
At least it's no Samba server bug...

Maybe a missing libsmbclient feature
or a cifs.ok bug...
Comment 17 Jörg Sommer 2010-02-11 06:34:53 UTC
(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.
Comment 18 Stefan Metzmacher 2010-02-11 07:02:10 UTC
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.
Comment 19 Jörg Sommer 2010-02-11 08:24:44 UTC
(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?
Comment 20 Shirish S. Pargaonkar 2010-02-16 15:41:21 UTC
Looking
Comment 21 Shirish S. Pargaonkar 2010-02-17 17:21:27 UTC
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?
Comment 22 Shirish S. Pargaonkar 2010-02-18 15:14:24 UTC
> 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.

Comment 23 Shirish S. Pargaonkar 2010-02-23 04:28:43 UTC
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.