Index: src/libchcore/TLocalFilesystemFile.cpp
===================================================================
diff -u -N -r8068e0c351055554340ac9755d1bc846893bf2b8 -rf8fcbbd1d2321cf0c8be79526c449384af654e49
--- src/libchcore/TLocalFilesystemFile.cpp	(.../TLocalFilesystemFile.cpp)	(revision 8068e0c351055554340ac9755d1bc846893bf2b8)
+++ src/libchcore/TLocalFilesystemFile.cpp	(.../TLocalFilesystemFile.cpp)	(revision f8fcbbd1d2321cf0c8be79526c449384af654e49)
@@ -28,16 +28,18 @@
 #include "TCoreWin32Exception.h"
 #include "TFileException.h"
 #include "TFileInfo.h"
+#include "StreamingHelpers.h"
 
 namespace chcore
 {
 	// compile-time check - ensure the buffer granularity used for transfers are bigger than expected sector size
 	static_assert(TLocalFilesystemFile::MaxSectorSize <= TBufferSizes::BufferGranularity, "Buffer granularity must be equal to or bigger than the max sector size");
 
-	TLocalFilesystemFile::TLocalFilesystemFile(const TSmartPath& pathFile, bool bNoBuffering) :
+	TLocalFilesystemFile::TLocalFilesystemFile(const TSmartPath& pathFile, bool bNoBuffering, const logger::TLogFileDataPtr& spLogFileData) :
 		m_pathFile(TLocalFilesystem::PrependPathExtensionIfNeeded(pathFile)),
 		m_hFile(INVALID_HANDLE_VALUE),
-		m_bNoBuffering(bNoBuffering)
+		m_bNoBuffering(bNoBuffering),
+		m_spLog(logger::MakeLogger(spLogFileData, L"Filesystem-File"))
 	{
 		if (pathFile.IsEmpty())
 			throw TCoreException(eErr_InvalidArgument, L"pathFile", LOCATION);
@@ -63,24 +65,34 @@
 	{
 		Close();
 
+		LOG_DEBUG(m_spLog) << L"Opening existing file for reading" << GetFileInfoForLog(m_bNoBuffering);
+
 		m_hFile = ::CreateFile(m_pathFile.ToString(), GENERIC_READ, FILE_SHARE_READ | FILE_SHARE_WRITE, nullptr, OPEN_EXISTING, GetFlagsAndAttributes(m_bNoBuffering), nullptr);
 		if (m_hFile == INVALID_HANDLE_VALUE)
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << "Opening file for reading failed with error: " << dwLastError << GetFileInfoForLog(m_bNoBuffering);
+
 			throw TFileException(eErr_CannotOpenFile, dwLastError, m_pathFile, L"Cannot open for reading", LOCATION);
 		}
+
+		LOG_DEBUG(m_spLog) << "Opening file for reading succeeded. New handle: " << m_hFile << GetFileInfoForLog(m_bNoBuffering);
 	}
 
 	void TLocalFilesystemFile::CreateNewForWriting()
 	{
 		Close();
 
+		LOG_DEBUG(m_spLog) << "Creating new file for writing" << GetFileInfoForLog(m_bNoBuffering);
+
 		m_hFile = ::CreateFile(m_pathFile.ToString(), GENERIC_WRITE, FILE_SHARE_READ, nullptr, CREATE_NEW, GetFlagsAndAttributes(m_bNoBuffering), nullptr);
 		if (m_hFile == INVALID_HANDLE_VALUE)
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << "CreateNewForWriting failed with error: " << dwLastError << GetFileInfoForLog(m_bNoBuffering);
 			throw TFileException(eErr_CannotOpenFile, dwLastError, m_pathFile, L"Cannot create file.", LOCATION);
 		}
+		LOG_DEBUG(m_spLog) << "CreateNewForWriting succeeded. New handle: " << m_hFile << GetFileInfoForLog(m_bNoBuffering);
 	}
 
 	void TLocalFilesystemFile::OpenExistingForWriting()
@@ -92,24 +104,36 @@
 	{
 		Close();
 
+		LOG_DEBUG(m_spLog) << "OpenExistingForWriting" << GetFileInfoForLog(bNoBuffering);
+
 		m_hFile = CreateFile(m_pathFile.ToString(), GENERIC_WRITE, FILE_SHARE_READ, nullptr, OPEN_EXISTING, GetFlagsAndAttributes(bNoBuffering), nullptr);
 		if (m_hFile == INVALID_HANDLE_VALUE)
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << "OpenExistingForWriting failed with error: " << dwLastError << GetFileInfoForLog(bNoBuffering);
+
 			throw TFileException(eErr_CannotOpenFile, dwLastError, m_pathFile, L"Cannot open for reading.", LOCATION);
 		}
