Bug 815418: Telemetry for failed profile lock attempts r=vladan

--HG--
extra : rebase_source : 792850a58328ba4aa33e70b6c4cf7162bf167e8e

toolkit/components/telemetry/Telemetry.cpp

@@ -31,7 +31,9 @@
 #include "nsStringGlue.h"
 #include "nsITelemetry.h"
 #include "nsIFile.h"
+#include "nsIFileStreams.h"
 #include "nsIMemoryReporter.h"
+#include "nsISeekableStream.h"
 #include "Telemetry.h" 
 #include "nsTHashtable.h"
 #include "nsHashKeys.h"
@@ -39,6 +41,7 @@
 #include "nsXULAppAPI.h"
 #include "nsThreadUtils.h"
 #include "nsNetCID.h"
+#include "nsNetUtil.h"
 #include "plstr.h"
 #include "nsAppDirectoryServiceDefs.h"
 #include "mozilla/ProcessedStack.h"
@@ -334,6 +337,7 @@ private:
   CombinedStacks mLateWritesStacks; // This is collected out of the main thread.
   bool mCachedTelemetryData;
   uint32_t mLastShutdownTime;
+  uint32_t mFailedLockCount;
   nsCOMArray<nsIFetchTelemetryDataCallback> mCallbacks;
   friend class nsFetchTelemetryData;
 };
@@ -726,15 +730,49 @@ ReadLastShutdownDuration(const char *filename) {
   return shutdownTime;
 }
 
+const int32_t kMaxFailedProfileLockFileSize = 10;
+
+bool
+GetFailedLockCount(nsIInputStream* inStream, uint32_t aCount,
+                   unsigned int& result)
+{
+  nsAutoCString bufStr;
+  nsresult rv;
+  rv = NS_ReadInputStreamToString(inStream, bufStr, aCount);
+  NS_ENSURE_SUCCESS(rv, false);
+  result = bufStr.ToInteger(&rv);
+  return NS_SUCCEEDED(rv) && result > 0;
+}
+
+nsresult
+GetFailedProfileLockFile(nsIFile* *aFile, nsIFile* aProfileDir = nullptr)
+{
+  nsresult rv;
+  if (aProfileDir) {
+    rv = aProfileDir->Clone(aFile);
+  } else {
+    rv = NS_GetSpecialDirectory(NS_APP_USER_PROFILE_50_DIR, aFile);
+  }
+  NS_ENSURE_SUCCESS(rv, rv);
+
+  (*aFile)->AppendNative(NS_LITERAL_CSTRING("Telemetry.FailedProfileLocks.txt"));
+  return NS_OK;
+}
+
 class nsFetchTelemetryData : public nsRunnable
 {
 public:
-  nsFetchTelemetryData(const char *aFilename) :
-    mFilename(aFilename), mTelemetry(TelemetryImpl::sTelemetry) {
+  nsFetchTelemetryData(const char* aShutdownTimeFilename,
+                       nsIFile* aFailedProfileLockFile)
+    : mShutdownTimeFilename(aShutdownTimeFilename),
+      mFailedProfileLockFile(aFailedProfileLockFile),
+      mTelemetry(TelemetryImpl::sTelemetry)
+  {
   }
 
 private:
-  const char *mFilename;
+  const char* mShutdownTimeFilename;
+  nsCOMPtr<nsIFile> mFailedProfileLockFile;
   nsCOMPtr<TelemetryImpl> mTelemetry;
 
 public:
@@ -747,7 +785,9 @@ public:
   }
 
   NS_IMETHOD Run() {
-    mTelemetry->mLastShutdownTime = ReadLastShutdownDuration(mFilename);
+    LoadFailedLockCount(mTelemetry->mFailedLockCount);
+    mTelemetry->mLastShutdownTime = 
+      ReadLastShutdownDuration(mShutdownTimeFilename);
     mTelemetry->ReadLateWritesStacks();
     nsCOMPtr<nsIRunnable> e =
       NS_NewRunnableMethod(this, &nsFetchTelemetryData::MainThread);
@@ -755,6 +795,31 @@ public:
     NS_DispatchToMainThread(e, NS_DISPATCH_NORMAL);
     return NS_OK;
   }
+
+private:
+  nsresult
+  LoadFailedLockCount(uint32_t& failedLockCount)
+  {
+    failedLockCount = 0;
+    int64_t fileSize = 0;
+    nsresult rv = mFailedProfileLockFile->GetFileSize(&fileSize);
+    if (NS_FAILED(rv)) {
+      return rv;
+    }
+    NS_ENSURE_TRUE(fileSize <= kMaxFailedProfileLockFileSize,
+                   NS_ERROR_UNEXPECTED);
+    nsCOMPtr<nsIInputStream> inStream;
+    rv = NS_NewLocalFileInputStream(getter_AddRefs(inStream),
+                                    mFailedProfileLockFile,
+                                    PR_RDONLY);
+    NS_ENSURE_SUCCESS(rv, rv);
+    NS_ENSURE_TRUE(GetFailedLockCount(inStream, fileSize, failedLockCount),
+                   NS_ERROR_UNEXPECTED);
+    inStream->Close();
+
+    mFailedProfileLockFile->Remove(false);
+    return NS_OK;
+  }
 };
 
 static TimeStamp gRecordedShutdownStartTime;
