smw/deskflow
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

refactor(daemon): More helpful and less noisy logging

Browse source
This commit is contained in:
Nick Bolton 2025-03-14 11:31:24 +00:00
parent e8ea9f53ee
commit 16517ca541
6 changed files with 69 additions and 61 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
src/lib/arch/win32/ArchDaemonWindows.cpp
View file

@ -350,6 +350,8 @@ void ArchDaemonWindows::setStatus(DWORD state, DWORD step, DWORD waitHint)
{
assert(s_daemon != NULL);
LOG_DEBUG("setting service status: state=%d, step=%d, waitHint=%d", state, step, waitHint);
SERVICE_STATUS status;
status.dwServiceType = SERVICE_WIN32_OWN_PROCESS | SERVICE_INTERACTIVE_PROCESS;
status.dwCurrentState = state;

15
src/lib/deskflow/DaemonApp.cpp
View file

@ -55,20 +55,20 @@ void DaemonApp::saveLogLevel(const QString &logLevel) const
// saves setting for next time the daemon starts.
ARCH->setting("LogLevel", logLevel.toStdString());
} catch (XArch &e) {
LOG((CLOG_ERR "failed to save log level setting: %s", e.what()));
LOG_ERR("failed to save log level setting: %s", e.what());
}
}
void DaemonApp::setElevate(bool elevate)
{
LOG((CLOG_DEBUG "elevate value changed: %s", elevate ? "yes" : "no"));
LOG_DEBUG("elevate value changed: %s", elevate ? "yes" : "no");
m_elevate = elevate;
try {
// saves setting for next time the daemon starts.
ARCH->setting("Elevate", std::string(elevate ? "1" : "0"));
} catch (XArch &e) {
LOG((CLOG_ERR "failed to save elevate setting: %s", e.what()));
LOG_ERR("failed to save elevate setting: %s", e.what());
}
}
@ -81,7 +81,7 @@ void DaemonApp::setCommand(const QString &command)
// saves setting for next time the daemon starts.
ARCH->setting("Command", command.toStdString());
} catch (XArch &e) {
LOG((CLOG_ERR "failed to save command setting: %s", e.what()));
LOG_ERR("failed to save command setting: %s", e.what());
}
}
@ -230,21 +230,22 @@ int DaemonApp::mainLoop()
LOG_INFO("daemon is running");
m_events.loop();
LOG_INFO("daemon is stopping");
} catch (std::exception &e) { // NOSONAR - Catching all exceptions
LOG((CLOG_CRIT "daemon error: %s", e.what()));
} catch (...) { // NOSONAR - Catching remaining exceptions
LOG((CLOG_CRIT "daemon unknown error"));
}
LOG_INFO("daemon is stopping");
#if SYSAPI_WIN32
try {
LOG_DEBUG("stopping process watchdog");
m_pWatchdog->stop();
} catch (std::exception &e) { // NOSONAR - Catching all exceptions
LOG((CLOG_CRIT "stop watchdog error: %s", e.what()));
LOG((CLOG_CRIT "daemon stop watchdog error: %s", e.what()));
} catch (...) { // NOSONAR - Catching remaining exceptions
LOG((CLOG_CRIT "stop watchdog unknown error"));
LOG((CLOG_CRIT "daemon stop watchdog unknown error"));
}
#endif

2
src/lib/gui/core/CoreProcess.cpp
View file

@ -191,7 +191,7 @@ void CoreProcess::daemonIpcClientConnected()
m_daemonFileTail->deleteLater();
}
qInfo() << "daemon log path:" << logPath;
qDebug() << "daemon log path:" << logPath;
m_daemonFileTail = new FileTail(logPath, this);
connect(m_daemonFileTail, &FileTail::newLine, this, &CoreProcess::handleLogLines);
}

42
src/lib/gui/ipc/DaemonIpcClient.cpp
View file

