Index: src/libchcore/TLocalFilesystem.cpp
===================================================================
diff -u -N -r8a2ff3b2b71b45fb525e030167e62f316cb32869 -rf8fcbbd1d2321cf0c8be79526c449384af654e49
--- src/libchcore/TLocalFilesystem.cpp	(.../TLocalFilesystem.cpp)	(revision 8a2ff3b2b71b45fb525e030167e62f316cb32869)
+++ src/libchcore/TLocalFilesystem.cpp	(.../TLocalFilesystem.cpp)	(revision f8fcbbd1d2321cf0c8be79526c449384af654e49)
@@ -26,30 +26,22 @@
 #include <boost/numeric/conversion/cast.hpp>
 #include "TAutoHandles.h"
 #include "TFileInfo.h"
-// disable "warning C4201: nonstandard extension used : nameless struct/union"
-// for standard VS2008 with SDK 6.0A where winioctl.h generates some warnings
-// converted to errors by the project settings.
-#pragma warning(push)
-#pragma warning(disable: 4201)
 #include <winioctl.h>
-#pragma warning(pop)
 #include "TCoreException.h"
 #include "ErrorCodes.h"
 #include "TPathContainer.h"
 #include "TFileTime.h"
-#include "TOverlappedDataBuffer.h"
-#include "RoundingFunctions.h"
-#include "TBufferSizes.h"
 #include "TLocalFilesystemFile.h"
 #include <memory>
 #include "TLocalFilesystemFind.h"
 #include "TFileException.h"
-#include "TDateTime.h"
 #include <boost/thread/locks.hpp>
+#include "StreamingHelpers.h"
 
 namespace chcore
 {
-	TLocalFilesystem::TLocalFilesystem()
+	TLocalFilesystem::TLocalFilesystem(const logger::TLogFileDataPtr& spLogFileData) :
+		m_spLog(logger::MakeLogger(spLogFileData, L"Filesystem"))
 	{
 	}
 
@@ -92,49 +84,83 @@
 			findPath.AppendIfNotExists(_T("*"), false);
 		}
 
-		HANDLE hFind = FindFirstFile(PrependPathExtensionIfNeeded(findPath).ToString(), &fd);
+		findPath = PrependPathExtensionIfNeeded(findPath);
+
+		LOG_DEBUG(m_spLog) << L"Checking for path existence: " << pathToCheck << L" (using search pattern: " << findPath << L")";
+
+		HANDLE hFind = FindFirstFile(findPath.ToString(), &fd);
 		if (hFind != INVALID_HANDLE_VALUE)
 		{
 			::FindClose(hFind);
+			LOG_DEBUG(m_spLog) << L"Path: " << pathToCheck << L" exists";
 			return true;
 		}
-		else
-			return false;
+
+		LOG_DEBUG(m_spLog) << L"Path: " << pathToCheck << L" does not exist";
+		return false;
 	}
 
 	void TLocalFilesystem::SetFileDirectoryTime(const TSmartPath& pathFileDir, const TFileTime& ftCreationTime, const TFileTime& ftLastAccessTime, const TFileTime& ftLastWriteTime)
 	{
-		TAutoFileHandle hFile = TAutoFileHandle(CreateFile(PrependPathExtensionIfNeeded(pathFileDir).ToString(), GENERIC_READ | GENERIC_WRITE, FILE_SHARE_READ, nullptr, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL | FILE_FLAG_BACKUP_SEMANTICS, nullptr));
+		TSmartPath fullPath = PrependPathExtensionIfNeeded(pathFileDir);
+
+		LOG_TRACE(m_spLog) << L"Setting file/directory times for " << fullPath <<
+			L", creation-time: " << ftCreationTime.GetAsFiletime() <<
+			L", last-access-time: " << ftLastAccessTime.GetAsFiletime() <<
+			L", last-write-time: " << ftLastWriteTime.GetAsFiletime();
+
+		TAutoFileHandle hFile = TAutoFileHandle(CreateFile(fullPath.ToString(), GENERIC_READ | GENERIC_WRITE, FILE_SHARE_READ, nullptr, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL | FILE_FLAG_BACKUP_SEMANTICS, nullptr));
 		if (hFile == INVALID_HANDLE_VALUE)
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Open file failed with error: " << dwLastError << L". Cannot set file/directory times.";
+
 			throw TFileException(eErr_CannotOpenFile, dwLastError, pathFileDir, L"Cannot open file for setting file/directory times", LOCATION);
 		}
 
 		if (!SetFileTime(hFile, &ftCreationTime.GetAsFiletime(), &ftLastAccessTime.GetAsFiletime(), &ftLastWriteTime.GetAsFiletime()))
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Failed to set file/directory times. Error: " << dwLastError;
 			throw TFileException(eErr_CannotSetFileTimes, dwLastError, pathFileDir, L"Cannot set file/directory times", LOCATION);
 		}
