Missing WriteFile during network file copy (second request) PART 2

NTFSD
1

Continued from previous email >

35697 .2614136 AM cmd.exe QueryOpen
\meter\c$\UNC\long\long12.txt FAST IO DISALLOWED

35698 .2624824 AM cmd.exe CreateFile
C:\Windows\CSC\v2.0.6\namespace\meter NAME NOT FOUND
Desired Access: Read EA, Write EA, Read Attributes, Write Attributes,
Delete, Read Control, Synchronize, Disposition: Open, Options:
Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: n/a

35699 .2644385 AM cmd.exe CreateFile
\meter\c$\UNC\long\long12.txt NAME NOT FOUND Desired
Access: Read Attributes, Disposition: Open, Options: Open Reparse Point,
Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a

35700 .2648579 AM cmd.exe CreateFile
C:\Windows\CSC\v2.0.6\namespace\meter NAME NOT FOUND
Desired Access: Read EA, Write EA, Read Attributes, Write Attributes,
Delete, Read Control, Synchronize, Disposition: Open, Options:
Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: n/a

35701 "

35702 .2664835 AM cmd.exe RegOpenKey
HKLM\Software\Policies\Microsoft\Windows\System SUCCESS
Desired Access: Query Value

35703 .2665609 AM cmd.exe RegQueryValue
HKLM\SOFTWARE\Policies\Microsoft\Windows\System\CopyFileBufferedSynchron
ousIo NAME NOT FOUND Length: 20

35704 .2666123 AM cmd.exe RegCloseKey
HKLM\SOFTWARE\Policies\Microsoft\Windows\System SUCCESS

35705 .2670618 AM cmd.exe CreateFile
C:\Windows\CSC\v2.0.6\namespace\meter NAME NOT FOUND
Desired Access: Read EA, Write EA, Read Attributes, Write Attributes,
Delete, Read Control, Synchronize, Disposition: Open, Options:
Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: n/a

35706 .2691059 AM cmd.exe CreateFile
\meter\c$\UNC\long\small.txt SUCCESS Desired Access:
Generic Read, Disposition: Open, Options: Sequential Access,
Non-Directory File, Open Reparse Point, Attributes: n/a, ShareMode:
Read, Delete, AllocationSize: n/a, OpenResult: Opened

35707 .2695202 AM cmd.exe CreateFile
C:\Windows\CSC\v2.0.6\namespace\meter NAME NOT FOUND
Desired Access: Read EA, Write EA, Read Attributes, Write Attributes,
Delete, Read Control, Synchronize, Disposition: Open, Options:
Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: n/a

35708 .2714729 AM cmd.exe QueryAttributeTagFile
\meter\c$\UNC\long\small.txt SUCCESS Attributes: A,
ReparseTag: 0x0

35709 .2715858 AM cmd.exe QueryDeviceInformationVolume
\meter\c$\UNC\long\small.txt SUCCESS DeviceType:
Disk, Characteristics: Remote

35710 .2716861 AM cmd.exe FileSystemControl
\meter\c$\UNC\long\small.txt SUCCESS Control:
IOCTL_LMR_DISABLE_LOCAL_BUFFERING

35711 .2720861 AM cmd.exe QueryStandardInformationFile
\meter\c$\UNC\long\small.txt SUCCESS AllocationSize:
8,192, EndOfFile: 5,562, NumberOfLinks: 1, DeletePending: False,
Directory: False

35712 .2725675 AM cmd.exe QueryBasicInformationFile
\meter\c$\UNC\long\small.txt SUCCESS CreationTime:
6/25/2008 12:36:43 PM, LastAccessTime: 6/26/2008 3:47:14 PM,
LastWriteTime: 4/22/2004 2:37:32 PM, ChangeTime: 6/25/2008 12:36:43 PM,
FileAttributes: A

35713 .2730955 AM cmd.exe QueryStreamInformationFile
\meter\c$\UNC\long\small.txt SUCCESS 0: ::$DATA

35714 .2735721 AM cmd.exe QueryBasicInformationFile
\meter\c$\UNC\long\small.txt SUCCESS CreationTime:
6/25/2008 12:36:43 PM, LastAccessTime: 6/26/2008 3:47:14 PM,
LastWriteTime: 4/22/2004 2:37:32 PM, ChangeTime: 6/25/2008 12:36:43 PM,
FileAttributes: A

35715 .2740685 AM cmd.exe QueryEaInformationFile
\meter\c$\UNC\long\small.txt SUCCESS EaSize: 0

35716 .2749538 AM cmd.exe CreateFile
C:\Windows\CSC\v2.0.6\namespace\meter NAME NOT FOUND
Desired Access: Read EA, Write EA, Read Attributes, Write Attributes,
Delete, Read Control, Synchronize, Disposition: Open, Options:
Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: n/a

