[BUG] Moved file has size 0

[edge91]

Hello again,

first of all, loved the product and I think you are doing a great job. I was ready to move from tc to mc but I discovered a bug that I think is a very big one. When I move a file, or better said, when I want to move a file from my local drive to a mapped network drive, sometimes it happened that the original file is deleted and the file on the mapped drive has 0 size (I checked in the windows explorer it also says 0). In the whole procedure everything is ok, it says it is copying file, the computer and the network take their time (I can see the data being transfered in my network monitor), then it says it is copied and that everything is ok, then the file from my local drive is deleted and the file on the mapped network drive has 0 size.  If you want I can do more tests to see if the problem is related to only a specific extensions, does it occur in special cases, or anything that would help you solve the problem.

I would also like to mention that the network drive is running just fine and doesn't have any problems.

[Mathias (Author)]

That is very strange.
I never seen that and no reports of it.

When moving a file the file is first copied and then the source is deleted, The source file is not deleted unless it successfully copied the file to the target.
It actually is verifying the target file size is correct before deleting the source file.
So how it can delete source file when target is 0 is very strange.

What is the network location.. Another Windows Server ? NAS ? Linux ? Mac ?
Any error in any log on the server ?
You are sure that there is no file system issue on the target device ? I seen file go to 0 if the filesystem was corrupt. specially on some NAS devices.
What does the fileoperation log in MC say ? Any error there ?
Do you see the file grow in size during file copy and then end up at 0 ?

[edge91]

NAS DLink DNS-320 with two WD Green 2TB drives in RAID 1 with static IP address. I haven't seen any error report on the NAS.

The problem shouldn't be on the device since TC worked with it for 1+ year and never had any problems.

I made a small video showing you what is going on... I think it will answer many questions...

http://youtu.be/LLKoiyQHqxQ

[Jungle]

Strange. In both cases zero-sized file is the same. Looks like antivirus deletes content after file is written.

[edge91]

I tried to copy and move those exact same files, from those same locations, to the same location with WE and TC and everything was fine. Didn't get any error or antivirus / firewall warning....

I should mention that this only happens in MC when I copy to the Z: drive aka. network mounted drive, when I try to move from one HDD to another in my PC everything is fine. It also happens when I access to the drive / folder via the Network (in the drop down menu).

[Mathias (Author)]

Very strange.. Never seen anything like that. AntiVirus is also the first thing that popup in my mind that can mess with the filesystem like that.

Did the FileOperation log say anything ?

In Core Settings set log level to "Debug (eval)" for FileSystem Log.
and then copy the file that fails.
and then look in the log if there are any issues reported. (Ctrl+L to show log window, and click on FileOperation tab)

[Mathias (Author)]

If you are used to advanced tools.

