Merge remote-tracking branch 'upstream/pr/795'

src/DBConnection.cpp

@@ -51,6 +51,11 @@ DBConnection::DBConnection(
 DBConnection::~DBConnection()
 {
    wxASSERT(mDB == nullptr);
+   if (mDB)
+   {
+      wxLogMessage("Database left open at connection destruction %s\n",
+                   sqlite3_db_filename(mDB, nullptr));
+   }
 }
 
 void DBConnection::SetBypass( bool bypass )
@@ -66,18 +71,21 @@ bool DBConnection::ShouldBypass()
 void DBConnection::SetError(
    const TranslatableString &msg, const TranslatableString &libraryError, int errorCode)
 {
-   wxLogMessage(wxT("Connection msg: %s"), msg.Debug());
+   mpErrors->mErrorCode = errorCode;
-   printf("Connection msg: %s", msg.Debug().mb_str().data());
-
-   if (!libraryError.empty())
-   {
-      wxLogMessage(wxT("Connection error: %s"), libraryError.Debug());
-      printf("Connection error: %s", libraryError.Debug().mb_str().data());
-   }
 
    mpErrors->mLastError = msg;
-   mpErrors->mLibraryError = libraryError;
+
-   mpErrors->mErrorCode = errorCode;
+   mpErrors->mLibraryError = errorCode && libraryError.empty()
+      ? XO("(%d): %s").Format(errorCode, sqlite3_errstr(errorCode))
+      : libraryError;
+
+   wxLogMessage("DBConnection SetError\n"
+                "\tErrorCode: %d\n"
+                "\tLastError: %s\n"
+                "\tLibraryError: %s",
+                 mpErrors->mErrorCode,
+                 mpErrors->mLastError.Debug(),
+                 mpErrors->mLibraryError.Debug());
 
    auto logger = AudacityLogger::Get();
    if (logger)
@@ -89,24 +97,27 @@ void DBConnection::SetError(
 void DBConnection::SetDBError(
    const TranslatableString &msg, const TranslatableString &libraryError, int errorCode)
 {
-    mpErrors->mErrorCode = errorCode < 0 ?
+   auto db = DB();
-        sqlite3_errcode(DB()) : errorCode;
 
-   mpErrors->mLastError = msg;
+   mpErrors->mErrorCode = errorCode < 0 && db
+      ? sqlite3_errcode(db)
+      : errorCode;
 
-   wxLogMessage(
+   mpErrors->mLastError = msg.empty()
-       wxT("SQLite error (%d): %s"), 
+      ? XO("(%d): %s").Format(mpErrors->mErrorCode, sqlite3_errstr(mpErrors->mErrorCode))
-       mpErrors->mErrorCode, 
+      : msg;
-       mpErrors->mLastError.Debug()
-   );
 
-   printf("SQLite error: %s", mpErrors->mLastError.Debug().mb_str().data());
+   mpErrors->mLibraryError = libraryError.empty() && db
+      ? Verbatim(sqlite3_errmsg(db))
+      : libraryError;
 
-   mpErrors->mLibraryError = libraryError.empty()
+   wxLogMessage("DBConnection SetDBError\n"
-      ? Verbatim(sqlite3_errmsg(DB())) : libraryError;
+                "\tErrorCode: %d\n"
-
+                "\tLastError: %s\n"
-   wxLogMessage(wxT("   Lib error: %s"), mpErrors->mLibraryError.Debug());
+                "\tLibraryError: %s",
-   printf("   Lib error: %s", mpErrors->mLibraryError.Debug().mb_str().data());
+                 mpErrors->mErrorCode,
+                 mpErrors->mLastError.Debug(),
+                 mpErrors->mLibraryError.Debug());
 
    auto logger = AudacityLogger::Get();
    if (logger)
@@ -115,7 +126,7 @@ void DBConnection::SetDBError(
    }
 }
 
-bool DBConnection::Open(const FilePath fileName)
+int DBConnection::Open(const FilePath fileName)
 {
    wxASSERT(mDB == nullptr);
    int rc;
@@ -123,10 +134,15 @@ bool DBConnection::Open(const FilePath fileName)
    rc = sqlite3_open(fileName.ToUTF8(), &mDB);
    if (rc != SQLITE_OK)
    {
+      wxLogMessage("Failed to open %s: %d, %s\n",
+         fileName,
+         rc,
+         sqlite3_errstr(rc));
+
       sqlite3_close(mDB);
       mDB = nullptr;
 
-      return false;
+      return rc;
    }
 
    // Set default mode
@@ -142,7 +158,7 @@ bool DBConnection::Open(const FilePath fileName)
    // Install our checkpoint hook
    sqlite3_wal_hook(mDB, CheckpointHook, this);
 
-   return mDB;
+   return rc;
 }
 
 bool DBConnection::Close()
@@ -202,8 +218,17 @@ bool DBConnection::Close()
       std::lock_guard<std::mutex> guard(mStatementMutex);
       for (auto stmt : mStatements)
       {
-         // No need to check return code.
+         // No need to process return code, but log it for diagnosis
-         sqlite3_finalize(stmt.second);
+         rc = sqlite3_finalize(stmt.second);
+         if (rc != SQLITE_OK)
+         {
+            wxLogMessage("Failed to finalize statement on %s\n"
+                         "\tErrMsg: %s\n"
+                         "\tSQL: %s",
+                         sqlite3_db_filename(mDB, nullptr), 
+                         sqlite3_errmsg(mDB),
+                         stmt.second);
+         }
       }
       mStatements.clear();
    }
@@ -218,7 +243,11 @@ bool DBConnection::Close()
       // Should we throw an error???
       //
       // LLL: Probably not worthwhile since the DB will just be recovered when
-      // next opened.
+      // next opened, but log it for diagnosis.
+      wxLogMessage("Failed to close %s\n"
+                   "\tError: %s\n",
+                   sqlite3_db_filename(mDB, nullptr),
+                   sqlite3_errmsg(mDB));
    }
 
    mDB = nullptr;
@@ -261,6 +290,16 @@ bool DBConnection::ModeConfig(sqlite3 *db, const char *schema, const char *confi
 
    // Set the configuration
    rc = sqlite3_exec(db, sql, nullptr, nullptr, nullptr);
+   if (rc != SQLITE_OK)
+   {
+      // Don't store in connection, just report it
+      wxLogMessage("Failed to set mode on %s\n"
+                   "\tError: %s\n"
+                   "\tSQL: %s",
+                   sqlite3_db_filename(mDB, nullptr), 
+                   sqlite3_errmsg(mDB),
+                   sql);
+   }
 
    return rc == SQLITE_OK;
 }
@@ -304,7 +343,14 @@ sqlite3_stmt *DBConnection::Prepare(enum StatementID id, const char *sql)
    rc = sqlite3_prepare_v3(mDB, sql, -1, SQLITE_PREPARE_PERSISTENT, &stmt, 0);
    if (rc != SQLITE_OK)
    {
-      wxLogMessage("prepare error %s", sqlite3_errmsg(mDB));
+      wxLogMessage("Failed to prepare statement for %s\n"
+                   "\tError: %s\n"
+                   "\tSQL: %s",
+                   sqlite3_db_filename(mDB, nullptr), 
+                   sqlite3_errmsg(mDB),
+                   sql);
+
+      // TODO: Look into why this causes an access violation
       THROW_INCONSISTENCY_EXCEPTION;
    }
 
@@ -322,9 +368,6 @@ sqlite3_stmt *DBConnection::Prepare(enum StatementID id, const char *sql)
    // Remember the cached statement.
    mStatements.insert({ndx, stmt});
 
-   //Thread Id not convertible to int.
-   //wxLogDebug( "Cached a statement for thread:%i thread:%i ", (int)ndx.first, (int)ndx.second);
-   wxLogDebug( "Cached a statement for %i", (int)id);
    return stmt;
 }
 