+		LOG_TRACE(m_spLog) << L"File/directory times set successfully";
 	}
 
 	void TLocalFilesystem::SetAttributes(const TSmartPath& pathFileDir, DWORD dwAttributes)
 	{
-		if (!::SetFileAttributes(PrependPathExtensionIfNeeded(pathFileDir).ToString(), dwAttributes))
+		TSmartPath fullPath = PrependPathExtensionIfNeeded(pathFileDir);
+
+		LOG_TRACE(m_spLog) << L"Setting file/directory attributes for " << fullPath <<
+			L", attributes: " << dwAttributes;
+
+		if (!::SetFileAttributes(fullPath.ToString(), dwAttributes))
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Failed to set file/directory attributes. Error: " << dwLastError;
 			throw TFileException(eErr_CannotSetFileAttributes, dwLastError, pathFileDir, L"Cannot set file/directory attributes", LOCATION);
 		}
+		LOG_TRACE(m_spLog) << L"File/directory attributes set successfully";
 	}
 
 	void TLocalFilesystem::CreateDirectory(const TSmartPath& pathDirectory, bool bCreateFullPath)
 	{
+		LOG_DEBUG(m_spLog) << L"Creating directory " << pathDirectory <<
+			L", create-full-path: " << bCreateFullPath;
+
 		if (!bCreateFullPath)
 		{
 			if (!::CreateDirectory(PrependPathExtensionIfNeeded(pathDirectory).ToString(), nullptr))
 			{
 				DWORD dwLastError = GetLastError();
-				throw TFileException(eErr_CannotCreateDirectory, dwLastError, pathDirectory, L"Cannot create directory", LOCATION);
+				if(dwLastError != ERROR_ALREADY_EXISTS)
+				{
+					LOG_ERROR(m_spLog) << L"Creating directory " << pathDirectory << L" failed with error " << dwLastError;
+					throw TFileException(eErr_CannotCreateDirectory, dwLastError, pathDirectory, L"Cannot create directory", LOCATION);
+				}
+				
+				LOG_DEBUG(m_spLog) << L"Directory " << pathDirectory << L" already exists, nothing to do";
+				return;
 			}
 		}
 		else
@@ -146,47 +172,71 @@
 			for (size_t stIndex = 0; stIndex < vComponents.GetCount(); ++stIndex)
 			{
 				const TSmartPath& pathComponent = vComponents.GetAt(stIndex);
-
 				pathToTest += pathComponent;
+
+				LOG_DEBUG(m_spLog) << L"Creating " << pathDirectory << L" - partial path: " << pathToTest;
+
 				// try to create subsequent paths
-				if (!pathToTest.IsDrive() && !pathToTest.IsServerName())
+				if(!pathToTest.IsDrive() && !pathToTest.IsServerName())
 				{
 					// try to create the specified path
 					BOOL bRes = ::CreateDirectory(PrependPathExtensionIfNeeded(pathToTest).ToString(), nullptr);
-					if (!bRes)
+					if(!bRes)
 					{
 						DWORD dwLastError = GetLastError();
-						if (dwLastError != ERROR_ALREADY_EXISTS)
+						if(dwLastError != ERROR_ALREADY_EXISTS)
+						{
+							LOG_ERROR(m_spLog) << L"Creating directory " << pathToTest << L" failed with error " << dwLastError;
 							throw TFileException(eErr_CannotCreateDirectory, dwLastError, pathToTest, L"Cannot create directory", LOCATION);
+						}
 					}
 				}
+				else
+					LOG_DEBUG(m_spLog) << L"Skipping drive/server part of a path when creating directory " << pathToTest;
 			}
 		}
+
+		LOG_DEBUG(m_spLog) << L"Directory " << pathDirectory << L" created successfully";
 	}
 
 	void TLocalFilesystem::RemoveDirectory(const TSmartPath& pathDirectory)
 	{
-		if (!::RemoveDirectory(PrependPathExtensionIfNeeded(pathDirectory).ToString()))
+		TSmartPath fullPath = PrependPathExtensionIfNeeded(pathDirectory);
+		LOG_DEBUG(m_spLog) << L"Removing directory " << fullPath;
+
+		if (!::RemoveDirectory(fullPath.ToString()))
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Failed to remove directory " << fullPath << L". Error: " << dwLastError;
 			throw TFileException(eErr_CannotRemoveDirectory, dwLastError, pathDirectory, L"Cannot delete directory", LOCATION);
 		}