35717 .2769315 AM cmd.exe CreateFile
\meter\c$\UNC\long\long12.txt SUCCESS Desired Access:
Generic Write, Read Data/List Directory, Read Attributes, Delete,
Disposition: OverwriteIf, Options: Sequential Access, Non-Directory
File, Attributes: A, ShareMode: None, AllocationSize: 5,562, OpenResult:
Created

35718 .2775234 AM cmd.exe CreateFile
C:\Windows\CSC\v2.0.6\namespace\meter NAME NOT FOUND
Desired Access: Read EA, Write EA, Read Attributes, Write Attributes,
Delete, Read Control, Synchronize, Disposition: Open, Options:
Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: n/a

35719 "

35720 "

35721 "

35722 .2818812 AM cmd.exe QueryStandardInformationFile
\meter\c$\UNC\long\long12.txt SUCCESS AllocationSize:
0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory:
False

35723 .2846266 AM cmd.exe QueryDeviceInformationVolume
\meter\c$\UNC\long\long12.txt SUCCESS DeviceType:
Disk, Characteristics: Remote

35724 .2848204 AM cmd.exe FileSystemControl
\meter\c$\UNC\long\long12.txt SUCCESS Control:
IOCTL_LMR_DISABLE_LOCAL_BUFFERING

35725 .2849529 AM cmd.exe QueryAttributeInformationVolume
\meter\c$\UNC\long\long12.txt SUCCESS FileSystemAttributes:
Case Preserved, Case Sensitive, Unicode, ACLs, Compression, Named
Streams, EFS, Object IDs, Reparse Points, Sparse Files, Quotas,
MaximumComponentNameLength: 255, FileSystemName: NTFS

35726 .2882033 AM cmd.exe QueryBasicInformationFile
\meter\c$\UNC\long\long12.txt SUCCESS CreationTime:
6/27/2008 10:11:08 AM, LastAccessTime: 6/27/2008 10:11:08 AM,
LastWriteTime: 6/27/2008 10:11:08 AM, ChangeTime: 6/27/2008 10:11:08 AM,
FileAttributes: A

35727 .2883307 AM cmd.exe QueryAttributeInformationVolume
\meter\c$\UNC\long\small.txt SUCCESS
FileSystemAttributes: Case Preserved, Case Sensitive, Unicode, ACLs,
Compression, Named Streams, EFS, Object IDs, Reparse Points, Sparse
Files, Quotas, MaximumComponentNameLength: 255, FileSystemName: NTFS

35728 .2892258 AM cmd.exe QueryDeviceInformationVolume
\meter\c$\UNC\long\small.txt SUCCESS DeviceType:
Disk, Characteristics: Remote

35729 .2893230 AM cmd.exe QueryDeviceInformationVolume
\meter\c$\UNC\long\long12.txt SUCCESS DeviceType:
Disk, Characteristics: Remote

35730 .2895808 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\small.txt FAST IO DISALLOWED Control: 0x140410
(Device:0x14 Function:260 Method: 0)

35731 .2896297 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\small.txt BUFFER OVERFLOW Control: 0x140410
(Device:0x14 Function:260 Method: 0)

35732 .2897727 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\long12.txt FAST IO DISALLOWED Control: 0x140410
(Device:0x14 Function:260 Method: 0)

35733 .2898158 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\long12.txt BUFFER OVERFLOW Control: 0x140410
(Device:0x14 Function:260 Method: 0)

35734 .2900066 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\small.txt FAST IO DISALLOWED Control: 0x140410
(Device:0x14 Function:260 Method: 0)

35735 .2900530 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\small.txt SUCCESS Control: 0x140410
(Device:0x14 Function:260 Method: 0)

35736 .2901421 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\long12.txt FAST IO DISALLOWED Control: 0x140410
(Device:0x14 Function:260 Method: 0)

35737 .2901843 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\long12.txt SUCCESS Control: 0x140410
(Device:0x14 Function:260 Method: 0)

35738 .2902706 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\small.txt FAST IO DISALLOWED Control: 0x140414
(Device:0x14 Function:261 Method: 0)

35739 .2903125 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\small.txt SUCCESS Control: 0x140414
(Device:0x14 Function:261 Method: 0)

35740 .2908832 AM System 4 Thread Create
SUCCESS Thread ID: 396

35741 .2913115 AM cmd.exe QueryBasicInformationFile
\meter\c$\UNC\long\long12.txt SUCCESS CreationTime:
6/27/2008 10:11:08 AM, LastAccessTime: 6/27/2008 10:11:08 AM,
LastWriteTime: 6/27/2008 10:11:08 AM, ChangeTime: 6/27/2008 10:11:08 AM,
FileAttributes: A