@@ -801,6 +866,21 @@ TelemetryImpl::GetLastShutdownDuration(uint32_t *aResult)
   return NS_OK;
 }
 
+NS_IMETHODIMP
+TelemetryImpl::GetFailedProfileLockCount(uint32_t* aResult)
+{
+  // The user must call AsyncFetchTelemetryData first. We return zero instead of
+  // reporting a failure so that the rest of telemetry can uniformly handle
+  // the read not being available yet.
+  if (!mCachedTelemetryData) {
+    *aResult = 0;
+    return NS_OK;
+  }
+
+  *aResult = mFailedLockCount;
+  return NS_OK;
+}
+
 NS_IMETHODIMP
 TelemetryImpl::AsyncFetchTelemetryData(nsIFetchTelemetryDataCallback *aCallback)
 {
@@ -836,15 +916,24 @@ TelemetryImpl::AsyncFetchTelemetryData(nsIFetchTelemetryDataCallback *aCallback)
   }
 
   // We have to get the filename from the main thread.
-  const char *filename = GetShutdownTimeFileName();
-  if (!filename) {
+  const char *shutdownTimeFilename = GetShutdownTimeFileName();
+  if (!shutdownTimeFilename) {
+    mCachedTelemetryData = true;
+    aCallback->Complete();
+    return NS_OK;
+  }
+
+  nsCOMPtr<nsIFile> failedProfileLockFile;
+  nsresult rv = GetFailedProfileLockFile(getter_AddRefs(failedProfileLockFile));
+  if (NS_FAILED(rv)) {
     mCachedTelemetryData = true;
     aCallback->Complete();
     return NS_OK;
   }
 
   mCallbacks.AppendObject(aCallback);
-  nsCOMPtr<nsIRunnable> event = new nsFetchTelemetryData(filename);
+  nsCOMPtr<nsIRunnable> event = new nsFetchTelemetryData(shutdownTimeFilename,
+                                                         failedProfileLockFile);
 
   targetThread->Dispatch(event, NS_DISPATCH_NORMAL);
   return NS_OK;
@@ -856,7 +945,8 @@ mCanRecord(XRE_GetProcessType() == GeckoProcessType_Default),
 mHashMutex("Telemetry::mHashMutex"),
 mHangReportsMutex("Telemetry::mHangReportsMutex"),
 mCachedTelemetryData(false),
-mLastShutdownTime(0)
+mLastShutdownTime(0),
+mFailedLockCount(0)
 {
   // A whitelist to prevent Telemetry reporting on Addon & Thunderbird DBs
   const char *trackedDBs[] = {
@@ -2278,6 +2368,56 @@ GetStackAndModules(const std::vector<uintptr_t>& aPCs)
   return Ret;
 }
 
+void
+WriteFailedProfileLock(nsIFile* aProfileDir)
+{
+  nsCOMPtr<nsIFile> file;
+  nsresult rv = GetFailedProfileLockFile(getter_AddRefs(file), aProfileDir);
+  NS_ENSURE_SUCCESS_VOID(rv);
+  int64_t fileSize = 0;
+  rv = file->GetFileSize(&fileSize);
+  // It's expected that the file might not exist yet
+  if (NS_FAILED(rv) && rv != NS_ERROR_FILE_NOT_FOUND) {
+    return;
+  }
+  nsCOMPtr<nsIFileStream> fileStream;
+  rv = NS_NewLocalFileStream(getter_AddRefs(fileStream), file,
+                             PR_RDWR | PR_CREATE_FILE, 0640);
+  NS_ENSURE_SUCCESS_VOID(rv);
+  NS_ENSURE_TRUE_VOID(fileSize <= kMaxFailedProfileLockFileSize);
+  unsigned int failedLockCount = 0;
+  if (fileSize > 0) {
+    nsCOMPtr<nsIInputStream> inStream = do_QueryInterface(fileStream);
+    NS_ENSURE_TRUE_VOID(inStream);
+    if (!GetFailedLockCount(inStream, fileSize, failedLockCount)) {
+      failedLockCount = 0;
+    }
+  }
+  ++failedLockCount;
+  nsAutoCString bufStr;
+  bufStr.AppendInt(static_cast<int>(failedLockCount));
+  nsCOMPtr<nsISeekableStream> seekStream = do_QueryInterface(fileStream);
+  NS_ENSURE_TRUE_VOID(seekStream);
+  // If we read in an existing failed lock count, we need to reset the file ptr
+  if (fileSize > 0) {
+    rv = seekStream->Seek(nsISeekableStream::NS_SEEK_SET, 0);
+    NS_ENSURE_SUCCESS_VOID(rv);
+  }
+  nsCOMPtr<nsIOutputStream> outStream = do_QueryInterface(fileStream);
+  uint32_t bytesLeft = bufStr.Length();
+  const char* bytes = bufStr.get();
+  do {
+    uint32_t written = 0;
+    rv = outStream->Write(bytes, bytesLeft, &written);
+    if (NS_FAILED(rv)) {
+      break;
+    }
+    bytes += written;
+    bytesLeft -= written;
+  } while (bytesLeft > 0);
+  seekStream->SetEOF();
+}
+
 } // namespace Telemetry
 } // namespace mozilla
 

