Bug 1519387 - Implement IMAP cache logging. r=jorgk
authorGene Smith <gds@chartertn.net>
Thu, 09 Aug 2018 02:52:30 -0400
changeset 34167 f751be7a177924870f99fc454340791ebf6d5476
parent 34166 77f1eb52e15571ac991adb90c0862701e7238bc1
child 34168 bb6728bfe4358525d708631344c8da6638b9f7e8
push id389
push userclokep@gmail.com
push dateMon, 18 Mar 2019 19:01:53 +0000
reviewersjorgk
bugs1519387
Bug 1519387 - Implement IMAP cache logging. r=jorgk
mailnews/imap/src/nsIMAPBodyShell.cpp
mailnews/imap/src/nsImapProtocol.cpp
mailnews/imap/src/nsImapUrl.cpp
--- a/mailnews/imap/src/nsIMAPBodyShell.cpp
+++ b/mailnews/imap/src/nsIMAPBodyShell.cpp
@@ -8,16 +8,19 @@
 #include "nsImapProtocol.h"
 
 #include "nsMimeTypes.h"
 #include "nsServiceManagerUtils.h"
 
 // need to talk to Rich about this...
 #define IMAP_EXTERNAL_CONTENT_HEADER "X-Mozilla-IMAP-Part"
 