35742 .2914266 AM cmd.exe SetEndOfFileInformationFile
\meter\c$\UNC\long\long12.txt SUCCESS EndOfFile:
5,562

35743 .2916730 AM System 4 Thread Create
SUCCESS Thread ID: 2164

35752 .3040961 AM cmd.exe QueryDeviceInformationVolume
\meter\c$\UNC\long\small.txt SUCCESS DeviceType:
Disk, Characteristics: Remote

35753 .3042587 AM cmd.exe FileSystemControl
\meter\c$\UNC\long\small.txt SUCCESS Control:
FSCTL_LMR_QUERY_DEBUG_INFO

35754 .3043872 AM cmd.exe RegOpenKey
HKLM\Software\Policies\Microsoft\Windows\System SUCCESS
Desired Access: Query Value

35755 .3044615 AM cmd.exe RegQueryValue
HKLM\SOFTWARE\Policies\Microsoft\Windows\System\CopyFileChunkSize
NAME NOT FOUND Length: 20

35756 .3045056 AM cmd.exe RegQueryValue
HKLM\SOFTWARE\Policies\Microsoft\Windows\System\CopyFileOverlappedCount
NAME NOT FOUND Length: 20

35757 .3045534 AM cmd.exe RegCloseKey
HKLM\SOFTWARE\Policies\Microsoft\Windows\System SUCCESS

35758 .3051979 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\long12.txt FAST IO DISALLOWED Control: 0x144418
(Device:0x14 Function:262 Method: 0)

35759 .3052448 AM cmd.exe DeviceIoControl
\meter\c$\UNC\long\long12.txt SUCCESS Control: 0x144418
(Device:0x14 Function:262 Method: 0)

35760 .3081097 AM System Thread Exit SUCCESS
User Time: 0.0000000, Kernel Time: 0.0000000

35761 .3155526 AM cmd.exe SetBasicInformationFile
\meter\c$\UNC\long\long12.txt SUCCESS CreationTime: 0,
LastAccessTime: 0, LastWriteTime: 4/22/2004 2:37:32 PM, ChangeTime:
6/25/2008 12:36:43 PM, FileAttributes: n/a

35762 .3158909 AM System Thread Exit SUCCESS
User Time: 0.0000000, Kernel Time: 0.0000000

35763 .3164608 AM cmd.exe CloseFile
\meter\c$\UNC\long\small.txt SUCCESS

35765 .3176241 AM cmd.exe CloseFile
\meter\c$\UNC\long\long12.txt SUCCESS

2

Interesting! It looks like CopyFileEx() handles case when remote source and destination file lays on the same server and it does copy remotely. It sends several IOCTL commands for source and/or destination file. IOCTL with function code 262 is sent only to destination file, so I think it is REMOTE_COPY command.

Undocumented IOCTL commands are following:

CTL_CODE(FILE_DEVICE_NETWORK_FILE_SYSTEM, 260, METHOD_NEITHER, FILE_READ_ACCESS)
CTL_CODE(FILE_DEVICE_NETWORK_FILE_SYSTEM, 261, METHOD_NEITHER, FILE_READ_ACCESS)
CTL_CODE(FILE_DEVICE_NETWORK_FILE_SYSTEM, 262, METHOD_NEITHER, FILE_READ_ACCESS)

stack proves that they are sent from CopyFile API:
0 fltmgr.sys FltpPerformPreCallbacks + 0x2e5
1 fltmgr.sys FltpPassThroughInternal + 0x32
2 fltmgr.sys FltpPassThrough + 0x199
3 fltmgr.sys FltpDispatch + 0xb1
4 ntkrnlpa.exe IovCallDriver + 0x252
5 ntkrnlpa.exe IofCallDriver + 0x1b
6 ntkrnlpa.exe IopSynchronousServiceTail + 0x1e0
7 ntkrnlpa.exe IopXxxControlFile + 0x6b7
8 ntkrnlpa.exe NtDeviceIoControlFile + 0x2a
9 ntkrnlpa.exe KiFastCallEntry + 0x12a
10 ntdll.dll ZwDeviceIoControlFile + 0xc
11 kernel32.dll DeviceIoControl + 0xd2
12 kernel32.dll BaseCopyStream + 0x1cf9
13 kernel32.dll BasepCopyFileExW + 0x740
14 kernel32.dll CopyFileExW + 0x4a
15 cmd.exe do_normal_copy + 0x7fe
16 cmd.exe copy + 0xb2
17 cmd.exe eCopy + 0x10
18 cmd.exe FindFixAndRun + 0x1de
19 cmd.exe Dispatch + 0x14a
20 cmd.exe main + 0x21a

There is a good article about an effort which was done to improve CopyFile API performance in Mark’s blog, but this case is not covered. Here is link:
http://blogs.technet.com/markrussinovich/archive/2008/02/04/2826167.aspx

-bg