+		LOG_DEBUG(m_spLog) << "OpenExistingForWriting succeeded. New handle: " << m_hFile << GetFileInfoForLog(bNoBuffering);
 	}
 
 	file_size_t TLocalFilesystemFile::GetSeekPositionForResume(file_size_t fsLastAvailablePosition)
 	{
 		file_size_t fsMove = (m_bNoBuffering ? RoundDown<file_size_t>(fsLastAvailablePosition, MaxSectorSize) : fsLastAvailablePosition);
+		LOG_DEBUG(m_spLog) << "Calculated seek position for last-available-pos: " << fsLastAvailablePosition << L" = " << fsMove << GetFileInfoForLog(m_bNoBuffering);
+
 		return fsMove;
 	}
 
 	void TLocalFilesystemFile::Truncate(file_size_t fsNewSize)
 	{
+		LOG_TRACE(m_spLog) << "Truncating file to: " << fsNewSize << GetFileInfoForLog(m_bNoBuffering);
+
 		if (!IsOpen())
+		{
+			LOG_ERROR(m_spLog) << L"Cannot truncate - file not open" << GetFileInfoForLog(m_bNoBuffering);
 			throw TFileException(eErr_FileNotOpen, ERROR_INVALID_HANDLE, m_pathFile, L"File not open yet. Cannot truncate.", LOCATION);
+		}
 
 		// when no-buffering is used, there are cases where we'd need to switch to buffered ops
 		// to adjust file size
@@ -119,6 +143,8 @@
 			file_size_t fsNewAlignedSize = RoundUp<file_size_t>(fsNewSize, MaxSectorSize);
 			if (fsNewAlignedSize != fsNewSize)
 			{
+				LOG_TRACE(m_spLog) << "Truncating to non-aligned size. Requested: " << fsNewSize << L", aligned: " << fsNewAlignedSize << L". Will reopen file in buffering mode." << GetFileInfoForLog(m_bNoBuffering);
+
 				Close();
 				OpenExistingForWriting(false);
 
@@ -131,39 +157,58 @@
 
 		li.QuadPart = fsNewSize;
 
+		LOG_TRACE(m_spLog) << L"Setting file pointer to: " << li.QuadPart << GetFileInfoForLog(m_bNoBuffering);
 		if (!SetFilePointerEx(m_hFile, li, &liNew, FILE_BEGIN))
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Setting file pointer to: " << li.QuadPart << L" failed." << GetFileInfoForLog(m_bNoBuffering);
+
 			throw TFileException(eErr_SeekFailed, dwLastError, m_pathFile, L"Cannot seek to appropriate position", LOCATION);
 		}
 
+		LOG_TRACE(m_spLog) << L"Setting EOF" << GetFileInfoForLog(m_bNoBuffering);
 		if(!::SetEndOfFile(m_hFile))
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Setting EOF failed" << GetFileInfoForLog(m_bNoBuffering);
 			throw TFileException(eErr_CannotTruncate, dwLastError, m_pathFile, L"Cannot mark the end of file", LOCATION);
 		}
 
 		// close the file that was open in inappropriate mode
 		if(bFileSettingsChanged)