@@ -337,7 +380,9 @@ void DBConnection::CheckpointThread()
    sqlite3 *db = nullptr;
    const auto name = sqlite3_db_filename(mDB, nullptr);
    bool giveUp = false;
-   if (sqlite3_open(name, &db) == SQLITE_OK)
+
+   auto rc = sqlite3_open(name, &db);
+   if (rc == SQLITE_OK)
    {
       // Configure it to be safe
       ModeConfig(db, "main", SafeConfig);
@@ -366,7 +411,6 @@ void DBConnection::CheckpointThread()
 
          // And kick off the checkpoint. This may not checkpoint ALL frames
          // in the WAL.  They'll be gotten the next time around.
-         int rc;
          using namespace std::chrono;
          do {
             rc = giveUp ? SQLITE_OK :
@@ -381,12 +425,23 @@ void DBConnection::CheckpointThread()
          // Reset
          mCheckpointActive = false;
 
-         if (rc != SQLITE_OK) {
+         if (rc != SQLITE_OK)
+         {
+            wxLogMessage("Failed to perform checkpoint on %s\n"
+                         "\tErrCode: %d\n"
+                         "\tErrMsg: %s",
+                         name,
+                         sqlite3_errcode(db),
+                         sqlite3_errmsg(db));
+
             // Can't checkpoint -- maybe the device has too little space
             wxFileNameWrapper fName{ name };
             auto path = FileNames::AbbreviatePath(fName);
             auto name = fName.GetFullName();
             auto longname = name + "-wal";
+
+            // TODO: Should we return the actual error message if it's not a
+            // disk full condition?
             auto message1 = rc == SQLITE_FULL
                ? XO("Could not write to %s.\n").Format(path)
                : TranslatableString{};
@@ -416,9 +471,27 @@ void DBConnection::CheckpointThread()
          }
       }
    }
+   else
+   {
+      wxLogMessage("Checkpoint thread failed to open %s\n"
+                   "\tErrCode: %d\n"
+                   "\tErrMsg: %s",
+                   name,
+                   rc,
+                   sqlite3_errstr(rc));
+   }
 
    // All done (always close)
-   sqlite3_close(db);
+   rc = sqlite3_close(db);
+   if (rc != SQLITE_OK)
+   {
+      wxLogMessage("Checkpoint thread failed to close %s\n"
+                   "\tErrCode: %d\n"
+                   "\tErrMsg: %s",
+                   name,
+                   rc,
+                   sqlite3_errstr(rc));
+   }
 
    return;
 }