You can run the Microsoft tool Process Monitor to track all file access in the system.
And then you can filter out for just that file and see what is happening and what process that does it.
(Or you can save the entire trace log and send to me at http://multicommander.com/upload (let me know the filename to look for) )

[edge91]

Very strange.. Never seen anything like that. AntiVirus is also the first thing that popup in my mind that can mess with the filesystem like that.

Did the FileOperation log say anything ?

In Core Settings set log level to "Debug (eval)" for FileSystem Log.
and then copy the file that fails.
and then look in the log if there are any issues reported. (Ctrl+L to show log window, and click on FileOperation tab)

Followed your instructions and this is what I am getting...

Code: [Select]

2014-02-26 20:27:18.201 FileOperationDlg - AutoDetect RW Stratergy - "To network"
2014-02-26 20:27:19.590 Start FileOperation (Copy/Move/Delete) Settings
2014-02-26 20:27:19.590 '-- Chunk size  : 262144
2014-02-26 20:27:19.591 '-- Buffer size : 10485760
2014-02-26 20:27:19.591 '-- Read Flags  : 0x0
2014-02-26 20:27:19.594 '-- Write Flags : 0x10
2014-02-26 20:27:19.599 '-- Flags       : 0x600204
2014-02-26 20:27:19.652 Allocating Buffers (Chunks = 40 , Chunks size = 262144 Bytes , Buffer size = 10485760 Bytes)
2014-02-26 20:27:19.652 Prepare Write - Create new file on target. : "Z:\Backup\babka.rs\temp\sk-backup20140225.zip"
2014-02-26 20:27:19.666 Prepare Copy - Asynchronous mode enabled.
2014-02-26 20:27:19.666 ThreadWrite created
2014-02-26 20:27:31.169 [4076] Wait for WriteThread to finish and pause.
2014-02-26 20:27:31.769 [4076] WriteThread is now paused.
2014-02-26 20:27:31.769 Copied : "C:\Users\martin\Documents\sk-backup20140225.zip" => "Z:\Backup\babka.rs\temp\sk-backup20140225.zip" - 198875648 bytes (189.7 MB) in 12sec - Average Speed : 16427857 bytes/sec (15.7 MB/sec) Read data time 203ms (934.3 MB/sec),  Write data time 12010ms (15.8 MB/sec)
2014-02-26 20:27:31.774 Add path to Refresh Queue : "Z:\Backup\babka.rs\temp\"
2014-02-26 20:27:31.777 Local file was written to using NoSystemCache - Fixing Filesize : "Z:\Backup\babka.rs\temp\sk-backup20140225.zip"
2014-02-26 20:27:31.788 Current file size : "198875648", Bytes past EOF : 274
Part of the log for a successful copy.

Code: [Select]

2014-02-26 20:28:43.377 FileOperationDlg - AutoDetect RW Stratergy - "To network"
2014-02-26 20:28:43.903 Start FileOperation (Copy/Move/Delete) Settings
2014-02-26 20:28:43.903 '-- Chunk size  : 262144
2014-02-26 20:28:43.903 '-- Buffer size : 10485760
2014-02-26 20:28:43.904 '-- Read Flags  : 0x0
2014-02-26 20:28:43.904 '-- Write Flags : 0x10
2014-02-26 20:28:43.904 '-- Flags       : 0x600204
2014-02-26 20:28:43.915 Allocating Buffers (Chunks = 40 , Chunks size = 262144 Bytes , Buffer size = 10485760 Bytes)
2014-02-26 20:28:43.930 Prepare Write - Create new file on target. : "Z:\Backup\babka.rs\temp\administrator.zip"
2014-02-26 20:28:44.385 Prepare Copy - Asynchronous mode enabled.
2014-02-26 20:28:44.385 ThreadWrite created
2014-02-26 20:28:47.130 [6412] Wait for WriteThread to finish and pause.
2014-02-26 20:28:47.630 [6412] WriteThread is now paused.
2014-02-26 20:28:47.630 Copied : "C:\Users\martin\Downloads\administrator.zip" => "Z:\Backup\babka.rs\temp\administrator.zip" - 54824448 bytes (52.3 MB) in 3sec - Average Speed : 16900261 bytes/sec (16.1 MB/sec) Read data time 196ms (266.8 MB/sec),  Write data time 3217ms (16.3 MB/sec)
2014-02-26 20:28:47.638 Add path to Refresh Queue : "Z:\Backup\babka.rs\temp\"
2014-02-26 20:28:47.638 Local file was written to using NoSystemCache - Fixing Filesize : "Z:\Backup\babka.rs\temp\administrator.zip"
2014-02-26 20:28:47.651 Current file size : "54824448", Bytes past EOF : 335

[edge91]

If you are used to advanced tools.

You can run the Microsoft tool Process Monitor to track all file access in the system.
And then you can filter out for just that file and see what is happening and what process that does it.
(Or you can save the entire trace log and send to me at http://multicommander.com/upload (let me know the filename to look for) )

I uploaded you the logs (didn't know which format you wanted so I saved in all): proc_log_edge91.zip

Also, I have noticed that when I wanted to save the selection from log in MC it didn't work. I selected the text, right - clicked, Save to file, it created the file, but it was empty.

If you need anything else, just ask, I am willing to help as much as I can.

[Mathias (Author)]

Strange..
The FileOperation log looks correct and I can find anything in the ProcMon log that MC shorten/empty the file (Only the MC Process is available in ProcMon log, So I can't see if another program does something to that file.)

Sure it is not antivirus or something?

[edge91]

I tried disabling my AV and firewall, still the same results. There's no antivirus or firewall on the NAS.

I'll try from another computer tomorrow.

[Mathias (Author)]

Found this in user comments on Amazon for that NAS D-Link 320
http://www.amazon.com/D-Link-DNS-320-ShareCenter-Network-Enclosure/dp/B004SUO450   (comment from April 6, 2012)

"Since the November 2011 release of Firmware 2.02, users have been reporting data integrity problems with the box - including files that get copied and then show up as "0 bytes". (See forums.dlink.com for DNS-320)"

So it might be a NAS issue. you can try to turn off optimized file copy in MC, then file copy will be less optimized but it might be what the NAS needs.
Either disable "Automatically detect read/write strategy for file copy" then the unoptimized read/write will always be done.
or you can tweak just that read/write strategy used for your network copy.. I guess to will be "To Network" (if it detects it correct) and then enable all checkboxes for write options.

[edge91]

To network --> Write options(Target) --> Use system cache should be checked, then it works like a charm.

Maybe this could be the default settings in future releases?

BTW. thank you for pointing that bug for the NAS, I really didn't have a clue that other people were experiencing problems... I know I've never had problems with it so I assumed it isn't the problem... I will have to check for new firmware.

[Mathias (Author)]

To network --> Write options(Target) --> Use system cache should be checked, then it works like a charm.

Maybe this could be the default settings in future releases?

No. MC has to assume that hardware works as they should, and how Windows require the hardware to work.

Enabling System Cache will hurt performance a bit since all data that should be written will now also be cached by Windows.
It can also give you false sense of the progress, since the progress you see is when the data have been sent to the cache, not the actual drive/target device.
And it can also give you a jerky copy experience, First the progress goes very fast, then it stops/halt because the system cache is full and everything stop and wait until all the data have actually been written and then it continues. And it continues to do so. This is specially seen on large files. But also depends on how much RAM you got left that the system uses for cache.