[cifs-protocol] Excel timestamp client side-caching request

[Hongwei Sun]

Jeremy,

   Just a quick update.  I have duplicated the exactly same behavior as you reported, which makes live debugging possible.  We are actively working on it.  I will keep you posted.

Thanks!

-------------------------------------------------------------------
Hongwei  Sun - Sr. Support Escalation Engineer
DSC Protocol  Team, Microsoft
hongweis at microsoft.com
Tel:  469-7757027 x 57027
---------------------------------------------------------------------




-----Original Message-----
From: Jeremy Allison [mailto:jra at samba.org]
Sent: Wednesday, August 05, 2009 4:47 PM
To: Interoperability Documentation Help
Cc: jra at samba.org; pfif at tridgell.net; cifs-protocol at samba.org
Subject: Excel timestamp client side-caching request

Hi Hongwei,

As requested here is a write up of the Excel timestamps issue I've discovered with client side caching turned on.

To reproduce. Use Windows Vista with Microsoft Office 2003 :

Set up a share called "offline", containing a single Excel file "test.xls".

Mount this share as drive z:, then open with

explorer z:

Right click on the test.xls file and enable "Make this file available offline".

Then double click text.xls to open the file, and *immediately* (as soon as the Excel window
opens) click on the "X" (top right hand corner) to close Excel.

Then right click on test.xls and select "Sync".
Against a Windows 2003 server this always works, against a Samba server it intermittently (50% to 90% of the time) fails. The symptom is that the "Sync" icon in the lower bar shows a "!"
icon, and looking at the synchronization failure shows that the last write timestamp on the file on the remote server has been updated to the current time at open, instead of being the same as the original last write time which is being stored in the cache on the local Vista client.

What is going on under the covers
---------------------------------

On selecting "Make this file available offline"
the file (and metadata is copied locally onto the Vista client).

When the file is double clicked and opened by Excel, the sequence of events is that the file is opened with NTCreateX, then the last write time is set to the current time using SET_FILE_INFO, then part of the file is written to (I'm assuming to enable synchronization info to be conveyed to another process trying to open this .xls file at the same time).

When the .xls file is closed, the client
*should* then use SET_FILE_INFO to restore the last write time to the original last write time that was originally read before the file was opened.

Against a Samba server the client does this *sometimes*, but not reliably and I'm trying to figure out why.

I'm enclosing two packet capture traces.

The first is called "office2003-openclose-samba-bad.pcap"
and is the above scenario being done from a Vista client (IP address: 172.18.102.177) to a Samba server (IP address: 172.18.102.85).

The meta data of the .XLS file on the Samba server is :

  File: `test.xls'
  Size: 811520          Blocks: 1608       IO Block: 4096   regular file
Device: 806h/2054d      Inode: 11567162    Links: 1
Access: (0666/-rw-rw-rw-)  Uid: (41427/     jra)   Gid: ( 5000/     eng)
Access: 2009-07-22 12:00:00.000000000 -0700
Modify: 2009-07-31 00:00:00.000000000 -0700
Change: 2009-08-04 10:21:49.000000000 -0700

This is a modified version of Samba that stores the create time in the "access" field of the POSIX timestamp, on a filesystem mounted with "noatime"
so that field is free to use by Samba as the create time.

Packets 0 - 900 show the right click -> Set Offline action from explorer.

Packets 958 - 2079 show the open/close being done by Excel on the file - note this is an example of a "correct" operation by the client (in that it resets the "last write" timestamp correctly back to the server).

Packets 2080 - 2200 show the right click -> Sync action from explorer (that succeeds).

The rest of the packets 2201 - 2976 show the open/close right click -> Sync operation being done again immediately against the .XLS file, and this time the operation fails (the last write timestamp is not correctly reset).

The interesting packets are :

1043: SET_FILE_INFO setting the last write time to the current time.

1882: SET_FILE_INFO resetting the last write time to the original time (2009-07-31 00:00:00.000000000 -0700)
- this is the step that is missing from the second operation that causes the sync to succeed.

2262: SET_FILE_INFO setting the last write time to the current time.

Note that in this second case there is no follow up SET_FILE_INFO to reset the time to the correct original value.

What I'm trying to find out is what it is within the data Samba is returning to the client that causes the client to fail to restore the original timestamp in the case where CSC sync caching is turned on.

As a comparison, I'm including a packet trace from the same client against a Win2K3 server, called :
office2003-open-close-windows-good.cap.

This is exactly the same sequence of operations against a Win2k3 server, with IP address : 172.18.103.237 (the client IP address is still 172.18.102.177).
The file in this case is called Book1.xls.

The interesting packets in this trace are:

1216: SET_FILE_INFO setting the last write time to the current time.

1513: SET_FILE_INFO resetting the last write time to the original time.

This sequence of events is always seen in the traces to a Windows server, but only intermittently seen in the traces to a Samba server.

My first thoughts were this was a change notify issue, so the version of Samba being used for this trace emulates perfectly (as far as I can tell) the change notify replies as seen from a Windows server, yet the problem remains.

Any help tracking down what is different about the timestamp or other meta data replies that cause the Vista + Office 2003 + CSC client to behave differently against a Samba server will be gratefully received.

Thanks,

Jeremy.