+
+		LOG_DEBUG(m_spLog) << L"Directory " << fullPath << L" removed successfully";
 	}
 
 	void TLocalFilesystem::DeleteFile(const TSmartPath& pathFile)
 	{
-		if (!::DeleteFile(PrependPathExtensionIfNeeded(pathFile).ToString()))
+		TSmartPath fullPath = PrependPathExtensionIfNeeded(pathFile);
+		LOG_DEBUG(m_spLog) << L"Removing file " << fullPath;
+
+		if (!::DeleteFile(fullPath.ToString()))
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Failed to remove file " << fullPath << L". Error: " << dwLastError;
 			throw TFileException(eErr_CannotDeleteFile, dwLastError, pathFile, L"Cannot delete file", LOCATION);
 		}
+
+		LOG_DEBUG(m_spLog) << L"File " << fullPath << L" removed successfully";
 	}
 
 	void TLocalFilesystem::GetFileInfo(const TSmartPath& pathFile, TFileInfoPtr& spFileInfo, const TBasePathDataPtr& spBasePathData)
 	{
 		if (!spFileInfo)
 			throw TCoreException(eErr_InvalidArgument, L"spFileInfo", LOCATION);
 
+		LOG_DEBUG(m_spLog) << L"Retrieving file information for " << pathFile <<
+			L" with base path data: " << TSmartPath(spBasePathData ? spBasePathData->GetSrcPath() : TSmartPath());
+
 		WIN32_FIND_DATA wfd;
 
 		TSmartPath findPath = pathFile;
@@ -198,6 +248,8 @@
 			findPath.AppendIfNotExists(_T("*"), false);
 		}
 
+		LOG_DEBUG(m_spLog) << L"Retrieving file information for " << pathFile << L". Using search pattern: " << findPath;
+
 		HANDLE hFind = FindFirstFileEx(PrependPathExtensionIfNeeded(findPath).ToString(), FindExInfoStandard, &wfd, FindExSearchNameMatch, nullptr, 0);
 		if (hFind != INVALID_HANDLE_VALUE)
 		{
@@ -209,46 +261,69 @@
 				ftTime.SetCurrentTime();
 
 				spFileInfo->Init(spBasePathData, pathFile, FILE_ATTRIBUTE_DIRECTORY, 0, ftTime, ftTime, ftTime, 0);
+				LOG_DEBUG(m_spLog) << L"Retrieved information for drive - using current timestamp file information for " << pathFile;
 			}
 			else
 			{
 				// new instance of path to accommodate the corrected path (i.e. input path might have lower case names, but we'd like to
 				// preserve the original case contained in the file system)
 				TSmartPath pathNew(pathFile);
 				pathNew.DeleteFileName();
+				pathNew += PathFromString(wfd.cFileName);
 
+				unsigned long long ullFullSize = (((unsigned long long)wfd.nFileSizeHigh) << 32) + wfd.nFileSizeLow;
+
 				// copy data from W32_F_D
-				spFileInfo->Init(spBasePathData, pathNew + PathFromString(wfd.cFileName),
-					wfd.dwFileAttributes, (((ULONGLONG)wfd.nFileSizeHigh) << 32) + wfd.nFileSizeLow, wfd.ftCreationTime,
+				spFileInfo->Init(spBasePathData, pathNew,
+					wfd.dwFileAttributes, ullFullSize, wfd.ftCreationTime,
 					wfd.ftLastAccessTime, wfd.ftLastWriteTime, 0);
+
+				LOG_DEBUG(m_spLog) << L"Retrieved information for file/directory " << pathFile <<
+					L", full-path: " << pathNew <<
+					L", attributes: " << wfd.dwFileAttributes <<
+					L", size: " << ullFullSize <<
+					L", creation-time: " << wfd.ftCreationTime <<
+					L", last-access-time: " << wfd.ftLastAccessTime <<
+					L", last-write-time: " << wfd.ftLastWriteTime;
 			}
 		}
 		else
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Failed to retrieve file information for " << pathFile << L". Error: " << dwLastError;
 			throw TFileException(eErr_CannotGetFileInfo, dwLastError, pathFile, L"Cannot retrieve file information", LOCATION);
 		}
 	}
 
 	void TLocalFilesystem::FastMove(const TSmartPath& pathSource, const TSmartPath& pathDestination)
 	{
-		if (!::MoveFileEx(PrependPathExtensionIfNeeded(pathSource).ToString(), PrependPathExtensionIfNeeded(pathDestination).ToString(), 0))
+		TSmartPath pathMoveFrom = PrependPathExtensionIfNeeded(pathSource);
+		TSmartPath pathMoveTo = PrependPathExtensionIfNeeded(pathDestination);
+
+		LOG_DEBUG(m_spLog) << L"Trying to fast-move file " << pathMoveFrom << L" to " << pathMoveTo;
+
+		if (!::MoveFileEx(pathMoveFrom.ToString(), pathMoveTo.ToString(), 0))
 		{
 			DWORD dwLastError = GetLastError();
-			// there is also the destination path that is important; tracking that would require adding a new exception class
-			// complicating the solution. For now it's not necessary to have that information in the exception.
+
+			LOG_ERROR(m_spLog) << L"Failed to fast-move file " << pathMoveFrom << L" to " << pathMoveTo << L". Error: " << dwLastError;
 			throw TFileException(eErr_CannotFastMove, dwLastError, pathSource, L"Cannot fast move file/directory", LOCATION);
 		}
+
+		LOG_DEBUG(m_spLog) << L"Successfully fast-moved file " << pathMoveFrom << L" to " << pathMoveTo;
 	}
 
 	IFilesystemFindPtr TLocalFilesystem::CreateFinderObject(const TSmartPath& pathDir, const TSmartPath& pathMask)
 	{
-		return std::shared_ptr<TLocalFilesystemFind>(new TLocalFilesystemFind(pathDir, pathMask));
+		LOG_TRACE(m_spLog) << L"Creating file finder object for path " << pathDir << L" with mask " << pathMask;
+
+		return std::shared_ptr<TLocalFilesystemFind>(new TLocalFilesystemFind(pathDir, pathMask, m_spLog->GetLogFileData()));
 	}
 
 	IFilesystemFilePtr TLocalFilesystem::CreateFileObject(const TSmartPath& pathFile, bool bNoBuffering)
 	{
-		return std::shared_ptr<TLocalFilesystemFile>(new TLocalFilesystemFile(pathFile, bNoBuffering));
+		LOG_TRACE(m_spLog) << L"Creating file object for path " << pathFile << L" with no-buffering set to " << bNoBuffering;
+		return std::shared_ptr<TLocalFilesystemFile>(new TLocalFilesystemFile(pathFile, bNoBuffering, m_spLog->GetLogFileData()));
 	}
 
 	TSmartPath TLocalFilesystem::PrependPathExtensionIfNeeded(const TSmartPath& pathInput)
