Common: Add a LOG of logging for loading files from idb

GUIs.Common/DocumentResultList/frmDocumentResultList.vb

@@ -241,7 +241,7 @@ Public Class frmDocumentResultList
     Private Function LoadFile_IDB(GridRow As DataRow) As DocumentResultInfo
         Try
             Dim oObjectId = GridRow.Item(COLUMN_DOCID)
-            _Logger.Debug($"Getting Information for oObjectId: {oObjectId}")
+            _Logger.Debug("Loading Information for ObjectId: [{0}]", oObjectId)
 
             ' This needs to be Sync bc otherwise the PopupMenuShowing event will fire before this method loaded the Document Info
             Dim oDocumentInfo As DocumentInfo = _IDBClient.GetDocumentInfo(_Environment.User.UserId, oObjectId)
@@ -249,34 +249,47 @@ Public Class frmDocumentResultList
                 .AccessRight = oDocumentInfo.AccessRight,
                 .FullPath = oDocumentInfo.FullPath
             }
+            _Logger.Debug("Successfully loaded Information for ObjectId: [{0}]", oObjectId)
 
+            _Logger.Debug("Loading file [{0}]", oResultDocumentInfo.FullPath)
             If File.Exists(oResultDocumentInfo.FullPath) Then
                 oResultDocumentInfo = LoadFile_AsByteArray(oResultDocumentInfo)
                 _OpenDocuments.Add(oResultDocumentInfo)
                 _CurrentDocument = oResultDocumentInfo
+            Else
+                _Logger.Warn("File [{0}] does not exist.", oResultDocumentInfo.FullPath)
             End If
-            _Logger.Debug($"Got Info for oObjectId: {oObjectId}!")
+            _Logger.Debug("Successfully loaded File [{0}]", oResultDocumentInfo.FullPath)
+
             Return oResultDocumentInfo
+
         Catch ex As Exception
             _Logger.Error(ex)
             Return Nothing
+
         End Try
     End Function
 
     Private Function LoadFile_AsByteArray(DocumentInfo As DocumentResultInfo) As DocumentResultInfo
         Try
+            _Logger.Debug("Loading File [{0}]", DocumentInfo.FullPath)
             Dim oFullPath As String = DocumentInfo.FullPath
             Dim oPathExists = From oFile In _OpenDocuments
                               Where oFile.FullPath = oFullPath And oFile.Contents IsNot Nothing
                               Select oFile
+
             Dim oExistsInCache = oPathExists.Count() > 0
             Dim oSizeChanged = False
             Dim oWriteTimeChanged = False
 
+            _Logger.Debug("File exists in Cache: [{0}]", oExistsInCache)
+
             ' Get Information about the file on the filesystem
             Dim oFileInfo As New FileInfo(oFullPath)
 
             If oExistsInCache Then
+                _Logger.Debug("Loading file from cache.")
+
                 Dim oCachedItem = oPathExists.First()
 
                 If oCachedItem.Contents Is Nothing Then
@@ -284,37 +297,29 @@ Public Class frmDocumentResultList
                 Else
                     oSizeChanged = Not (oFileInfo.Length = oCachedItem.Contents.Length)
                 End If
+                _Logger.Debug("Filesize changed: [{0}]", oSizeChanged)
 
                 If oCachedItem.LastWriteTime = Nothing Then
                     oWriteTimeChanged = False
                 Else
                     oWriteTimeChanged = Not oFileInfo.LastWriteTime.Equals(oCachedItem.LastWriteTime)
                 End If
+                _Logger.Debug("Write-time changed: [{0}]", oWriteTimeChanged)
 
                 If oSizeChanged Or oWriteTimeChanged Then
-                    Using oStream = File.OpenRead(DocumentInfo.FullPath)
-                        Using oMemoryStream = New MemoryStream()
-                            oStream.CopyTo(oMemoryStream)
-                            DocumentInfo.Contents = oMemoryStream.ToArray()
-                            DocumentInfo.LastWriteTime = oFileInfo.LastWriteTime
-                        End Using
-                    End Using
+                    _Logger.Debug("Size or Write-time changed, loading from disk.")
 
-                    Return DocumentInfo
+                    Return LoadFile_FromDisk(DocumentInfo, oFileInfo)
                 Else
+                    _Logger.Debug("Loading from cache")
+
                     Return oCachedItem
                 End If
 
             Else
-                Using oStream = File.OpenRead(DocumentInfo.FullPath)
-                    Using oMemoryStream = New MemoryStream()
-                        oStream.CopyTo(oMemoryStream)
-                        DocumentInfo.Contents = oMemoryStream.ToArray()
-                        DocumentInfo.LastWriteTime = oFileInfo.LastWriteTime
-                    End Using
-                End Using
+                _Logger.Debug("File exists in cache, loading from disk.")
 
-                Return DocumentInfo
+                Return LoadFile_FromDisk(DocumentInfo, oFileInfo)
             End If
 
         Catch ex As Exception
@@ -323,6 +328,22 @@ Public Class frmDocumentResultList
         End Try
     End Function
 
+    Private Function LoadFile_FromDisk(pDocumentInfo As DocumentResultInfo, pFileInfo As FileInfo) As DocumentResultInfo
+        Using oStream = File.OpenRead(pDocumentInfo.FullPath)
+            _Logger.Debug("File opened.")
+
+            Using oMemoryStream = New MemoryStream()
+                _Logger.Debug("Copying file contents to memory stream.")
+                oStream.CopyTo(oMemoryStream)
+                pDocumentInfo.Contents = oMemoryStream.ToArray()
+                pDocumentInfo.LastWriteTime = pFileInfo.LastWriteTime
+                _Logger.Debug("Successfully copied file contents to memory stream.")
+            End Using
+        End Using
+
+        Return pDocumentInfo
+    End Function
+
     Public Function RefreshResults(pResults As IEnumerable(Of BaseResult)) As Boolean Implements IResultForm.RefreshResults
         _IsLoading = True
         Try