Bug 10865 - Data corruption when Windows locking in use and a file is renamed while being written.
Data corruption when Windows locking in use and a file is renamed while being...
Status: NEW
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services
4.1.12
All All
: P5 major
: ---
Assigned To: Samba QA Contact
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2014-10-09 19:57 UTC by Paul Green
Modified: 2016-04-18 19:04 UTC (History)
4 users (show)

See Also:


Attachments
Detailed description of the problem, including extracts of traces. (108.25 KB, application/msword)
2014-10-09 19:57 UTC, Paul Green
no flags Details
strace of ftp send operation (Machine A) (332.66 KB, text/plain)
2014-10-10 16:26 UTC, Paul Green
no flags Details
strace of ftp rename operation (Machine A) (4.73 KB, text/plain)
2014-10-10 16:26 UTC, Paul Green
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Paul Green 2014-10-09 19:57:17 UTC
Created attachment 10335 [details]
Detailed description of the problem, including extracts of traces.

We are experiencing file corruption with Samba 3.6.12 when a file that is the target of an ftp put operation, and which resides on a Samba share, is renamed prior to the conclusion of the transfer.  We can consistently produce similar patterns of corruption by using different versions of Linux as the host of Samba. The corruption is typically related to lock conflicts that prevent the writing of locked regions, directly leading to data corruption (specifically, holes of zeros).  Corruption patterns are consistent when the test is repeated with a given scenario, but vary with different versions of Samba or Linux. 

The lock conflicts first appear at the time of the rename.  They lead to an unsuccessful oplock break attempt (apparently due to a sharing violation), which does not happen when using Samba 3.2.4 with the same clients.

This scenario was originally reported to us when the target of the Samba share resided on a Stratus VOS machine, but since then we have reproduced similar corruption on various Linux machines running Samba 3.6.12. We also see similar corruption using Samba 4.1.12, which we built from the source3 directory in the 4.1.X tarball.

Please refer to the attached file named Samba_Data_Corruption.rtf for complete details.
Comment 1 Volker Lendecke 2014-10-09 20:02:57 UTC
If possible, can you get us

- debug level 10 logs of the participating smbds
- network traces of the ftp and cifs mounts
- strace -ttT of the ftp server process[es] serving the clients

This would probably be a great info source to solve this.

Thanks!

Volker
Comment 2 Paul Green 2014-10-09 20:39:17 UTC
We will get you traces. 

Here is some additional information regarding the test setup.

We have two processes using the ftp client on Machine A. The first process performs the ftp "put" request. When the put completes, it triggers a second process to perform the ftp "rename" request. So all of the user activities are routed via ftp to Machine B, and machine B routes all of the activities via CIFS to Machine C, which is running Samba.

Indeed, as suggested, we did try running with "no oplocks". 

This simply eliminates the optimization which if TRUE generates this message:

   is_locked: optimisation - exclusive oplock on file test_file.stm.071E46AC

but when FALSE, we go right into the brl_lock code.  This case runs fine until the rename. The break processing in this case is a bit different, resulting in a downgrade:

   initial_break_processing: called for 80400720:64edc9:0/937497185 Current      
oplocks_open (exclusive = 0, levelII = 0)
   process_oplock_async_level2_break_message: downgrading fake level 2 oplock.

but right after this message, we see the same situation with a lock requested with a different smblctx, which results in the lock conflict and missing write.

Note: this was tried with Scenario 1 in which we get the same behavior with linux and VOS running the daemon.
Comment 3 Paul Green 2014-10-09 21:38:31 UTC
A level 10 Samba 4.1.12 debug log for Scenario 1, using only Linux servers, is now available at ftp://ftp.stratus.com/pub/vos/samba-10865/wyeth1-georgeft.d10+.samba-4.1.12.corrupt.log.

We have confirmed that data corruption is present, and the offsets of the corruption match the offsets recorded in the log file.

"Wyeth1" is Machine A. "Georgeft" is Machine B. "d10+" means a debug level 10 log plus our own added debug messages.

We will produce the other logs tomorrow.
Comment 4 Paul Green 2014-10-09 21:40:22 UTC
My colleagues have informed me that while our customer claims that they wait for the ftp to (appear to) finish before issuing the rename request, in our reproduction test case, we just go ahead and issue the rename while the file is still clearly in motion. I apologize for my mistake.
Comment 5 Paul Green 2014-10-10 16:26:00 UTC
Created attachment 10343 [details]
strace of ftp send operation (Machine A)
Comment 6 Paul Green 2014-10-10 16:26:55 UTC
Created attachment 10344 [details]
strace of ftp rename operation (Machine A)
Comment 7 Paul Green 2014-10-10 18:04:15 UTC
I have uploaded the packet trace files to ftp://ftp.stratus.com/pub/vos/samba-10865, where they can be retrieved via anonymous ftp.

The file m112-wyeth1-tcpdump.log is the trace between Machine A and Machine B. It is approximately 17MB.

The file wyeth1-georgeftserver-tcpdump.log is the trace between Machine B and Machine C. It is approximately 124MB.

For good measure, I have also placed the two strace files in this directory as well.
Comment 8 Paul Green 2014-10-15 17:54:16 UTC
Volker wrote:

The tcpdump logs are the stdout of tcpdump. Unfortunately, that is
missing a lot of information. If possible, can you repeat the test and
do network traces according to

https://wiki.samba.org/index.php/Capture_Packets

to get the raw traces? Also, the ftp server and the Samba server seem
to have different clocks. The strace is a bit past 12pm, the Samba
server is right before 5pm. Not super-important, but if possible, can
you coordinate both clocks?

...and I respond:

We are re-running them now.
Comment 9 Paul Green 2014-10-15 22:17:44 UTC
We have re-run the test with NTP in operation to ensure that the clocks start and stay synchronized. Also, this time we captured all of the data for the same run. 

The following files are available at ftp://ftp.stratus.com/pub/vos/samba-10865/.

The binary file m112-wyeth1.tcpdump is a packet trace between Machine A and Machine B. It is approximately 1GB.

The binary file wyeth1-georgeftserver.tcpdump is a packet trace between Machine B and Machine C. It is approximately 1GB.

The text file strace-wyeth1-ftp-send.log is an strace of the ftp send operation. It is approximately 2MB.

The text file strace-wyeth1-ftp-rename.log is an strace of the ftp rename operation. It is approximately 4KB.

The text file wyeth1-georgeft.d10+.samba-4.1.12.corrupt.log is a Samba Level 10 debug log (plus a few added debug messages from us). It is approximately 2.6GB.

The two strace attachments on this bug report, both dated 2014-10-10, should be ignored and, if possible, deleted. They are from the first run, which is no longer interesting.