@@ -268,12 +343,13 @@
 		if(pathSecond.IsEmpty())
 			throw TCoreException(eErr_InvalidArgument, L"pathSecond", LOCATION);
 
+		LOG_DEBUG(m_spLog) << L"Trying to find relation between paths: " << pathFirst << L" and " << pathSecond;
+
 		// get information about both paths
-		UINT uiFirstDriveType = 0;
-		uiFirstDriveType = GetDriveData(pathFirst);
+		UINT uiFirstDriveType = GetDriveData(pathFirst);
+		UINT uiSecondDriveType = GetDriveData(pathSecond);
 
-		UINT uiSecondDriveType = 0;
-		uiSecondDriveType = GetDriveData(pathSecond);
+		LOG_TRACE(m_spLog) << L"Drive type for " << pathFirst << L" is " << uiFirstDriveType << L", drive type for " << pathSecond << L" is " << uiSecondDriveType;
 
 		// what kind of relation...
 		EPathsRelation eRelation = eRelation_Other;
@@ -296,6 +372,9 @@
 			{
 				DWORD dwFirstPhysicalDisk = GetPhysicalDiskNumber(wchFirstDrive);
 				DWORD dwSecondPhysicalDisk = GetPhysicalDiskNumber(wchSecondDrive);
+
+				LOG_TRACE(m_spLog) << L"Physical disk for " << pathFirst << L" is " << dwFirstPhysicalDisk << L", physical disk for " << pathSecond << L" is " << dwSecondPhysicalDisk;
+
 				if (dwFirstPhysicalDisk == std::numeric_limits<DWORD>::max() || dwSecondPhysicalDisk == std::numeric_limits<DWORD>::max())
 				{
 					// NOTE: disabled throwing an exception here - when testing, it came out that some DRIVE_FIXED
@@ -311,35 +390,53 @@
 			}
 		}
 
