commit 0a66b935c728292b03d0e606483ac351cfeddb10
parent f66e3301faa1359e75327d79d36e82dd1b33c17d
Author: JohnMcPMS <johnmcp@microsoft.com>
Date: Tue, 26 Jul 2022 16:21:38 -0700
Logging improvements (#2378)
Add a connection identifier and log it when opening the connection and with each statement. This makes it somewhat easier to follow the (extremely) verbose SQLite logging.
Also changes the file logger to append by default, enabling logging to the same file repeatedly a possibility (a util scenario mostly).
Diffstat:
4 files changed, 29 insertions(+), 9 deletions(-)
diff --git a/.github/actions/spelling/expect.txt b/.github/actions/spelling/expect.txt
@@ -296,6 +296,7 @@ NX
objbase
objidl
ofile
+openmode
Outptr
packageinuse
PARAMETERMAP
diff --git a/src/AppInstallerCommonCore/FileLogger.cpp b/src/AppInstallerCommonCore/FileLogger.cpp
@@ -15,6 +15,7 @@ namespace AppInstaller::Logging
static constexpr std::string_view s_fileLoggerDefaultFilePrefix = "WinGet"sv;
static constexpr std::string_view s_fileLoggerDefaultFileExt = ".log"sv;
+ static constexpr std::ios_base::openmode s_fileLoggerDefaultOpenMode = std::ios_base::out | std::ios_base::app;
FileLogger::FileLogger() : FileLogger(s_fileLoggerDefaultFilePrefix) {}
@@ -23,7 +24,7 @@ namespace AppInstaller::Logging
m_name = GetNameForPath(filePath);
m_filePath = filePath;
- m_stream.open(m_filePath);
+ m_stream.open(m_filePath, s_fileLoggerDefaultOpenMode);
}
FileLogger::FileLogger(const std::string_view fileNamePrefix)
@@ -32,7 +33,7 @@ namespace AppInstaller::Logging
m_filePath = Runtime::GetPathTo(Runtime::PathName::DefaultLogLocation);
m_filePath /= fileNamePrefix.data() + ('-' + Utility::GetCurrentTimeForFilename() + s_fileLoggerDefaultFileExt.data());
- m_stream.open(m_filePath);
+ m_stream.open(m_filePath, s_fileLoggerDefaultOpenMode);
}
FileLogger::~FileLogger()
diff --git a/src/AppInstallerRepositoryCore/SQLiteWrapper.cpp b/src/AppInstallerRepositoryCore/SQLiteWrapper.cpp
@@ -37,6 +37,12 @@ namespace AppInstaller::Repository::SQLite
namespace
{
+ size_t GetNextConnectionId()
+ {
+ static std::atomic_size_t connectionId(0);
+ return ++connectionId;
+ }
+
size_t GetNextStatementId()
{
static std::atomic_size_t statementId(0);
@@ -141,7 +147,8 @@ namespace AppInstaller::Repository::SQLite
Connection::Connection(const std::string& target, OpenDisposition disposition, OpenFlags flags)
{
- AICLI_LOG(SQL, Info, << "Opening SQLite connection: '" << target << "' [" << std::hex << static_cast<int>(disposition) << ", " << std::hex << static_cast<int>(flags) << "]");
+ m_id = GetNextConnectionId();
+ AICLI_LOG(SQL, Info, << "Opening SQLite connection #" << m_id << ": '" << target << "' [" << std::hex << static_cast<int>(disposition) << ", " << std::hex << static_cast<int>(flags) << "]");
// Always force connection serialization until we determine that there are situations where it is not needed
int resultingFlags = static_cast<int>(disposition) | static_cast<int>(flags) | SQLITE_OPEN_FULLMUTEX;
THROW_IF_SQLITE_FAILED(sqlite3_open_v2(target.c_str(), &m_dbconn, resultingFlags, nullptr), nullptr);
@@ -172,10 +179,16 @@ namespace AppInstaller::Repository::SQLite
return sqlite3_changes(m_dbconn.get());
}
+ size_t Connection::GetID() const
+ {
+ return m_id;
+ }
+
Statement::Statement(const Connection& connection, std::string_view sql)
{
+ m_connectionId = connection.GetID();
m_id = GetNextStatementId();
- AICLI_LOG(SQL, Verbose, << "Preparing statement #" << m_id << ": " << sql);
+ AICLI_LOG(SQL, Verbose, << "Preparing statement #" << m_connectionId << '-' << m_id << ": " << sql);
// SQL string size should include the null terminator (https://www.sqlite.org/c3ref/prepare.html)
assert(sql.data()[sql.size()] == '\0');
THROW_IF_SQLITE_FAILED(sqlite3_prepare_v2(connection, sql.data(), static_cast<int>(sql.size() + 1), &m_stmt, nullptr), connection);
@@ -241,18 +254,18 @@ namespace AppInstaller::Repository::SQLite
bool Statement::Step(bool failFastOnError)
{
- AICLI_LOG(SQL, Verbose, << "Stepping statement #" << m_id);
+ AICLI_LOG(SQL, Verbose, << "Stepping statement #" << m_connectionId << '-' << m_id);
int result = sqlite3_step(m_stmt.get());
if (result == SQLITE_ROW)
{
- AICLI_LOG(SQL, Verbose, << "Statement #" << m_id << " has data");
+ AICLI_LOG(SQL, Verbose, << "Statement #" << m_connectionId << '-' << m_id << " has data");
m_state = State::HasRow;
return true;
}
else if (result == SQLITE_DONE)
{
- AICLI_LOG(SQL, Verbose, << "Statement #" << m_id << " has completed");
+ AICLI_LOG(SQL, Verbose, << "Statement #" << m_connectionId << '-' << m_id << " has completed");
m_state = State::Completed;
return false;
}
@@ -283,7 +296,7 @@ namespace AppInstaller::Repository::SQLite
void Statement::Reset()
{
- AICLI_LOG(SQL, Verbose, << "Reset statement #" << m_id);
+ AICLI_LOG(SQL, Verbose, << "Reset statement #" << m_connectionId << '-' << m_id);
// Ignore return value from reset, as if it is an error, it was the error from the last call to step.
sqlite3_reset(m_stmt.get());
m_state = State::Prepared;
diff --git a/src/AppInstallerRepositoryCore/SQLiteWrapper.h b/src/AppInstallerRepositoryCore/SQLiteWrapper.h
@@ -177,11 +177,15 @@ namespace AppInstaller::Repository::SQLite
// Gets the count of changed rows for the last executed statement.
int GetChanges() const;
+ //. Gets the (fixed but arbitrary) identifier for this connection.
+ size_t GetID() const;
+
operator sqlite3* () const { return m_dbconn.get(); }
private:
Connection(const std::string& target, OpenDisposition disposition, OpenFlags flags);
+ size_t m_id = 0;
wil::unique_any<sqlite3*, decltype(sqlite3_close_v2), sqlite3_close_v2> m_dbconn;
};
@@ -223,7 +227,7 @@ namespace AppInstaller::Repository::SQLite
template <typename Value>
void Bind(int index, Value&& v)
{
- AICLI_LOG(SQL, Verbose, << "Binding statement #" << m_id << ": " << index << " => " << details::ParameterSpecifics<Value>::ToLog(std::forward<Value>(v)));
+ AICLI_LOG(SQL, Verbose, << "Binding statement #" << m_connectionId << '-' << m_id << ": " << index << " => " << details::ParameterSpecifics<Value>::ToLog(std::forward<Value>(v)));
details::ParameterSpecifics<Value>::Bind(m_stmt.get(), index, std::forward<Value>(v));
}
@@ -278,6 +282,7 @@ namespace AppInstaller::Repository::SQLite
return std::make_tuple(details::ParameterSpecifics<Values>::GetColumn(m_stmt.get(), I)...);
}
+ size_t m_connectionId = 0;
size_t m_id = 0;
wil::unique_any<sqlite3_stmt*, decltype(sqlite3_finalize), sqlite3_finalize> m_stmt;
State m_state = State::Prepared;