toolkit/components/telemetry/Telemetry.h

@@ -167,6 +167,13 @@ void RecordChromeHang(uint32_t duration,
                       ProcessedStack &aStack);
 #endif
 
+/**
+ * Record a failed attempt at locking the user's profile.
+ *
+ * @param aProfileDir The profile directory whose lock attempt failed
+ */
+void WriteFailedProfileLock(nsIFile* aProfileDir);
+
 } // namespace Telemetry
 } // namespace mozilla
 #endif // Telemetry_h__

toolkit/components/telemetry/TelemetryPing.js

@@ -151,6 +151,10 @@ function getSimpleMeasurements() {
   if (shutdownDuration)
     ret.shutdownDuration = shutdownDuration;
 
+  let failedProfileLockCount = Telemetry.failedProfileLockCount;
+  if (failedProfileLockCount)
+    ret.failedProfileLockCount = failedProfileLockCount;
+
   return ret;
 }
 

toolkit/components/telemetry/nsITelemetry.idl

@@ -12,7 +12,7 @@ interface nsIFetchTelemetryDataCallback : nsISupports
   void complete();
 };
 
-[scriptable, uuid(23fdd971-8db1-48ef-b9b3-99dbf60f04dd)]
+[scriptable, uuid(e70ba4cc-7ccd-41fe-a75c-e4042233a8cb)]
 interface nsITelemetry : nsISupports
 {
   /**
@@ -48,6 +48,12 @@ interface nsITelemetry : nsISupports
    */
   readonly attribute uint32_t lastShutdownDuration;
 
+  /**
+   * The number of failed profile lock attempts that have occurred prior to 
+   * successfully locking the profile
+   */
+  readonly attribute uint32_t failedProfileLockCount;
+
   /*
    * An object containing information about slow SQL statements.
    *

toolkit/components/telemetry/tests/unit/test_TelemetryPing.js

@@ -27,6 +27,7 @@ const ADDON_NAME = "Telemetry test addon";
 const ADDON_HISTOGRAM = "addon-histogram";
 const FLASH_VERSION = "1.1.1.1";
 const SHUTDOWN_TIME = 10000;
+const FAILED_PROFILE_LOCK_ATTEMPTS = 2;
 
 // Constants from prio.h for nsIFileOutputStream.init
 const PR_WRONLY = 0x2;
@@ -182,6 +183,14 @@ function checkPayload(request, reason, successfulPings) {
   do_check_eq(payload.simpleMeasurements.shutdownDuration, SHUTDOWN_TIME);
   do_check_eq(payload.simpleMeasurements.savedPings, 1);
 
+  do_check_eq(payload.simpleMeasurements.failedProfileLockCount,
+              FAILED_PROFILE_LOCK_ATTEMPTS);
+  let profileDirectory = Services.dirsvc.get("ProfD", Ci.nsIFile);
+  let failedProfileLocksFile = profileDirectory.clone();
+  failedProfileLocksFile.append("Telemetry.FailedProfileLocks.txt");
+  do_check_true(!failedProfileLocksFile.exists());
+
+
   var isWindows = ("@mozilla.org/windows-registry-key;1" in Components.classes);
   if (isWindows) {
     do_check_true(payload.simpleMeasurements.startupSessionRestoreReadBytes > 0);
@@ -439,6 +448,14 @@ function write_fake_shutdown_file() {
   writeStringToFile(file, contents);
 }
 
+function write_fake_failedprofilelocks_file() {
+  let profileDirectory = Services.dirsvc.get("ProfD", Ci.nsIFile);
+  let file = profileDirectory.clone();
+  file.append("Telemetry.FailedProfileLocks.txt");
+  let contents = "" + FAILED_PROFILE_LOCK_ATTEMPTS;
+  writeStringToFile(file, contents);
+}
+
 function run_test() {
   do_test_pending();
   try {
@@ -453,6 +470,9 @@ function run_test() {
   do_get_profile();
   createAppInfo("xpcshell@tests.mozilla.org", "XPCShell", "1", "1.9.2");
 
+  // Make it look like we've previously failed to lock a profile a couple times.
+  write_fake_failedprofilelocks_file();
+
   // Make it look like we've shutdown before.
   write_fake_shutdown_file();
 

toolkit/xre/nsAppRunner.cpp

@@ -26,6 +26,7 @@
 #include "mozilla/Util.h"
 #include "mozilla/Attributes.h"
 #include "mozilla/Likely.h"
+#include "mozilla/Telemetry.h"
 
 #include "nsAppRunner.h"
 #include "mozilla/AppData.h"
@@ -1709,6 +1710,8 @@ ProfileLockedDialog(nsIFile* aProfileDir, nsIFile* aProfileLocalDir,
   rv = xpcom.Initialize();
   NS_ENSURE_SUCCESS(rv, rv);
 
+  mozilla::Telemetry::WriteFailedProfileLock(aProfileDir);
+
   rv = xpcom.SetWindowCreator(aNative);
   NS_ENSURE_SUCCESS(rv, NS_ERROR_FAILURE);