+		{
+			LOG_DEBUG(m_spLog) << L"Closing file due to mode change in truncate function" << GetFileInfoForLog(m_bNoBuffering);
+
 			Close();
+		}
 	}
 
 	void TLocalFilesystemFile::ReadFile(TOverlappedDataBuffer& rBuffer)
 	{
+		LOG_TRACE(m_spLog) << L"Requesting read of " << rBuffer.GetRequestedDataSize() <<
+			L" bytes at position " << rBuffer.GetFilePosition() <<
+			L"; buffer-order: " << rBuffer.GetBufferOrder() <<
+			GetFileInfoForLog(m_bNoBuffering);
+
 		if (!IsOpen())
+		{
+			LOG_ERROR(m_spLog) << L"Read request failed - file not open" << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
 			throw TFileException(eErr_FileNotOpen, ERROR_INVALID_HANDLE, m_pathFile, L"Cannot read from closed file", LOCATION);
+		}
 
-		//ATLTRACE(_T("Reading %lu bytes\n"), rBuffer.GetRequestedDataSize());
 		if (!::ReadFileEx(m_hFile, rBuffer.GetBufferPtr(), rBuffer.GetRequestedDataSize(), &rBuffer, OverlappedReadCompleted))
 		{
 			DWORD dwLastError = GetLastError();
 			switch (dwLastError)
 			{
 			case ERROR_IO_PENDING:
+				LOG_TRACE(m_spLog) << L"Read requested and is pending" << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
 				return;
 
 			case ERROR_HANDLE_EOF:
 				{
+					LOG_TRACE(m_spLog) << L"Read request marked as EOF" << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
+
 					rBuffer.SetBytesTransferred(0);
 					rBuffer.SetStatusCode(0);
 					rBuffer.SetErrorCode(ERROR_SUCCESS);
@@ -174,47 +219,80 @@
 				}
 
 			default:
-				throw TFileException(eErr_CannotReadFile, dwLastError, m_pathFile, L"Error reading data from file", LOCATION);
+				{
+					LOG_ERROR(m_spLog) << L"Read request failed with error " << dwLastError << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
+
+					throw TFileException(eErr_CannotReadFile, dwLastError, m_pathFile, L"Error reading data from file", LOCATION);
+				}
 			}
 		}
+		else
+			LOG_TRACE(m_spLog) << L"Read request succeeded" << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
 	}
 
 	void TLocalFilesystemFile::WriteFile(TOverlappedDataBuffer& rBuffer)
 	{
+		LOG_TRACE(m_spLog) << L"Requesting writing of " << rBuffer.GetRealDataSize() <<
+			L" bytes at position " << rBuffer.GetFilePosition() <<
+			L"; buffer-order: " << rBuffer.GetBufferOrder() <<
+			GetFileInfoForLog(m_bNoBuffering);
+
 		if (!IsOpen())
+		{
+			LOG_ERROR(m_spLog) << L"Write request failed - file not open" << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
 			throw TFileException(eErr_FileNotOpen, ERROR_INVALID_HANDLE, m_pathFile, L"Cannot write to closed file", LOCATION);
+		}
 
 		DWORD dwToWrite = boost::numeric_cast<DWORD>(rBuffer.GetRealDataSize());
 
 		if (m_bNoBuffering && rBuffer.IsLastPart())
+		{
 			dwToWrite = RoundUp<DWORD>(dwToWrite, MaxSectorSize);
+			LOG_TRACE(m_spLog) << L"Writing last part of file in no-buffering mode. Rounding up last write to " << dwToWrite << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
+		}
 
-		//ATLTRACE(_T("Writing %lu bytes\n"), dwToWrite);
 		if (!::WriteFileEx(m_hFile, rBuffer.GetBufferPtr(), dwToWrite, &rBuffer, OverlappedWriteCompleted))
 		{
 			DWORD dwLastError = GetLastError();
 			if (dwLastError != ERROR_IO_PENDING)
+			{
+				LOG_ERROR(m_spLog) << L"Write request failed with error " << dwLastError << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
 				throw TFileException(eErr_CannotWriteFile, dwLastError, m_pathFile, L"Error while writing to file", LOCATION);
+			}
+
+			LOG_TRACE(m_spLog) << L"Write requested and is pending" << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
 		}
+		else
+			LOG_TRACE(m_spLog) << L"Write request succeeded" << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
 	}
 
 	void TLocalFilesystemFile::FinalizeFile(TOverlappedDataBuffer& rBuffer)
 	{
+		LOG_TRACE(m_spLog) << L"Finalizing file" <<
+			L"; buffer-order: " << rBuffer.GetBufferOrder() <<
+			GetFileInfoForLog(m_bNoBuffering);
+
 		if (!IsOpen())
+		{
+			LOG_ERROR(m_spLog) << L"Cannot finalize file - file not open" << L"; buffer-order: " << rBuffer.GetBufferOrder() << GetFileInfoForLog(m_bNoBuffering);
 			throw TFileException(eErr_FileNotOpen, ERROR_INVALID_HANDLE, m_pathFile, L"Cannot write to closed file", LOCATION);
+		}
 
 		if (m_bNoBuffering && rBuffer.IsLastPart())
 		{
 			DWORD dwToWrite = boost::numeric_cast<DWORD>(rBuffer.GetRealDataSize());
 			DWORD dwReallyWritten = RoundUp<DWORD>(dwToWrite, MaxSectorSize);
 
-			//ATLTRACE(_T("Finalize file - size diff: written: %I64u, required: %I64u\n"), dwReallyWritten, dwToWrite);
 			if (dwToWrite != dwReallyWritten)
 			{
 				file_size_t fsNewFileSize = rBuffer.GetFilePosition() + dwToWrite;	// new size
 
-				//seek
-				//ATLTRACE(_T("Truncating file to %I64u bytes\n"), fsNewFileSize);
+				LOG_TRACE(m_spLog) << L"File need truncating - really written " << dwReallyWritten <<
+					L", should write " << dwToWrite <<
+					L". Truncating file to " << fsNewFileSize <<
+					L"; buffer-order: " << rBuffer.GetBufferOrder() <<
+					GetFileInfoForLog(m_bNoBuffering);
+
 				Truncate(fsNewFileSize);
 			}
 		}
@@ -223,42 +301,70 @@
 	void TLocalFilesystemFile::InternalClose()
 	{
 		if (m_hFile != INVALID_HANDLE_VALUE)
+		{
+			LOG_DEBUG(m_spLog) << L"Closing file" << GetFileInfoForLog(m_bNoBuffering);
 			::CloseHandle(m_hFile);
+		}
 		m_hFile = INVALID_HANDLE_VALUE;
 	}
 
+	std::wstring TLocalFilesystemFile::GetFileInfoForLog(bool bNoBuffering) const
+	{
+		std::wstringstream wss;
+		wss << L" (handle: " << m_hFile << ", path : " << m_pathFile << L", no-buffering : " << bNoBuffering << L")";
+		return wss.str();
+	}
+
 	void TLocalFilesystemFile::Close()
 	{
 		InternalClose();
 	}
 
 	file_size_t TLocalFilesystemFile::GetFileSize() const
 	{
+		LOG_DEBUG(m_spLog) << L"Retrieving file size" << GetFileInfoForLog(m_bNoBuffering);
+
 		if (!IsOpen())
+		{
+			LOG_ERROR(m_spLog) << L"Retrieving file size failed - file not open" << GetFileInfoForLog(m_bNoBuffering);
 			return 0;
+		}
 
 		BY_HANDLE_FILE_INFORMATION bhfi;
 
 		if (!::GetFileInformationByHandle(m_hFile, &bhfi))
+		{
+			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Retrieving file size failed with error " << dwLastError << GetFileInfoForLog(m_bNoBuffering);
+
 			return 0;
+		}
 
 		ULARGE_INTEGER uli;
 		uli.HighPart = bhfi.nFileSizeHigh;
 		uli.LowPart = bhfi.nFileSizeLow;
 
+		LOG_DEBUG(m_spLog) << L"File size retrieved -> " << uli.QuadPart << GetFileInfoForLog(m_bNoBuffering);
+
 		return uli.QuadPart;
 	}
 
 	void TLocalFilesystemFile::GetFileInfo(TFileInfo& tFileInfo) const
 	{
+		LOG_DEBUG(m_spLog) << L"Retrieving file information" << GetFileInfoForLog(m_bNoBuffering);
+
 		if (!IsOpen())
+		{
+			LOG_ERROR(m_spLog) << L"Retrieving file information failed - file not open" << GetFileInfoForLog(m_bNoBuffering);
 			throw TFileException(eErr_FileNotOpen, ERROR_INVALID_HANDLE, m_pathFile, L"File not open. Cannot get file info.", LOCATION);
+		}
 
 		BY_HANDLE_FILE_INFORMATION bhfi;
 
 		if (!::GetFileInformationByHandle(m_hFile, &bhfi))
 		{
 			DWORD dwLastError = GetLastError();
+			LOG_ERROR(m_spLog) << L"Retrieving file information failed with error " << dwLastError << GetFileInfoForLog(m_bNoBuffering);
 			throw TFileException(eErr_CannotGetFileInfo, dwLastError, m_pathFile, L"Retrieving file info from handle failed.", LOCATION);
 		}
 
@@ -270,6 +376,14 @@
 		tFileInfo.SetAttributes(bhfi.dwFileAttributes);
 		tFileInfo.SetFileTimes(TFileTime(bhfi.ftCreationTime), TFileTime(bhfi.ftLastAccessTime), TFileTime(bhfi.ftLastWriteTime));
 		tFileInfo.SetLength64(uli.QuadPart);
+
+		LOG_DEBUG(m_spLog) << L"Retrieving file information succeeded. Attributes: " <<
+			bhfi.dwFileAttributes <<
+			L", creation-time: " << bhfi.ftCreationTime <<
+			L", last-access-time: " << bhfi.ftLastAccessTime<<
+			L", last-write-time: " << bhfi.ftLastWriteTime <<
+			L", size: " << uli.QuadPart <<
+			GetFileInfoForLog(m_bNoBuffering);
 	}
 
 	TSmartPath TLocalFilesystemFile::GetFilePath() const