@@ -526,6 +599,7 @@ TransactionScope::~TransactionScope()
       {
          // Do not throw from a destructor!
          // This has to be a no-fail cleanup that does the best that it can.
+         wxLogMessage("Transaction active at scope destruction");
       }
    }
 }
@@ -533,8 +607,12 @@ TransactionScope::~TransactionScope()
 bool TransactionScope::Commit()
 {
    if ( !mInTrans )
+   {
+      wxLogMessage("No active transaction to commit");
+
       // Misuse of this class
       THROW_INCONSISTENCY_EXCEPTION;
+   }
 
    mInTrans = !TransactionCommit(mName);
 
@@ -544,6 +622,10 @@ bool TransactionScope::Commit()
 ConnectionPtr::~ConnectionPtr()
 {
    wxASSERT_MSG(!mpConnection, wxT("Project file was not closed at shutdown"));
+   if (mpConnection)
+   {
+      wxLogMessage("Project file was not closed at connection destruction");
+   }
 }
 
 static const AudacityProject::AttachedObjects::RegisteredFactory

src/DBConnection.h

@@ -48,7 +48,7 @@ public:
       CheckpointFailureCallback callback);
    ~DBConnection();
 
-   bool Open(const FilePath fileName);
+   int Open(const FilePath fileName);
    bool Close();
 
    //! throw and show appropriate message box