+using namespace mozilla;
+extern LazyLogModule IMAPCache;  // defined in nsImapProtocol.cpp
+
 // imapbody.cpp
 // Implementation of the nsIMAPBodyShell and associated classes
 // These are used to parse IMAP BODYSTRUCTURE responses, and intelligently (?)
 // figure out what parts we need to display inline.
 
 /*
         Create a nsIMAPBodyShell from a full BODYSTRUCUTRE response from the parser.
 
@@ -211,16 +214,17 @@ int32_t nsIMAPBodyShell::Generate(char *
   if (!GetIsValid() || PreflightCheckAllInline())
   {
     // We don't have a valid shell, or all parts are going to be inline anyway.  Fall back to fetching the whole message.
 #ifdef DEBUG_chrisf
     NS_ASSERTION(GetIsValid());
 #endif
     m_generatingWholeMessage = true;
     uint32_t messageSize = m_protocolConnection->GetMessageSize(GetUID().get(), true);
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("Generate(): Set IMAP_CONTENT_NOT MODIFIED"));
     m_protocolConnection->SetContentModified(IMAP_CONTENT_NOT_MODIFIED);  // So that when we cache it, we know we have the whole message
     if (!DeathSignalReceived())
       m_protocolConnection->FallbackToFetchWholeMsg(GetUID(), messageSize);
     contentLength = (int32_t) messageSize;  // ugh
   }
   else
   {
     // We have a valid shell.
@@ -444,16 +448,18 @@ int32_t nsIMAPBodypart::GeneratePart(nsI
 
   // we are fetching and streaming this part's body as we go
   if (stream && !aShell->DeathSignalReceived())
   {
     char *generatingPart = aShell->GetGeneratingPart();
     bool fetchingSpecificPart = (generatingPart && !PL_strcmp(generatingPart, m_partNumberString));
 
     aShell->GetConnection()->Log("SHELL","GENERATE-Part-Inline",m_partNumberString);
+    MOZ_LOG(IMAPCache, LogLevel::Debug,
+      ("GeneratePart(): Call FetchTryChunking() part length=%" PRIi32 ", part number=%s", m_partLength, m_partNumberString));
     aShell->GetConnection()->FetchTryChunking(aShell->GetUID(), kMIMEPart, true, m_partNumberString, m_partLength, !fetchingSpecificPart);
   }
   return m_partLength;  // the part length has been filled in from the BODYSTRUCTURE response
 }
 
 int32_t nsIMAPBodypart::GenerateBoundary(nsIMAPBodyShell *aShell, bool stream, bool prefetch, bool lastBoundary)
 {
   if (prefetch)
--- a/mailnews/imap/src/nsImapProtocol.cpp
+++ b/mailnews/imap/src/nsImapProtocol.cpp
@@ -76,16 +76,17 @@
 #include "nsIImapMailFolderSink.h"
 #include "nsIImapServerSink.h"
 #include "nsIImapMessageSink.h"
 
 using namespace mozilla;
 
 LazyLogModule IMAP("IMAP");
 LazyLogModule IMAP_CS("IMAP_CS");
+LazyLogModule IMAPCache("IMAPCache");
 
 #define ONE_SECOND ((uint32_t)1000)    // one second
 
 #define OUTPUT_BUFFER_SIZE (4096*2) // mscott - i should be able to remove this if I can use nsMsgLineBuffer???
 
 #define IMAP_ENV_HEADERS "From To Cc Bcc Subject Date Message-ID "
 #define IMAP_DB_HEADERS "Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To"
 #define IMAP_ENV_AND_DB_HEADERS IMAP_ENV_HEADERS IMAP_DB_HEADERS
@@ -1323,20 +1324,22 @@ nsImapProtocol::PseudoInterruptMsgLoad(n
       {
         nsCOMPtr <nsIMsgFolder> runningImapFolder;
         nsCOMPtr <nsIMsgWindow> msgWindow;
         nsCOMPtr <nsIMsgMailNewsUrl> mailnewsUrl = do_QueryInterface(runningImapURL);
         mailnewsUrl->GetMsgWindow(getter_AddRefs(msgWindow));
         mailnewsUrl->GetFolder(getter_AddRefs(runningImapFolder));
         if (aImapFolder == runningImapFolder && msgWindow == aMsgWindow)
         {
+          MOZ_LOG(IMAPCache, LogLevel::Debug, ("PseudoInterruptMsgLoad(): Set PseudoInterrupt"));
           PseudoInterrupt(true);
           *interrupted = true;
         }
         // If we're interrupted, doom any incomplete cache entry.
+        MOZ_LOG(IMAPCache, LogLevel::Debug, ("PseudoInterruptMsgLoad(): Call DoomCacheEntry()"));
         DoomCacheEntry(mailnewsUrl);
       }
     }
   }
   PR_CExitMonitor(this);
 #ifdef DEBUG_bienvenu
   printf("interrupt msg load : %s\n", (*interrupted) ? "TRUE" : "FALSE");
 #endif
@@ -1559,17 +1562,20 @@ static void DoomCacheEntry(nsIMsgMailNew
   bool readingFromMemCache = false;
   nsCOMPtr<nsIImapUrl> imapUrl = do_QueryInterface(url);
   imapUrl->GetMsgLoadingFromCache(&readingFromMemCache);
   if (!readingFromMemCache)
   {
     nsCOMPtr<nsICacheEntry> cacheEntry;
     url->GetMemCacheEntry(getter_AddRefs(cacheEntry));
     if (cacheEntry)
+    {
+      MOZ_LOG(IMAPCache, LogLevel::Debug, ("DoomCacheEntry(): Call AsyncDoom()"));
       cacheEntry->AsyncDoom(nullptr);
+    }
   }
 }
 
 // returns true if another url was run, false otherwise.
 bool nsImapProtocol::ProcessCurrentURL()
 {
   nsresult rv = NS_OK;
   if (m_idle)
@@ -1819,17 +1825,20 @@ bool nsImapProtocol::ProcessCurrentURL()
       rv = NS_MSG_ERROR_IMAP_COMMAND_FAILED;
     else
       rv = GetConnectionStatus();
     // we are done with this url.
     m_imapMailFolderSink->SetUrlState(this, mailnewsurl, false, suspendUrl,
                                       rv);
      // doom the cache entry
     if (NS_FAILED(rv) && DeathSignalReceived() && m_mockChannel)
+    {
+      MOZ_LOG(IMAPCache, LogLevel::Debug, ("ProcessCurrentURL(): Call DoomCacheEntry()"));
       DoomCacheEntry(mailnewsurl);
+    }
   }
   else
   {
     // That's seen at times in debug sessions.
     NS_WARNING("missing url or sink");
   }
 
   // disable timeouts before caching connection.
@@ -2410,17 +2419,17 @@ NS_IMETHODIMP nsImapProtocol::CanHandleU
                 else
                   *aCanRunUrl = true;
               }
             }
           }
           MOZ_LOG(IMAP, LogLevel::Debug,
                  ("proposed url = %s folder for connection %s has To Wait = %s can run = %s",
                   folderNameForProposedUrl, curSelectedUrlFolderName.get(),
-                  (*hasToWait) ? "TRUE" : "FALSE", (*aCanRunUrl) ? "TRUE" : "FALSE"));
+                  (*hasToWait) ? "true" : "false", (*aCanRunUrl) ? "true" : "false"));
           PR_FREEIF(folderNameForProposedUrl);
         }
       }
       else // *** jt - an authenticated state url can be run in either
         // authenticated or selected state
       {
         nsImapAction actionForRunningUrl;
 
@@ -2626,17 +2635,21 @@ void nsImapProtocol::ProcessSelectedStat
             // multiple messages, fetch them all
             SetProgressString(IMAP_MESSAGES_STRING_INDEX);
 
             m_progressCurrentNumber[m_stringIndex] = 0;
             m_progressExpectedNumber = CountMessagesInIdString(messageIdString.get());
 
             // we need to set this so we'll get the msg from the memory cache.
             if (m_imapAction == nsIImapUrl::nsImapMsgFetchPeek)
+            {
+              MOZ_LOG(IMAPCache, LogLevel::Debug,
+                ("ProcessSelectedStateURL(): Set IMAP_CONTENT_NOT_MODIFIED; action nsImapMsgFetchPeek"));
               SetContentModified(IMAP_CONTENT_NOT_MODIFIED);
+            }
 
             FetchMessage(messageIdString,
               (m_imapAction == nsIImapUrl::nsImapMsgPreview)
               ? kBodyStart : kEveryThingRFC822Peek);
             if (m_imapAction == nsIImapUrl::nsImapMsgPreview)
               HeaderFetchCompleted();
             SetProgressString(IMAP_EMPTY_STRING_INDEX);
           }
@@ -2665,27 +2678,31 @@ void nsImapProtocol::ProcessSelectedStat
                 messageIdValString.AppendInt(m_uidValidity);
                 RefPtr<nsIMAPBodyShell> foundShell;
                 res = m_hostSessionList->FindShellInCacheForHost(GetImapServerKey(),
                   GetServerStateParser().GetSelectedMailboxName(),
                   messageIdValString.get(), modType, getter_AddRefs(foundShell));
                 if (!foundShell)
                 {
                   // The shell wasn't in the cache.  Deal with this case later.
-                  Log("SHELL",NULL,"Loading part, shell not found in cache!");
+                  Log("SHELL", NULL, "Loading part, shell not found in cache!");
                   //MOZ_LOG(IMAP, out, ("BODYSHELL: Loading part, shell not found in cache!"));
                   // The parser will extract the part number from the current URL.
+                  MOZ_LOG(IMAPCache, LogLevel::Debug,
+                    ("ProcessSelectedStateURL(): Set IMAP_CONTENT_MODIFIED_*; fetch bodystructure, one mime part"));
                   SetContentModified(modType);
                   Bodystructure(messageIdString, bMessageIdsAreUids);
                 }
                 else
                 {
                   Log("SHELL", NULL, "Loading Part, using cached shell.");
                   //MOZ_LOG(IMAP, out, ("BODYSHELL: Loading part, using cached shell."));
                   SetContentModified(modType);
+                  MOZ_LOG(IMAPCache, LogLevel::Debug,
+                    ("ProcessSelectedStateURL(): Set IMAP_CONTENT_MODIFIED_*: fetch one mime part"));
                   foundShell->SetConnection(this);
                   GetServerStateParser().UseCachedShell(foundShell);
                   //Set the current uid in server state parser (in case it was used for new mail msgs earlier).
                   GetServerStateParser().SetCurrentResponseUID(strtoul(messageIdString.get(), nullptr, 10));
                   foundShell->Generate(imappart);
                   GetServerStateParser().UseCachedShell(NULL);
                 }
               }
@@ -2708,23 +2725,22 @@ void nsImapProtocol::ProcessSelectedStat
               bool allowedToBreakApart = true; // (ce  && !DeathSignalReceived()) ? ce->URL_s->allow_content_change : false;
               bool mimePartSelectorDetected;
               bool urlOKToFetchByParts = false;
               m_runningUrl->GetMimePartSelectorDetected(&mimePartSelectorDetected);
               m_runningUrl->GetFetchPartsOnDemand(&urlOKToFetchByParts);
 
               {
                 nsCOMPtr<nsIMsgMailNewsUrl> mailnewsurl = do_QueryInterface(m_runningUrl);
-                nsAutoCString urlSpec;
-                if (mailnewsurl)
-                  urlSpec = mailnewsurl->GetSpecOrDefault();
-                MOZ_LOG(IMAP, LogLevel::Debug,
-                       ("SHELL: URL %s, OKToFetchByParts %d, allowedToBreakApart %d, ShouldFetchAllParts %d",
-                        urlSpec.get(), urlOKToFetchByParts, allowedToBreakApart,
-                        GetShouldFetchAllParts()));
+                if (mailnewsurl) {
+                  MOZ_LOG(IMAP, LogLevel::Debug,
+                         ("SHELL: URL %s, OKToFetchByParts %d, allowedToBreakApart %d, ShouldFetchAllParts %d",
+                          mailnewsurl->GetSpecOrDefault().get(), urlOKToFetchByParts, allowedToBreakApart,
+                          GetShouldFetchAllParts()));
+                }
               }
 
               if (urlOKToFetchByParts &&
                   allowedToBreakApart &&
                   !GetShouldFetchAllParts() &&
                   GetServerStateParser().ServerHasIMAP4Rev1Capability() /* &&
                 !mimePartSelectorDetected */)  // if a ?part=, don't do BS.
               {
@@ -2736,44 +2752,72 @@ void nsImapProtocol::ProcessSelectedStat
                 IMAP_ContentModifiedType modType = GetShowAttachmentsInline() ?
                   IMAP_CONTENT_MODIFIED_VIEW_INLINE :
                   IMAP_CONTENT_MODIFIED_VIEW_AS_LINKS ;
 
                 bool wasStoringMsgOffline;
                 m_runningUrl->GetStoreResultsOffline(&wasStoringMsgOffline);
                 m_runningUrl->SetStoreOfflineOnFallback(wasStoringMsgOffline);
                 m_runningUrl->SetStoreResultsOffline(false);
+                if (MOZ_LOG_TEST(IMAPCache, LogLevel::Debug))
+                {
+                  // For logging the running URL.
+                  nsCOMPtr<nsIMsgMailNewsUrl> mailnewsurl = do_QueryInterface(m_runningUrl);
+                  if (mailnewsurl) {
+                    MOZ_LOG(IMAPCache, LogLevel::Debug,
+                      ("ProcessSelectedStateURL(): Fetch parts; URL = |%s|", mailnewsurl->GetSpecOrDefault().get()));
+                  }
+                }
+                MOZ_LOG(IMAPCache, LogLevel::Debug,
+                  ("ProcessSelectedStateURL(): Set IMAP_CONTENT_MODIFIED_*; fetch message by parts"));
                 SetContentModified(modType);  // This will be looked at by the cache
                 if (bMessageIdsAreUids)
                 {
                   nsCString messageIdValString(messageIdString);
                   messageIdValString.AppendInt(m_uidValidity);
                   res = m_hostSessionList->FindShellInCacheForHost(GetImapServerKey(),
                     GetServerStateParser().GetSelectedMailboxName(),
                     messageIdValString.get(), modType, getter_AddRefs(foundShell));
                   if (foundShell)
                   {
-                    Log("SHELL",NULL,"Loading message, using cached shell.");
-                    //MOZ_LOG(IMAP, out, ("BODYSHELL: Loading message, using cached shell."));
+                    Log("SHELL", NULL, "Loading message, using cached shell.");
                     foundShell->SetConnection(this);
                     GetServerStateParser().UseCachedShell(foundShell);
                     //Set the current uid in server state parser (in case it was used for new mail msgs earlier).
                     GetServerStateParser().SetCurrentResponseUID(strtoul(messageIdString.get(), nullptr, 10));
                     foundShell->Generate(NULL);
+                    MOZ_LOG(IMAPCache, LogLevel::Debug,
+                      ("ProcessSelectedStateURL(): Generated parts fetch from cached shell)"));
                     GetServerStateParser().UseCachedShell(NULL);
                   }
                 }
 
                 if (!foundShell)
+                {
+                  MOZ_LOG(IMAPCache, LogLevel::Debug,
+                    ("ProcessSelectedStateURL(): Fetch bodystructure and generated parts fetch"));
                   Bodystructure(messageIdString, bMessageIdsAreUids);
+                }
               }
               else
               {
                 // Not doing bodystructure.  Fetch the whole thing, and try to do
                 // it in chunks.
+                if (MOZ_LOG_TEST(IMAPCache, LogLevel::Debug))
+                {
+                  // For logging the running URL.
+                  nsCOMPtr<nsIMsgMailNewsUrl> mailnewsurl = do_QueryInterface(m_runningUrl);
+                  if (mailnewsurl)
+                  {
+                    MOZ_LOG(IMAPCache, LogLevel::Debug,
+                      ("ProcessSelectedStateURL(): Fetch entire message; URL = |%s|", mailnewsurl->GetSpecOrDefault().get()));
+                  }
+                }
+                MOZ_LOG(IMAPCache, LogLevel::Debug,
+                  ("ProcessSelectedStateURL(): Set IMAP_CONTENT_NOT MODIFIED; fetch entire message with FetchTryChunking()"));
                 SetContentModified(IMAP_CONTENT_NOT_MODIFIED);
                 FetchTryChunking(messageIdString, whatToFetch,
                   bMessageIdsAreUids, NULL, messageSize, true);
               }
             }
             if (GetServerStateParser().LastCommandSuccessful()
                 && m_imapAction != nsIImapUrl::nsImapMsgPreview
                 && m_imapAction != nsIImapUrl::nsImapMsgFetchPeek)