+		LOG_DEBUG(m_spLog) << L"Drive relation for " << pathFirst << L" and " << pathSecond << L" is " << eRelation;
+
 		return eRelation;
 	}
 
 	DWORD TLocalFilesystem::GetPhysicalDiskNumber(wchar_t wchDrive)
 	{
+		LOG_TRACE(m_spLog) << L"Checking physical disk number for drive " << wchDrive;
+
 		{
 			boost::shared_lock<boost::shared_mutex> lock(m_lockDriveLetterToPhysicalDisk);
 
 			std::map<wchar_t, DWORD>::iterator iterMap = m_mapDriveLetterToPhysicalDisk.find(wchDrive);
 			if (iterMap != m_mapDriveLetterToPhysicalDisk.end())
+			{
+				LOG_TRACE(m_spLog) << L"Physical disk number for drive " << wchDrive << L" is " << (*iterMap).second << L" (cached)";
 				return (*iterMap).second;
+			}
 		}
 
 		wchar_t szDrive[] = { L'\\', L'\\', L'.', L'\\', wchDrive, L':', L'\0' };
 
+		LOG_DEBUG(m_spLog) << L"Creating handle for drive " << szDrive;
+
 		HANDLE hDevice = CreateFile(szDrive, FILE_READ_ATTRIBUTES, FILE_SHARE_READ | FILE_SHARE_WRITE, nullptr, OPEN_EXISTING, 0, nullptr);
 		if (hDevice == INVALID_HANDLE_VALUE)
+		{
+			DWORD dwLastError = GetLastError();
+			LOG_DEBUG(m_spLog) << L"Failed to create handle for drive " << szDrive << L". Error: " << dwLastError;
 			return std::numeric_limits<DWORD>::max();
+		}
 
 		// buffer for data (cannot make member nor static because this function might be called by many threads at once)
 		// buffer is larger than one extent to allow getting information in multi-extent volumes (raid?)
 		const int stSize = sizeof(VOLUME_DISK_EXTENTS) + 20 * sizeof(DISK_EXTENT);
 		boost::shared_array<BYTE> spData(new BYTE[stSize]);
 
+		LOG_DEBUG(m_spLog) << L"Retrieving volume disk extents for drive " << szDrive;
+
 		VOLUME_DISK_EXTENTS* pVolumeDiskExtents = (VOLUME_DISK_EXTENTS*)spData.get();
 		DWORD dwBytesReturned = 0;
 		BOOL bResult = DeviceIoControl(hDevice, IOCTL_VOLUME_GET_VOLUME_DISK_EXTENTS, nullptr, 0, pVolumeDiskExtents, stSize, &dwBytesReturned, nullptr);
 		if (!bResult)
 		{
+			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Failed to retrieve volume disk extents for drive " << szDrive << L". Error: " << dwLastError;
+
 			CloseHandle(hDevice);
 
 			// NOTE: when ERROR_INVALID_FUNCTION is reported here, it probably means that underlying volume
@@ -350,10 +447,15 @@
 		CloseHandle(hDevice);
 
 		if (pVolumeDiskExtents->NumberOfDiskExtents == 0)
+		{
+			LOG_DEBUG(m_spLog) << L"No disk extents available for drive " << szDrive;
 			return std::numeric_limits<DWORD>::max();
+		}
 
 		DISK_EXTENT* pDiskExtent = &pVolumeDiskExtents->Extents[0];
 
+		LOG_DEBUG(m_spLog) << L"Retrieved disk number for drive " << szDrive << L": " << pDiskExtent->DiskNumber;
+
 		boost::unique_lock<boost::shared_mutex> lock(m_lockDriveLetterToPhysicalDisk);
 		m_mapDriveLetterToPhysicalDisk.insert(std::make_pair(wchDrive, pDiskExtent->DiskNumber));
 
@@ -362,14 +464,20 @@
 
 	void TLocalFilesystem::GetDynamicFreeSpace(const TSmartPath& path, unsigned long long& rullFree)
 	{
+		LOG_DEBUG(m_spLog) << L"Retrieving free space for path " << path;
+
 		rullFree = 0;
 
 		ULARGE_INTEGER ui64Available, ui64Total;
 		if (GetDiskFreeSpaceEx(path.ToString(), &ui64Available, &ui64Total, nullptr))
+		{
 			rullFree = ui64Available.QuadPart;
+			LOG_DEBUG(m_spLog) << L"Free space for path " << path << L" is " << rullFree;
+		}
 		else
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Failed to retrieve free space for path " << path << L". Error: " << dwLastError;
 			throw TFileException(eErr_CannotGetFreeSpace, dwLastError, path, L"Failed to retrieve free space information", LOCATION);
 		}
 	}