src/ProjectFileIO.cpp

@@ -363,10 +363,14 @@ bool ProjectFileIO::OpenConnection(FilePath fileName /* = {}  */)
    // Pass weak_ptr to project into DBConnection constructor
    curConn = std::make_unique<DBConnection>(
       mProject.shared_from_this(), mpErrors, [this]{ OnCheckpointFailure(); } );
-   if (!curConn->Open(fileName))
+   auto rc = curConn->Open(fileName);
+   if (rc != SQLITE_OK)
    {
-      SetDBError(
+      // Must use SetError() here since we do not have an active DB
-         XO("Failed to open database file:\n\n%s").Format(fileName)
+      SetError(
+         XO("Failed to open database file:\n\n%s").Format(fileName),
+         {},
+         rc
       );
       curConn.reset();
       return false;
@@ -439,7 +443,12 @@ void ProjectFileIO::DiscardConnection()
          wxFileName file(mPrevFileName);
          file.SetFullName(wxT(""));
          if (file == temp)
-            RemoveProject(mPrevFileName);
+         {
+            if (!RemoveProject(mPrevFileName))
+            {
+               wxLogMessage("Failed to remove temporary project %s", mPrevFileName);
+            }
+         }
       }
       mPrevConn = nullptr;
       mPrevFileName.clear();
@@ -717,7 +726,6 @@ bool ProjectFileIO::DeleteBlocks(const BlockIDs &blockids, bool complement)
    {
       /* i18n-hint: An error message.  Don't translate inset or blockids.*/
       SetDBError(XO("Unable to add 'inset' function (can't verify blockids)"));
-      wxLogWarning(GetLastError().Translation());
       return false;
    }
 
@@ -755,7 +763,6 @@ bool ProjectFileIO::DeleteBlocks(const BlockIDs &blockids, bool complement)
          /* i18n-hint: An error message.  Don't translate blockfiles.*/
          SetDBError(XO("Unable to work with the blockfiles"));
 
-      wxLogWarning(GetLastError().Translation());
       return false;
    }
 
@@ -1303,27 +1310,67 @@ void ProjectFileIO::Compact(
                if (wxRenameFile(tempName, origName))
                {
                   // Open the newly compacted original file
-                  OpenConnection(origName);
+                  if (OpenConnection(origName))
+                  {
+                     // Remove the old original file
+                     if (!wxRemoveFile(backName))
+                     {
+                        // Just log the error, nothing can be done to correct it
+                        // and WX should have logged another message showing the
+                        // system error code.
+                        wxLogWarning(wxT("Compaction failed to delete backup %s"), backName);
+                     }
 
-                  // Remove the old original file
+                     // Remember that we compacted
-                  wxRemoveFile(backName);
+                     mWasCompacted = true;
 
-                  // Remember that we compacted
+                     return;
-                  mWasCompacted = true;
+                  }
+                  else
+                  {
+                     wxLogWarning(wxT("Compaction failed to open new project %s"), origName);
+                  }
 
-                  return;
+                  if (!wxRenameFile(origName, tempName))
+                  {
+                     wxLogWarning(wxT("Compaction failed to rename orignal %s to temp %s"),
+                                  origName, tempName);
+                  }
+               }
+               else
+               {
+                  wxLogWarning(wxT("Compaction failed to rename temp %s to orig %s"),
+                                 origName, tempName);
                }
 
-               wxRenameFile(backName, origName);
+               if (!wxRenameFile(backName, origName))
+               {
+                  wxLogWarning(wxT("Compaction failed to rename back %s to orig %s"),
+                               backName, origName);
+               }
+            }
+            else
+            {
+               wxLogWarning(wxT("Compaction failed to rename orig %s to back %s"),
+                              backName, origName);
             }
          }
 