@@ -4164,21 +4208,21 @@ void nsImapProtocol::ProcessMailboxUpdat
       // 3. Using CONDSTORE and highest MODSEQ response is not equal to stored
       // mod seq for folder.
 
       // Print to log items affecting needFolderSync:
       MOZ_LOG(IMAP_CS, LogLevel::Debug,
               ("1. Do a sync?: added=%" PRId32 ", deleted=%" PRId32 ", useCS=%s",
                added, deleted,  useCS ? "true" : "false"));
       MOZ_LOG(IMAP_CS, LogLevel::Debug,
-              ("2. Do a sync?: ShowDeletedMsgs=%s, exists=%" PRId32 ", mFolderTotalMsgCount=%" PRId32 "",
+              ("2. Do a sync?: ShowDeletedMsgs=%s, exists=%" PRId32 ", mFolderTotalMsgCount=%" PRId32,
                GetShowDeletedMessages() ? "true" : "false", GetServerStateParser().NumberOfMessages(),
                mFolderTotalMsgCount));
       MOZ_LOG(IMAP_CS, LogLevel::Debug,
-              ("3. Do a sync?: fHighestModSeq=%" PRIu64 ", mFolderLastModSeq=%" PRIu64 "",
+              ("3. Do a sync?: fHighestModSeq=%" PRIu64 ", mFolderLastModSeq=%" PRIu64,
                GetServerStateParser().fHighestModSeq,  mFolderLastModSeq));
 
       needFolderSync =
         (
           (flagStateEmpty || added == deleted) &&
           (
             !useCS
             ||
@@ -4217,52 +4261,52 @@ void nsImapProtocol::ProcessMailboxUpdat
         {
           uint32_t numExists = GetServerStateParser().NumberOfMessages();
           uint32_t numPrevExists = mFolderTotalMsgCount;
 
           if (MOZ_LOG_TEST(IMAP_CS, LogLevel::Debug))
           {
             int32_t addedByPartialFetch;
             m_flagState->GetNumberOfMessages(&addedByPartialFetch);
-            MOZ_LOG(IMAP_CS, LogLevel::Debug, ("Sanity, deleted=%" PRId32 ", numPrevExists=%" PRIu32 ", numExists=%" PRIu32 "",
+            MOZ_LOG(IMAP_CS, LogLevel::Debug, ("Sanity, deleted=%" PRId32 ", numPrevExists=%" PRIu32 ", numExists=%" PRIu32,
                     m_flagState->NumberOfDeletedMessages(), numPrevExists,  numExists));
-            MOZ_LOG(IMAP_CS, LogLevel::Debug, ("Sanity, addedByPartialFetch=%" PRId32 "",
+            MOZ_LOG(IMAP_CS, LogLevel::Debug, ("Sanity, addedByPartialFetch=%" PRId32,
                     addedByPartialFetch));
           }
 
           // Determine the number of new UIDs just fetched that are greater than
           // the saved highest UID for the folder. numToCheck will contain the
           // number of UIDs just fetched and, of course, not all are new.
           uint32_t numNewUIDs = 0;
           uint32_t numToCheck = m_flagState->GetNumAdded();
           bool flagChangeDetected = false;
-          MOZ_LOG(IMAP_CS, LogLevel::Debug, ("numToCheck=%" PRIu32 "", numToCheck));
+          MOZ_LOG(IMAP_CS, LogLevel::Debug, ("numToCheck=%" PRIu32, numToCheck));
           if (numToCheck && mFolderHighestUID)
           {
             uint32_t uid;
             int32_t topIndex;
             m_flagState->GetNumberOfMessages(&topIndex);
             do {
               topIndex--;
               m_flagState->GetUidOfMessage(topIndex, &uid);
               if (uid && uid != nsMsgKey_None)
               {
                 if (uid > mFolderHighestUID)
                 {
                   numNewUIDs++;
-                  MOZ_LOG(IMAP_CS, LogLevel::Debug, ("numNewUIDs=%" PRIu32 ", Added new UID=%" PRIu32 "",
+                  MOZ_LOG(IMAP_CS, LogLevel::Debug, ("numNewUIDs=%" PRIu32 ", Added new UID=%" PRIu32,
                        numNewUIDs ,uid));
                   numToCheck--;
                 }
                 else
                 {
                   // Just a flag change on an existing UID. No more new UIDs
                   // will be found. This does not detect an expunged message.
                   flagChangeDetected = true;
-                  MOZ_LOG(IMAP_CS, LogLevel::Debug, ("Not new uid = %" PRIu32 "", uid));
+                  MOZ_LOG(IMAP_CS, LogLevel::Debug, ("Not new uid=%" PRIu32, uid));
                   break;
                 }
               }
             } while(numToCheck);
           }
 
           // Another client expunged at least one message if the number of new
           // UIDs is not equal to the observed change in the number of messages
@@ -4309,17 +4353,17 @@ void nsImapProtocol::ProcessMailboxUpdat
     {
       // Obtain the highest (highwater mark) UID seen since the last UIDVALIDITY
       // response occurred (associated with the most recent SELECT for the folder).
       uint32_t highestRecordedUID = GetServerStateParser().HighestRecordedUID();
       // if we're using CONDSTORE, and the parser hasn't seen any UIDs, use
       // the highest UID previously seen and saved for the folder instead.
       if (useCS && !highestRecordedUID)
         highestRecordedUID = mFolderHighestUID;
-      MOZ_LOG(IMAP_CS, LogLevel::Debug, ("Check for new messages above UID=%" PRIu32 "",
+      MOZ_LOG(IMAP_CS, LogLevel::Debug, ("Check for new messages above UID=%" PRIu32,
               highestRecordedUID));
       AppendUid(fetchStr, highestRecordedUID + 1);
       fetchStr.AppendLiteral(":*");
       FetchMessage(fetchStr, kFlags);      // only new messages please
     }
   }
   else if (GetServerStateParser().LastCommandSuccessful())
   {
@@ -5740,17 +5784,17 @@ void nsImapProtocol::InitPrefAuthMethods
         m_prefAuthMethods = kHasCRAMCapability |
             kHasAuthGssApiCapability |
             kHasAuthNTLMCapability | kHasAuthMSNCapability;
         break;
       default:
         NS_ASSERTION(false, "IMAP: authMethod pref invalid");
         // TODO log to error console
         MOZ_LOG(IMAP, LogLevel::Error,
-            ("IMAP: bad pref authMethod = %d\n", authMethodPrefValue));
+            ("IMAP: bad pref authMethod = %d", authMethodPrefValue));
         // fall to any
         MOZ_FALLTHROUGH;
       case nsMsgAuthMethod::anything:
         m_prefAuthMethods = kHasAuthOldLoginCapability |
             kHasAuthLoginCapability | kHasAuthPlainCapability |
             kHasCRAMCapability | kHasAuthGssApiCapability |
             kHasAuthNTLMCapability | kHasAuthMSNCapability |
             kHasAuthExternalCapability | kHasXOAuth2Capability;
@@ -9270,16 +9314,26 @@ NS_IMETHODIMP nsImapMockChannel::Open2(n
   nsresult rv = nsContentSecurityManager::doContentSecurityCheck(this, listener);
   NS_ENSURE_SUCCESS(rv, rv);
   return Open(_retval);
 }
 
 NS_IMETHODIMP
 nsImapMockChannel::OnCacheEntryAvailable(nsICacheEntry *entry, bool aNew, nsIApplicationCache* aAppCache, nsresult status)
 {
+  if (MOZ_LOG_TEST(IMAPCache, LogLevel::Debug))
+  {
+    MOZ_LOG(IMAPCache, LogLevel::Debug,
+      ("OnCacheEntryAvailable(): Create/write new cache entry=%s", aNew ? "true" : "false"));
+    MOZ_LOG(IMAPCache, LogLevel::Debug,
+      ("OnCacheEntryAvailable(): Get part from entire message=%s", mTryingToReadPart ? "true" : "false"));
+    nsAutoCString key;
+    if(entry) entry->GetKey(key);
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("OnCacheEntryAvailable(): Cache entry key = |%s|", key.get()));
+  }
   nsresult rv = NS_OK;
 
   // make sure we didn't close the channel before the async call back came in...
   // hmmm....if we had write access and we canceled this mock channel then I wonder if we should
   // be invalidating the cache entry before kicking out...
   if (mChannelClosed)
   {
     entry->AsyncDoom(nullptr);
@@ -9294,17 +9348,21 @@ nsImapMockChannel::OnCacheEntryAvailable
 
   do {
     // For "normal" read/write access we always receive NS_OK here. aNew
     // indicates whether the cache entry is new and needs to be written, or not
     // new and can be read. If AsyncOpenURI() was called with access read-only,
     // status==NS_ERROR_CACHE_KEY_NOT_FOUND can be received here and we just read
     // the data directly.
     if (NS_FAILED(status))
+    {
+      MOZ_LOG(IMAPCache, LogLevel::Debug,
+        ("OnCacheEntryAvailable(): status parameter bad, preference browser.cache.memory not enabled?"));
       break;
+    }
 
     nsCOMPtr<nsIMsgMailNewsUrl> mailnewsUrl = do_QueryInterface(m_url, &rv);
     mailnewsUrl->SetMemCacheEntry(entry);
 
     // For URLs not related to parts, the processing is easy:
     // aNew==true means that we need to write to the entry,
     // aNew==false means that we can read it.
     //
@@ -9317,42 +9375,47 @@ nsImapMockChannel::OnCacheEntryAvailable
     //    The caller has already set up part extraction.
     //    This case is no different to non-part processing.
     // 2) The caller wants to try to extract the part from the cache entry
     //    of the entire message.
     //    In this case, the URL used as cache key addresses the message and
     //    mTryingToReadPart==true.
     if (mTryingToReadPart)
     {
+      MOZ_LOG(IMAPCache, LogLevel::Debug,
+        ("OnCacheEntryAvailable(): Trying to read part from entire message"));
       // We are here with the URI of the entire message which we know exists.
       MOZ_ASSERT(!aNew,
                  "Logic error: Trying to read part from entire message which doesn't exist");
       if (!aNew)
       {
         // Check the meta data.
         nsCString annotation;
         rv = entry->GetMetaDataElement("ContentModified", getter_Copies(annotation));
         if (NS_FAILED(rv) || !annotation.EqualsLiteral("Not Modified"))
         {
+          MOZ_LOG(IMAPCache, LogLevel::Debug,
+            ("OnCacheEntryAvailable(): Entry is not complete and cannot be used"));
           // The cache entry is not marked "Not Modified", that means it doesn't
           // contain the entire message, so we can't use it.
           // Call OpenCacheEntry() a second time to get the part.
           rv = OpenCacheEntry();
           if (NS_SUCCEEDED(rv))
             return rv;
 
           // Something has gone wrong, fall back to reading from the imap
           // connection so the protocol doesn't hang.
           break;
         }
       }
     }
 
     if (aNew)
     {
+      MOZ_LOG(IMAPCache, LogLevel::Debug, ("OnCacheEntryAvailable(): Begin cache WRITE"));
       // If we are writing, then insert a "stream listener Tee" into the flow
       // to force data into the cache and to our current channel listener.
       nsCOMPtr<nsIStreamListenerTee> tee = do_CreateInstance(NS_STREAMLISTENERTEE_CONTRACTID, &rv);
       if (NS_SUCCEEDED(rv))
       {
         nsCOMPtr<nsIOutputStream> out;
         // This will fail with the cache turned off, so we need to fall through
         // to ReadFromImapConnection instead of aborting with NS_ENSURE_SUCCESS(rv,rv).
@@ -9363,29 +9426,41 @@ nsImapMockChannel::OnCacheEntryAvailable
           m_channelListener = tee;
         }
         else
           NS_WARNING("IMAP Protocol failed to open output stream to Necko cache");
       }
     }
     else
     {
+      if (MOZ_LOG_TEST(IMAPCache, LogLevel::Debug))
+      {
+        int64_t size = 0;
+        rv = entry->GetDataSize(&size);
+        if (rv == NS_ERROR_IN_PROGRESS)
+          MOZ_LOG(IMAPCache, LogLevel::Debug, ("OnCacheEntryAvailable(): Concurrent cache READ, no size available"));
+        MOZ_LOG(IMAPCache, LogLevel::Debug, ("OnCacheEntryAvailable(): Begin cache READ, size=%" PRIi64 " ", size));
+      }
       rv = ReadFromMemCache(entry);
       if (NS_SUCCEEDED(rv))
       {
         NotifyStartEndReadFromCache(true);
         entry->MarkValid();
         return NS_OK; // Kick out if reading from the cache succeeded.
       }
       entry->AsyncDoom(nullptr); // Doom entry if we failed to read from cache.
       mailnewsUrl->SetMemCacheEntry(nullptr); // We aren't going to be reading from the cache.
     }
   } while (false);
 
   // If reading from the cache failed or if we are writing into the cache, default to ReadFromImapConnection.
+  if (aNew)
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("OnCacheEntryAvailable(): Cache WRITE start successful"));
+  else
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("OnCacheEntryAvailable: Cache READ failed"));
   return ReadFromImapConnection();
 }
 
 NS_IMETHODIMP
 nsImapMockChannel::OnCacheEntryCheck(nsICacheEntry* entry, nsIApplicationCache* appCache,
                                      uint32_t* aResult)
 {
   *aResult = nsICacheEntryOpenCallback::ENTRY_WANTED;
@@ -9393,18 +9468,21 @@ nsImapMockChannel::OnCacheEntryCheck(nsI
   // Check concurrent read: We can't read concurrently since we don't know
   // that the entry will ever be written successfully. It may be aborted
   // due to a size limitation. If reading concurrently, the following function
   // will return NS_ERROR_IN_PROGRESS. Then we tell the cache to wait until
   // the write is finished.
   int64_t size = 0;
   nsresult rv = entry->GetDataSize(&size);
   if (rv == NS_ERROR_IN_PROGRESS)
+  {
     *aResult = nsICacheEntryOpenCallback::RECHECK_AFTER_WRITE_FINISHED;
-
+    MOZ_LOG(IMAPCache, LogLevel::Debug,
+      ("OnCacheEntryCheck(): Attempted cache write while reading, will try again"));
+  }
   return NS_OK;
 }
 
 nsresult nsImapMockChannel::OpenCacheEntry()
 {
   nsresult rv;
   // get the cache session from our imap service...
   nsCOMPtr<nsIImapService> imapService = do_GetService(NS_IMAPSERVICE_CONTRACTID, &rv);
@@ -9427,16 +9505,18 @@ nsresult nsImapMockChannel::OpenCacheEnt
   if (folderSink)
     folderSink->GetUidValidity(&uidValidity);
   imapUrl->GetStoreResultsOffline(&storeResultsOffline);
   // If we're storing the message in the offline store, don't
   // write to the memory cache.
   if (storeResultsOffline)
     cacheAccess = nsICacheStorage::OPEN_READONLY;
 
+  MOZ_LOG(IMAPCache, LogLevel::Debug, ("OpenCacheEntry(): For URL = |%s|", m_url->GetSpecOrDefault().get()));
+
   // Use the uid validity as part of the cache key, so that if the uid validity
   // changes, we won't re-use the wrong cache entries.
   nsAutoCString extension;
   extension.AppendInt(uidValidity, 16);
 
   // Open a cache entry where the key is the potentially modified URL.
   nsAutoCString path;
   m_url->GetPathQueryRef(path);
@@ -9452,31 +9532,34 @@ nsresult nsImapMockChannel::OpenCacheEnt
   if (partQuery.IsEmpty()) {
     partQuery = MsgExtractQueryPart(path, "&part=");
     if (!partQuery.IsEmpty()) {
       // ? indicates a part query, so set the first character to that.
       partQuery.SetCharAt('?', 0);
     }
   }
   nsCString filenameQuery = MsgExtractQueryPart(path, "&filename=");
+  MOZ_LOG(IMAPCache, LogLevel::Debug,
+    ("OpenCacheEntry: part = |%s|, filename = |%s|", partQuery.get(), filenameQuery.get()));
 
   // Truncate path at either /; or ?
   int32_t ind = path.FindChar('?');
   if (ind != kNotFound)
     path.SetLength(ind);
   ind = path.Find("/;");
   if (ind != kNotFound)
     path.SetLength(ind);
 
   nsCOMPtr<nsIURI> newUri;
   if (partQuery.IsEmpty())
   {
     // Not looking for a part. That's the easy part.
     rv = NS_MutateURI(m_url).SetPathQueryRef(path).Finalize(newUri);
     NS_ENSURE_SUCCESS(rv, rv);
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("OpenCacheEntry(): Call AsyncOpenURI() on entire message"));
     return cacheStorage->AsyncOpenURI(newUri, extension, cacheAccess, this);
   }
 
   /**
    * Part processing (rest of this function).
    */
   if (mTryingToReadPart)
   {
@@ -9484,49 +9567,55 @@ nsresult nsImapMockChannel::OpenCacheEnt
     // We tried to read a part from the entire message but the meta data didn't
     // allow it. So we come back here.
     // Now request the part with its full URL.
     mTryingToReadPart = false;
 
     // Note that part extraction was already set the first time.
     rv = NS_MutateURI(m_url).SetPathQueryRef(path + partQuery + filenameQuery).Finalize(newUri);
     NS_ENSURE_SUCCESS(rv, rv);
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("OpenCacheEntry(): Call AsyncOpenURI() to write part (2nd try)"));
     return cacheStorage->AsyncOpenURI(newUri, extension, cacheAccess, this);
   }
 
   // First time processing. Set up part extraction.
   SetupPartExtractorListener(imapUrl, m_channelListener);
 
   // Check whether part is in the cache.
   bool exists = false;
   rv = NS_MutateURI(m_url).SetPathQueryRef(path + partQuery + filenameQuery).Finalize(newUri);
   NS_ENSURE_SUCCESS(rv, rv);
   rv = cacheStorage->Exists(newUri, extension, &exists);
   NS_ENSURE_SUCCESS(rv, rv);
   if (exists) {
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("OpenCacheEntry(): Call AsyncOpenURI() to read part from its own cache"));
     return cacheStorage->AsyncOpenURI(newUri, extension, cacheAccess, this);
   }
 
   // Let's see whether we have the entire message instead.
   rv = NS_MutateURI(m_url).SetPathQueryRef(path).Finalize(newUri);
   NS_ENSURE_SUCCESS(rv, rv);
   rv = cacheStorage->Exists(newUri, extension, &exists);
   NS_ENSURE_SUCCESS(rv, rv);
 
   if (!exists) {
     // The entire message is not in the cache. Request the part.
     rv = NS_MutateURI(m_url).SetPathQueryRef(path + partQuery + filenameQuery).Finalize(newUri);
     NS_ENSURE_SUCCESS(rv, rv);
+    MOZ_LOG(IMAPCache, LogLevel::Debug,
+      ("OpenCacheEntry(): Call AsyncOpenURI() to write part (entire message cache doesn't exists)"));
     return cacheStorage->AsyncOpenURI(newUri, extension, cacheAccess, this);
   }
 
   // This is where is gets complicated. The entire message is in the cache,
   // but we don't know whether it's suitable for use. Its meta data
   // might indicate that the message is incomplete.
   mTryingToReadPart = true;
+  MOZ_LOG(IMAPCache, LogLevel::Debug,
+    ("OpenCacheEntry(): Call AsyncOpenURI() to try to read part from entire message cache"));
   return cacheStorage->AsyncOpenURI(newUri, extension, cacheAccess, this);
 }
 
 nsresult nsImapMockChannel::ReadFromMemCache(nsICacheEntry *entry)
 {
   NS_ENSURE_ARG(entry);
 
   nsCString annotation;
@@ -9538,23 +9627,26 @@ nsresult nsImapMockChannel::ReadFromMemC
   entry->GetKey(entryKey);
   if (entryKey.FindChar('?') != kNotFound)
   {
     // Part processing: If we have a part, then we should use the cache entry.
     entry->GetMetaDataElement("contentType", getter_Copies(contentType));
     if (!contentType.IsEmpty())
       SetContentType(contentType);
     shouldUseCacheEntry = true;
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("ReadFromMemCache(): Reading a part"));
   }
   else
   {
     // Whole message processing: We should make sure the content isn't modified.
     rv = entry->GetMetaDataElement("ContentModified", getter_Copies(annotation));
     if (NS_SUCCEEDED(rv) && !annotation.IsEmpty())
       shouldUseCacheEntry = annotation.EqualsLiteral("Not Modified");
+    MOZ_LOG(IMAPCache, LogLevel::Debug,
+      ("ReadFromMemCache: Reading entire message, annotation: |%s|", annotation.get()));
 
     // Compare cache entry size with message size.
     if (shouldUseCacheEntry)
     {
       int64_t entrySize;
 
       rv = entry->GetDataSize(&entrySize);
       // We don't expect concurrent read here, so this call should always work.
@@ -9568,28 +9660,33 @@ nsresult nsImapMockChannel::ReadFromMemC
         msgUrl->GetMessageHeader(getter_AddRefs(msgHdr));
         if (msgHdr)
         {
           uint32_t messageSize;
           if (NS_SUCCEEDED(msgHdr->GetMessageSize(&messageSize)) &&
               messageSize != entrySize)
           {
             MOZ_LOG(IMAP, LogLevel::Warning,
-                ("ReadFromMemCache size mismatch for %s: message %" PRIu32 ", cache %" PRIi64 "\n",
-                 entryKey.get(), messageSize, entrySize));
+              ("ReadFromMemCache(): Size mismatch for %s: message %" PRIu32 ", cache %" PRIi64,
+               entryKey.get(), messageSize, entrySize));
+            MOZ_LOG(IMAPCache, LogLevel::Debug,
+              ("ReadFromMemCache(): Size mismatch for %s: message %" PRIu32 ", cache %" PRIi64,
+               entryKey.get(), messageSize, entrySize));
             shouldUseCacheEntry = false;
           }
         }
       }
     }
   }
 
   /**
    * Common processing for full messages and message parts.
    */
+  MOZ_LOG(IMAPCache, LogLevel::Debug,
+    ("ReadFromMemCache(): End separate processing: shouldUseCacheEntry=%s", shouldUseCacheEntry ? "true" : "false"));
 
   // Check header of full message or part.
   if (shouldUseCacheEntry)
   {
     nsCOMPtr<nsIInputStream> in;
     uint32_t readCount;
     rv = entry->OpenInputStream(0, getter_AddRefs(in));
     NS_ENSURE_SUCCESS(rv, rv);
@@ -9606,16 +9703,19 @@ nsresult nsImapMockChannel::ReadFromMemC
     // Check that the first line is a header line, i.e., with a ':' in it
     // Or that it begins with "From " because some IMAP servers allow that,
     // even though it's technically invalid.
     shouldUseCacheEntry = ((findPos != -1 && firstBlock[findPos] == ':') ||
                            !(strncmp(firstBlock, "From ", 5)));
     in->Close();
   }
 
+  MOZ_LOG(IMAPCache, LogLevel::Debug, ("ReadFromMemCache(): After header check: shouldUseCacheEntry=%s",
+    shouldUseCacheEntry ? "true" : "false"));
+
   if (shouldUseCacheEntry)
   {
     nsCOMPtr<nsIInputStream> in;
     rv = entry->OpenInputStream(0, getter_AddRefs(in));
     NS_ENSURE_SUCCESS(rv, rv);
      // if mem cache entry is broken or empty, return error.
     uint64_t bytesAvailable;
     rv = in->Available(&bytesAvailable);
@@ -9639,26 +9739,28 @@ nsresult nsImapMockChannel::ReadFromMemC
       // if the msg is unread, we should mark it read on the server. This lets
       // the code running this url we're loading from the cache, if it cares.
       imapUrl->SetMsgLoadingFromCache(true);
 
       // be sure to set the cache entry's security info status as our security info status...
       nsCOMPtr<nsISupports> securityInfo;
       entry->GetSecurityInfo(getter_AddRefs(securityInfo));
       SetSecurityInfo(securityInfo);
+      MOZ_LOG(IMAPCache, LogLevel::Debug, ("ReadFromMemCache(): Cache entry accepted"));
       return NS_OK;
     } // if AsyncRead succeeded.
   } // if content is not modified
   else
   {
     // Content is modified so return an error so we try to open it the
     // old fashioned way.
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("ReadFromMemCache(): Cache entry rejected"));
     rv = NS_ERROR_FAILURE;
   }
-
+  MOZ_LOG(IMAPCache, LogLevel::Debug, ("ReadFromMemCache(): Returning " PRIx32, static_cast<uint32_t>(rv)));
   return rv;
 }
 
 class nsReadFromImapConnectionFailure : public mozilla::Runnable
 {
 public:
   explicit nsReadFromImapConnectionFailure(nsImapMockChannel *aChannel)
     : mozilla::Runnable("nsReadFromImapConnectionFailure")
@@ -10049,16 +10151,17 @@ NS_IMETHODIMP nsImapMockChannel::Cancel(
                        "nsImapMockChannel::Cancel should only be called from UI thread");
   m_cancelStatus = status;
   nsCOMPtr<nsIImapProtocol> imapProtocol = do_QueryReferent(mProtocol);
 
   // if we aren't reading from the cache and we get canceled...doom our cache entry...
   if (m_url)
   {
     nsCOMPtr<nsIMsgMailNewsUrl> mailnewsUrl = do_QueryInterface(m_url);
+    MOZ_LOG(IMAPCache, LogLevel::Debug, ("Cancel(): Calling DoomCacheEntry()"));
     DoomCacheEntry(mailnewsUrl);
   }
 
   // Required for killing ImapProtocol thread
   if (imapProtocol)
     imapProtocol->TellThreadToDie(false);
 
   return NS_OK;
--- a/mailnews/imap/src/nsImapUrl.cpp
+++ b/mailnews/imap/src/nsImapUrl.cpp
@@ -24,16 +24,17 @@
 #include "nsIMAPNamespace.h"
 #include "nsICacheEntry.h"
 #include "nsIMsgFolder.h"
 #include "nsMsgUtils.h"
 #include "nsIMsgHdr.h"
 #include "nsServiceManagerUtils.h"
 
 using namespace mozilla;
+extern LazyLogModule IMAPCache;  // defined in nsImapProtocol.cpp
 
 static NS_DEFINE_CID(kCImapHostSessionListCID, NS_IIMAPHOSTSESSIONLIST_CID);
 
 nsImapUrl::nsImapUrl() : mLock("nsImapUrl.mLock")
 {
   m_listOfMessageIds = nullptr;
   m_sourceCanonicalFolderPathSubString = nullptr;
   m_destinationCanonicalFolderPathSubString = nullptr;
@@ -1048,18 +1049,25 @@ NS_IMETHODIMP nsImapUrl::SetContentModif
       break;
     case IMAP_CONTENT_MODIFIED_VIEW_AS_LINKS:
       contentModifiedAnnotation = "Modified View As Link";
       break;
     case IMAP_CONTENT_FORCE_CONTENT_NOT_MODIFIED:
       contentModifiedAnnotation = "Force Content Not Modified";
       break;
     }
+    MOZ_LOG(IMAPCache, LogLevel::Debug,
+      ("SetContentModified(): Set annotation to |%s|", contentModifiedAnnotation));
     cacheEntry->SetMetaDataElement("ContentModified", contentModifiedAnnotation);
   }
+  else
+  {
+    MOZ_LOG(IMAPCache, LogLevel::Debug,
+      ("SetContentModified(): Set annotation FAILED -- no cacheEntry"));
+  }
   return NS_OK;
 }
 
 NS_IMETHODIMP nsImapUrl::GetContentModified(nsImapContentModifiedType *contentModified)
 {
   if (!contentModified) return NS_ERROR_NULL_POINTER;
 
   *contentModified = m_contentModified;