@ -27,21 +27,21 @@ DaemonIpcClient::DaemonIpcClient(QObject *parent)
bool DaemonIpcClient::connectToServer()
{
qInfo("connecting to daemon ipc");
qDebug() << "daemon ipc client connecting to server:" << kDaemonIpcName;
m_socket->connectToServer(kDaemonIpcName);
if (!m_socket->waitForConnected(kTimeout)) {
qWarning() << "ipc client failed to connect to server:" << kDaemonIpcName;
qWarning() << "daemon ipc client failed to connect";
return false;
}
if (!sendMessage("hello", "hello", false)) {
qWarning() << "ipc client failed to send hello";
qWarning() << "daemon ipc client failed to send hello";
return false;
}
m_connected = true;
qInfo() << "ipc client connected to server:" << kDaemonIpcName;
qDebug() << "daemon ipc client connected";
Q_EMIT connected();
return true;
@ -49,17 +49,17 @@ bool DaemonIpcClient::connectToServer()
void DaemonIpcClient::handleDisconnected()
{
qWarning() << "ipc client disconnected from server";
qWarning() << "daemon ipc client disconnected from server";
m_connected = false;
if (!connectToServer()) {
qWarning() << "ipc client failed to reconnect to server";
qWarning() << "daemon ipc client failed to reconnect to server";
}
}
void DaemonIpcClient::handleErrorOccurred()
{
qWarning() << "ipc client error:" << m_socket->errorString();
qWarning() << "daemon ipc client error:" << m_socket->errorString();
m_connected = false;
}
@ -73,49 +73,49 @@ bool DaemonIpcClient::sendMessage(const QString &message, const QString &expectA
QByteArray messageData = message.toUtf8() + "\n";
m_socket->write(messageData);
if (!m_socket->waitForBytesWritten(kTimeout)) {
qWarning() << "ipc client failed to write command";
qWarning() << "daemon ipc client failed to write command";
return false;
}
if (!expectAck.isEmpty()) {
qDebug() << "ipc client waiting for ack: " << expectAck;
qDebug() << "daemon ipc client waiting for ack: " << expectAck;
if (!m_socket->waitForReadyRead(kTimeout)) {
qWarning() << "ipc client failed to read response";
qWarning() << "daemon ipc client failed to read response";
return false;
}
QByteArray response = m_socket->readAll();
if (response.isEmpty()) {
qWarning() << "ipc client got empty response";
qWarning() << "daemon ipc client got empty response";
return false;
}
QString responseData = QString::fromUtf8(response);
if (responseData.isEmpty()) {
qWarning() << "ipc client failed to convert response to string";
qWarning() << "daemon ipc client failed to convert response to string";
return false;
}
if (responseData != expectAck + "\n") {
qWarning() << "ipc client got unexpected response: " << responseData;
qWarning() << "daemon ipc client got unexpected response: " << responseData;
return false;
}
}
qDebug() << "ipc client sent message: " << messageData;
qDebug() << "daemon ipc client sent message: " << messageData;
return true;
}
bool DaemonIpcClient::keepAlive()
{
if (!isConnected() && !connectToServer()) {
qWarning() << "ipc client keep alive failed to connect";
qWarning() << "daemon ipc client keep alive failed to connect";
return false;
}
if (!sendMessage("noop")) {
qWarning() << "ipc client keep alive ping failed";
qWarning() << "daemon ipc client keep alive ping failed";
m_connected = false;
return false;
}
@ -164,31 +164,31 @@ QString DaemonIpcClient::requestLogPath()
}
if (!m_socket->waitForReadyRead(kTimeout)) {
qWarning() << "ipc client failed to read log path response";
qWarning() << "daemon ipc client failed to read log path response";
return QString();
}
QByteArray response = m_socket->readAll();
if (response.isEmpty()) {
qWarning() << "ipc client got empty log path response";
qWarning() << "daemon ipc client got empty log path response";
return QString();
}
QString responseData = QString::fromUtf8(response);
if (responseData.isEmpty()) {
qWarning() << "ipc client failed to convert log path response to string";
qWarning() << "daemon ipc client failed to convert log path response to string";
return QString();
}
// Trimming removes newline from end of message.
QStringList parts = responseData.trimmed().split("=");
if (parts.size() != 2) {
qWarning() << "ipc client got invalid log path response: " << responseData;
qWarning() << "daemon ipc client got invalid log path response: " << responseData;
return QString();
}
if (parts[0] != "logPath") {
qWarning() << "ipc client got unexpected log path response: " << responseData;
qWarning() << "daemon ipc client got unexpected log path response: " << responseData;
return QString();
}

2
src/lib/platform/MSWindowsProcess.cpp
View file

@ -90,7 +90,7 @@ DWORD MSWindowsProcess::waitForExit()
{
const auto kMaxWaitMilliseconds = 10000;
LOG_INFO("waiting for process to exit, pid: %lu", m_info.dwProcessId);
LOG_DEBUG("waiting for process to exit, pid: %lu", m_info.dwProcessId);
if (WaitForSingleObject(m_info.hProcess, kMaxWaitMilliseconds) != WAIT_OBJECT_0) {
LOG_ERR("process did not exit within the expected time");
TerminateProcess(m_info.hProcess, 1);

67
src/lib/platform/MSWindowsWatchdog.cpp
View file

@ -62,7 +62,7 @@ HANDLE openProcessForKill(const PROCESSENTRY32 &entry)
HANDLE handle = OpenProcess(PROCESS_ALL_ACCESS, FALSE, entry.th32ProcessID);
if (handle == nullptr) {
LOG((CLOG_ERR "could not open process handle for kill"));
LOG_ERR("could not open process handle for kill");
throw XArch(new XArchEvalWindows);
}
@ -101,15 +101,15 @@ void MSWindowsWatchdog::stop()
m_running = false;
if (!m_mainThread->wait(kThreadWaitSeconds)) {
LOG((CLOG_WARN "could not stop main thread"));
LOG_WARN("could not stop main thread");
}
if (!m_outputThread->wait(kThreadWaitSeconds)) {
LOG((CLOG_WARN "could not stop output thread"));
LOG_WARN("could not stop output thread");
}
if (!m_sasThread->wait(kThreadWaitSeconds)) {
LOG((CLOG_WARN "could not stop sas thread"));
LOG_WARN("could not stop sas thread");
}
}
@ -121,11 +121,11 @@ MSWindowsWatchdog::duplicateProcessToken(HANDLE process, LPSECURITY_ATTRIBUTES s
BOOL tokenRet = OpenProcessToken(process, TOKEN_ASSIGN_PRIMARY | TOKEN_ALL_ACCESS, &sourceToken);
if (!tokenRet) {
LOG((CLOG_ERR "could not open token, process handle: %d", process));
LOG_ERR("could not open token, process handle: %d", process);
throw XArch(new XArchEvalWindows());
}
LOG((CLOG_DEBUG "got token %i, duplicating", sourceToken));
LOG_DEBUG("got token %i, duplicating", sourceToken);
HANDLE newToken;
BOOL duplicateRet = DuplicateTokenEx(
@ -133,11 +133,11 @@ MSWindowsWatchdog::duplicateProcessToken(HANDLE process, LPSECURITY_ATTRIBUTES s
);
if (!duplicateRet) {
LOG((CLOG_ERR "could not duplicate token %i", sourceToken));
LOG_ERR("could not duplicate token %i", sourceToken);
throw XArch(new XArchEvalWindows());
}
LOG((CLOG_DEBUG "duplicated, new token: %i", newToken));
LOG_DEBUG("duplicated, new token: %i", newToken);
return newToken;
}
@ -152,7 +152,7 @@ MSWindowsWatchdog::getUserToken(LPSECURITY_ATTRIBUTES security, bool elevatedTok
// and so would be unusable with the new elevated process taking focus.
if (elevatedToken || m_session.isProcessInSession("logonui.exe", nullptr)) {
LOG((CLOG_DEBUG "getting elevated token, %s", (elevatedToken ? "elevation required" : "at login screen")));
LOG_DEBUG("getting elevated token, %s", (elevatedToken ? "elevation required" : "at login screen"));
HANDLE process;
if (!m_session.isProcessInSession("winlogon.exe", &process)) {
@ -167,7 +167,7 @@ MSWindowsWatchdog::getUserToken(LPSECURITY_ATTRIBUTES security, bool elevatedTok
throw e;
}
} else {
LOG((CLOG_DEBUG "getting non-elevated token"));
LOG_DEBUG("getting non-elevated token");
return m_session.getUserToken(security);
}
}
@ -178,6 +178,7 @@ void MSWindowsWatchdog::mainLoop(void *)
LOG_DEBUG("starting watchdog main loop");
while (m_running) {
LOG_DEBUG3("locking process state mutex in watchdog main loop");
std::unique_lock lock(m_processStateMutex);
if (!m_command.empty() && !m_foreground && m_session.hasChanged()) {
@ -190,11 +191,11 @@ void MSWindowsWatchdog::mainLoop(void *)
using enum ProcessState;
case Idle:
LOG_DEBUG3("watchdog: process idle");
LOG_DEBUG3("watchdog process state idle");
break;
case StartScheduled: {
LOG_DEBUG3("watchdog: process start scheduled");
LOG_DEBUG3("watchdog process start scheduled");
if (m_nextStartTime.has_value() && m_nextStartTime.value() <= ARCH->time()) {
LOG_DEBUG("start time reached, queueing process start");
m_processState = StartPending;
@ -202,7 +203,7 @@ void MSWindowsWatchdog::mainLoop(void *)
} break;
case StartPending: {
LOG_INFO("daemon starting new process");
LOG_DEBUG("watchdog starting new process");
try {
startProcess();
m_startFailures = 0;
@ -217,15 +218,15 @@ void MSWindowsWatchdog::mainLoop(void *)
} break;
case Running: {
LOG_DEBUG3("watchdog: process running");
LOG_DEBUG3("watchdog process in running state");
if (!isProcessRunning()) {
LOG((CLOG_WARN "detected application not running, pid=%d", m_process->info().dwProcessId));
LOG_WARN("detected application not running, pid=%d", m_process->info().dwProcessId);
m_processState = StartPending;
}
} break;
case StopPending: {
LOG_INFO("stopping running process");
LOG_DEBUG("watchdog stopping current process");
if (m_process != nullptr) {
m_process->shutdown();
m_process.reset();
@ -237,16 +238,18 @@ void MSWindowsWatchdog::mainLoop(void *)
} break;
}
LOG_DEBUG3("unlocking process state mutex in watchdog main loop");
lock.unlock();
// Sleep for only 100ms rather than 1 second so that the service can shut down faster.
LOG_DEBUG3("watchdog main loop sleeping");
ARCH->sleep(0.1);
}
LOG_DEBUG("watchdog main loop finished");
if (m_process != nullptr) {
LOG((CLOG_DEBUG "terminated running process on exit"));
LOG_DEBUG("terminated running process on exit");
m_process->shutdown();
m_process.reset();
}
@ -272,7 +275,7 @@ void MSWindowsWatchdog::startProcess()
}
if (m_process != nullptr) {
LOG((CLOG_DEBUG "closing existing process to make way for new one"));
LOG_DEBUG("closing existing process to make way for new one");
m_process->shutdown();
m_process.reset();
}
@ -305,14 +308,13 @@ void MSWindowsWatchdog::startProcess()
}
if (!createRet) {
LOG((CLOG_CRIT "could not launch command"));
DWORD exitCode = 0;
GetExitCodeProcess(m_process->info().hProcess, &exitCode);
LOG((CLOG_ERR "exit code: %d", exitCode));
LOG_ERR("daemon failed to run command, exit code: %d", exitCode);
throw XArch(new XArchEvalWindows);
} else {
// Wait for program to fail. This needs to be 1 second, as the process may take some time to fail.
LOG_DEBUG("waiting for process start result");
LOG_DEBUG("watchdog waiting for process start result");
ARCH->sleep(1);
if (!isProcessRunning()) {
@ -320,19 +322,20 @@ void MSWindowsWatchdog::startProcess()
throw XArch("process immediately stopped");
}
LOG((CLOG_DEBUG "started core process from daemon"));
LOG(
(CLOG_DEBUG2 "process info, session=%i, elevated: %s, command=%s", m_session.getActiveSessionId(),
m_elevateProcess ? "yes" : "no", m_command.c_str())
LOG_DEBUG("started core process from watchdog");
LOG_DEBUG2(
"process info, session=%i, elevated=%s, command: %s", //
m_session.getActiveSessionId(), m_elevateProcess ? "yes" : "no", m_command.c_str()
);
}
}
void MSWindowsWatchdog::setProcessConfig(const std::string_view &command, bool elevate)
{
LOG_DEBUG("updating watchdog process config");
LOG_DEBUG1("locking process state mutex for watchdog config change");
std::lock_guard lock(m_processStateMutex);
LOG_DEBUG("setting watchdog process config");
m_command = command;
m_elevateProcess = elevate;
@ -390,7 +393,7 @@ void MSWindowsWatchdog::shutdownExistingProcesses()
// first we need to take a snapshot of the running processes
HANDLE snapshot = CreateToolhelp32Snapshot(TH32CS_SNAPPROCESS, kAllProcesses);
if (snapshot == INVALID_HANDLE_VALUE) {
LOG((CLOG_ERR "could not get process snapshot"));
LOG_ERR("could not get process snapshot");
throw XArch(new XArchEvalWindows);
}
@ -401,7 +404,7 @@ void MSWindowsWatchdog::shutdownExistingProcesses()
// unlikely we can go any further
BOOL gotEntry = Process32First(snapshot, &entry);
if (!gotEntry) {
LOG((CLOG_ERR "could not get first process entry"));
LOG_ERR("could not get first process entry");
throw XArch(new XArchEvalWindows);
}
@ -409,7 +412,7 @@ void MSWindowsWatchdog::shutdownExistingProcesses()
while (gotEntry) {
if (HANDLE handle = openProcessForKill(entry); handle != nullptr) {
LOG((CLOG_INFO "shutting down process, name=%s, pid=%d", entry.szExeFile, entry.th32ProcessID));
LOG_DEBUG("shutting down process, name=%s, pid=%d", entry.szExeFile, entry.th32ProcessID);
deskflow::platform::MSWindowsProcess::shutdown(handle, entry.th32ProcessID);
CloseHandle(handle);
}
@ -422,7 +425,7 @@ void MSWindowsWatchdog::shutdownExistingProcesses()
if (err != ERROR_NO_MORE_FILES) {
// only worry about error if it's not the end of the snapshot
LOG((CLOG_ERR "could not get next process entry"));
LOG_ERR("could not get next process entry");
throw XArch(new XArchEvalWindows);
}
}
@ -558,13 +561,15 @@ void MSWindowsWatchdog::initSasFunc()
void MSWindowsWatchdog::sasLoop(void *) // NOSONAR - Thread entry point signature
{
LOG_DEBUG3("watchdog creating sas event");
if (m_sendSasFunc == nullptr) {
throw XArch("SendSAS function not initialized");
}
while (m_running) {
if (m_processState != ProcessState::Running) {
LOG_DEBUG2("watchdog: not running, skipping SendSAS");
LOG_DEBUG2("watchdog not running, skipping SendSAS");
ARCH->sleep(1);
continue;
}