-         OpenConnection(origName);
+         if (!OpenConnection(origName))
+         {
+            wxLogWarning(wxT("Compaction failed to reopen %s"), origName);
+         }
       }
 
       // Did not achieve any real compaction
       // RemoveProject not needed for what was an attached database
-      wxRemoveFile(tempName);
+      if (!wxRemoveFile(tempName))
+      {
+         // Just log the error, nothing can be done to correct it
+         // and WX should have logged another message showing the
+         // system error code.
+         wxLogWarning(wxT("Failed to delete temporary file...ignoring"));
+      }
    }
 
    return;
@@ -1729,7 +1776,10 @@ bool ProjectFileIO::WriteDoc(const char *table,
    if (sqlite3_bind_blob(stmt, 1, dict.GetData(), dict.GetDataLen(), SQLITE_STATIC) ||
        sqlite3_bind_blob(stmt, 2, data.GetData(), data.GetDataLen(), SQLITE_STATIC))
    {
-      wxASSERT_MSG(false, wxT("Binding failed...bug!!!"));
+      SetDBError(
+         XO("Unable to bind to blob")
+      );
+      return false;
    }
 
    rc = sqlite3_step(stmt);
@@ -1976,10 +2026,16 @@ bool ProjectFileIO::SaveProject(
       //       there.
       {
          std::atomic_bool done = {false};
-         bool success = false;
+         bool success = true;
          auto thread = std::thread([&]
          {
-            success = newConn->Open(fileName);
+            auto rc =  newConn->Open(fileName);
+            if (rc != SQLITE_OK)
+            {
+               // Capture the error string
+               SetError(Verbatim(sqlite3_errstr(rc)));
+               success = false;
+            }
             done = true;
          });
 
@@ -2002,15 +2058,18 @@ bool ProjectFileIO::SaveProject(
          {
             // Additional help via a Help button links to the manual.
             ShowError(nullptr,
-                           XO("Error Saving Project"),
+                      XO("Error Saving Project"),
-                           XO("The project failed to open, possibly due to limited space\n"
+                      XO("The project failed to open, possibly due to limited space\n"
-                              "on the storage device.\n\n%s").Format(GetLastError()),
+                         "on the storage device.\n\n%s").Format(GetLastError()),
-                           "Error:_Disk_full_or_not_writable");
+                      "Error:_Disk_full_or_not_writable");
 
             newConn = nullptr;
 
             // Clean up the destination project
-            wxRemoveFile(fileName);
+            if (!wxRemoveFile(fileName))
+            {
+               wxLogMessage("Failed to remove destination project after open failure: %s", fileName);
+            }
 
             return false;
          }
@@ -2021,15 +2080,18 @@ bool ProjectFileIO::SaveProject(
       {
          // Additional help via a Help button links to the manual.
          ShowError(nullptr,
-                        XO("Error Saving Project"),
+                   XO("Error Saving Project"),
-                        XO("Unable to remove autosave information, possibly due to limited space\n"
+                   XO("Unable to remove autosave information, possibly due to limited space\n"
-                           "on the storage device.\n\n%s").Format(GetLastError()),
+                      "on the storage device.\n\n%s").Format(GetLastError()),
-                        "Error:_Disk_full_or_not_writable");
+                  "Error:_Disk_full_or_not_writable");
 
          newConn = nullptr;
 
          // Clean up the destination project
-         wxRemoveFile(fileName);
+         if (!wxRemoveFile(fileName))
+         {
+            wxLogMessage("Failed to remove destination project after AutoSaveDelete failure: %s", fileName);
+         }
 
          return false;
       }
@@ -2039,6 +2101,7 @@ bool ProjectFileIO::SaveProject(
          bool recovered = mRecovered;
          SampleBlockIDSet blockids;
          InspectBlocks( *lastSaved, {}, &blockids );
+         // TODO: Not sure what to do if the deletion fails
          DeleteBlocks(blockids, true);
          // Don't set mRecovered if any were deleted
          mRecovered = recovered;