diff --git a/src/lib/arch/win32/ArchDaemonWindows.cpp b/src/lib/arch/win32/ArchDaemonWindows.cpp index 733d36735..334f2b465 100644 --- a/src/lib/arch/win32/ArchDaemonWindows.cpp +++ b/src/lib/arch/win32/ArchDaemonWindows.cpp @@ -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; diff --git a/src/lib/deskflow/DaemonApp.cpp b/src/lib/deskflow/DaemonApp.cpp index 0a0bf153e..cd7cfb95c 100644 --- a/src/lib/deskflow/DaemonApp.cpp +++ b/src/lib/deskflow/DaemonApp.cpp @@ -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 diff --git a/src/lib/gui/core/CoreProcess.cpp b/src/lib/gui/core/CoreProcess.cpp index 86a71e815..335869516 100644 --- a/src/lib/gui/core/CoreProcess.cpp +++ b/src/lib/gui/core/CoreProcess.cpp @@ -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); } diff --git a/src/lib/gui/ipc/DaemonIpcClient.cpp b/src/lib/gui/ipc/DaemonIpcClient.cpp index c0cd7f083..456daf2ee 100644 --- a/src/lib/gui/ipc/DaemonIpcClient.cpp +++ b/src/lib/gui/ipc/DaemonIpcClient.cpp @@ -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(); } diff --git a/src/lib/platform/MSWindowsProcess.cpp b/src/lib/platform/MSWindowsProcess.cpp index 39ca0582e..402a885a4 100644 --- a/src/lib/platform/MSWindowsProcess.cpp +++ b/src/lib/platform/MSWindowsProcess.cpp @@ -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); diff --git a/src/lib/platform/MSWindowsWatchdog.cpp b/src/lib/platform/MSWindowsWatchdog.cpp index 788efa3ed..d982e6b3b 100644 --- a/src/lib/platform/MSWindowsWatchdog.cpp +++ b/src/lib/platform/MSWindowsWatchdog.cpp @@ -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; }