Skip to content

fix(process_group_manager): standardize ProcessInfoNode logs #609

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
shegazyy wants to merge 1 commit into
base: main
Choose a base branch
from
Open

fix(process_group_manager): standardize ProcessInfoNode logs #609

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
53 changes: 30 additions & 23 deletions score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@
#include <score/assert.hpp>
#include <unistd.h>
#include <cstring>
#include <sstream>

namespace score::mw::lifecycle::internal
{
Expand All @@ -47,7 +48,7 @@ ProcessInfoNode::ProcessInfoNode(configuration::ComponentConfig&& config, Proces
app_profile.alive_supervision.has_value(), "Supervised process did not have alive supervision config");
const uid_t uid = config_.deployment_config.sandbox.uid;

LM_LOG_DEBUG() << "Setting up alive supervision for" << identifier_;
LM_LOG_DEBUG() << "Setting up alive supervision for" << logId();

config_.deployment_config.environmental_variables.add(
"LCM_ALIVE_INTERFACE_PATH", aliveInterfacePath(identifier_));
Expand All @@ -57,11 +58,11 @@ ProcessInfoNode::ProcessInfoNode(configuration::ComponentConfig&& config, Proces

if (!supervision_handle_)
{
LM_LOG_ERROR() << "Failed to set up alive supervision for" << identifier_;
LM_LOG_ERROR() << "Failed to set up alive supervision for" << logId();
}
else
{
LM_LOG_DEBUG() << "Successfully set up alive supervision for" << identifier_;
LM_LOG_DEBUG() << "Successfully set up alive supervision for" << logId();
}
}
}
Expand Down Expand Up @@ -180,7 +181,7 @@ void ProcessInfoNode::unblockSync()

IComponent::RequestResult ProcessInfoNode::tryHandleTermination(int32_t process_status)
{
LM_LOG_DEBUG() << "Process" << identifier_ << "( pid" << pid_ << ") terminated with exit code" << process_status;
LM_LOG_DEBUG() << logId() << "terminated with exit code" << process_status;
exit_code_ = process_status;
IComponent::RequestResult res = {IComponent::RequestState::kWaiting};
ProcessState starting = ProcessState::kStarting;
Expand Down Expand Up @@ -218,8 +219,7 @@ IComponent::RequestResult ProcessInfoNode::tryHandleTermination(int32_t process_
}
else
{
LM_LOG_WARN() << "unexpected termination of process" << identifier_ << "( pid" << pid_ << "exit code"
<< exit_code_ << ")";
LM_LOG_WARN() << "Unexpected termination of" << logId() << "exit code" << exit_code_;
res = score::cpp::make_unexpected(IComponent::ComponentError::kErrorAfterReady);
}
}
Expand Down Expand Up @@ -247,8 +247,8 @@ bool ProcessInfoNode::isSupervised() const

IComponent::RequestResult ProcessInfoNode::startProcess(score::cpp::stop_token stop_token)
{
LM_LOG_DEBUG() << "Starting process (" << identifier_ << ") from executable" << config_.deployment_config.bin_dir
<< "/" << config_.component_properties.binary_name;
LM_LOG_DEBUG() << "Starting" << logId() << "from executable" << config_.deployment_config.bin_dir << "/"
<< config_.component_properties.binary_name;

std::optional<ComponentError> error;
const std::chrono::time_point initial_time = std::chrono::steady_clock::now();
Expand All @@ -264,7 +264,7 @@ IComponent::RequestResult ProcessInfoNode::startProcess(score::cpp::stop_token s
// - Terminating: A termination is in progress (allowed)
if (!setState(score::mw::lifecycle::ProcessState::kIdle))
{
LM_LOG_WARN() << "Starting process" << this << "failed: termination in progress";
LM_LOG_WARN() << "Starting" << logId() << "failed: termination in progress";
error = ComponentError::kErrorBeforeReady;
break;
}
Expand All @@ -278,8 +278,8 @@ IComponent::RequestResult ProcessInfoNode::startProcess(score::cpp::stop_token s
if (osal::OsalReturnType::kSuccess == process_handling_.process_interface_->startProcess(pid_, sync_, config_))
{
const std::chrono::time_point launched_time = std::chrono::steady_clock::now();
LM_LOG_DEBUG() << "startProcess pid" << pid_ << "received for process:" << identifier_ << "( startup time:"
<< std::chrono::round<std::chrono::microseconds>(launched_time - initial_time) << ")";
LM_LOG_DEBUG() << logId() << "started, startup time:"
<< std::chrono::round<std::chrono::microseconds>(launched_time - initial_time);

if (configuration::ApplicationType::StateManager ==
config_.component_properties.application_profile.application_type)
Expand Down Expand Up @@ -314,7 +314,7 @@ IComponent::RequestResult ProcessInfoNode::startProcess(score::cpp::stop_token s
sync_.reset();
}
const std::chrono::time_point finished_time = std::chrono::steady_clock::now();
LM_LOG_DEBUG() << "startProcess for process (" << config_.name << ") done, took"
LM_LOG_DEBUG() << "startProcess for" << logId() << "done, took"
<< std::chrono::round<std::chrono::milliseconds>(finished_time - initial_time);

if (error.has_value())
Expand Down Expand Up @@ -366,6 +366,13 @@ void ProcessInfoNode::setupControlClientChannel()
std::atomic_store(&control_client_channel_, ControlClientChannel::getControlClientChannel(sync_));
}

std::string ProcessInfoNode::logId() const

@NicolasFussberger NicolasFussberger Sep 11, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the idea of having this reusable method.

Currently, though this causes heap allocation on every call which we need to avoid after initialization.
So I think we need to come up with a way that does not require heap after construction

{
std::ostringstream oss;
oss << "Name: " << identifier_ << ", PID: " << pid_;
return oss.str();
}

score::cpp::expected_blank<IComponent::ComponentError> ProcessInfoNode::handleProcessStillStarting(
const score::cpp::stop_token& stop_token)
{
Expand Down Expand Up @@ -406,7 +413,7 @@ score::cpp::expected_blank<IComponent::ComponentError> ProcessInfoNode::handlePr

if (wait_res != osal::OsalReturnType::kSuccess)
{
LM_LOG_ERROR() << "Error Waiting for file";
LM_LOG_ERROR() << "Error waiting for file for" << logId();
}

return (wait_res == osal::OsalReturnType::kSuccess) && (exit_code_ == 0);
Expand All @@ -425,7 +432,7 @@ score::cpp::expected_blank<IComponent::ComponentError> ProcessInfoNode::handlePr
return score::cpp::make_unexpected(ComponentError::kErrorBeforeReady);
}

LM_LOG_WARN() << "Got kRunning timeout for process (" << identifier_ << ")";
LM_LOG_WARN() << "Got kRunning timeout for" << logId();
terminateProcess(stop_token);
return score::cpp::make_unexpected(ComponentError::kActivationTimedOut);
}
Expand Down Expand Up @@ -456,7 +463,7 @@ ProcessInfoNode::handleProcessStarted(const score::cpp::stop_token& stop_token)
return handleProcessAlreadyTerminated();
default: // Error case when pn == -1
// really bad fatal error, should not happen, treat as a failure to set the state & kill the process
LM_LOG_ERROR() << "Could not add PID to map!";
LM_LOG_ERROR() << "Could not add" << logId() << "to process map!";
terminateProcess(stop_token);
return score::cpp::make_unexpected(ComponentError::kErrorBeforeReady);
}
Expand All @@ -466,37 +473,37 @@ void ProcessInfoNode::handleProcessRunning()
{
if (!isReporting())
{
LM_LOG_DEBUG() << "Considered kRunning for Non Reporting Process pid" << pid_ << "(" << identifier_ << ")";
LM_LOG_DEBUG() << "Considered kRunning for non-reporting" << logId();
}
else
{
LM_LOG_DEBUG() << "Got kRunning for pid" << pid_ << "(" << identifier_ << ")";
LM_LOG_DEBUG() << "Got kRunning for" << logId();
}
}

void ProcessInfoNode::terminateProcess(const score::cpp::stop_token& stop_token)
{
LM_LOG_DEBUG() << "terminating process (" << identifier_ << ")";
LM_LOG_DEBUG() << "Terminating" << logId();

if (setState(score::mw::lifecycle::ProcessState::kTerminating))
{
handleTerminationProcess(stop_token);
}
LM_LOG_DEBUG() << "terminateProcess for process (" << identifier_ << ") done";
LM_LOG_DEBUG() << "terminateProcess for" << logId() << "done";
}

void ProcessInfoNode::handleTerminationProcess(const score::cpp::stop_token& stop_token)
{
static_cast<void>(terminator_.init(0U, false));
has_semaphore_.store(true);
LM_LOG_DEBUG() << "Requesting termination of process pid" << pid_ << "(" << identifier_ << ")";
LM_LOG_DEBUG() << "Requesting termination of" << logId();

// handle request termination
if ((process_handling_.process_interface_->requestTermination(pid_) == osal::OsalReturnType::kFail) ||
(terminator_.timedWait(std::chrono::milliseconds(config_.deployment_config.shutdown_timeout_ms)) ==
osal::OsalReturnType::kSuccess))
{
LM_LOG_DEBUG() << "Queuing jobs after regular termination of process (" << identifier_ << ")";
LM_LOG_DEBUG() << "Queuing jobs after regular termination of" << logId();
}
else
{
Expand All @@ -512,12 +519,12 @@ void ProcessInfoNode::handleForcedTermination(const score::cpp::stop_token& stop
{
static_cast<void>(stop_token); // Not yet supported

LM_LOG_WARN() << "Process (" << identifier_ << ") did not respond to SIGTERM, sending SIGKILL";
LM_LOG_WARN() << logId() << "did not respond to SIGTERM, sending SIGKILL";

while ((osal::OsalReturnType::kSuccess == process_handling_.process_interface_->forceTermination(pid_)) &&
(terminator_.timedWait(score::mw::lifecycle::internal::kMaxSigKillDelay) != osal::OsalReturnType::kSuccess))
{
LM_LOG_FATAL() << "Process (" << identifier_ << ") did not respond to SIGKILL!!";
LM_LOG_FATAL() << logId() << "did not respond to SIGKILL!!";
}
}

Expand Down
4 changes: 4 additions & 0 deletions score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@
#include <score/stop_token.hpp>
#include <atomic>
#include <chrono>
#include <string>

namespace score::mw::lifecycle::internal
{
Expand Down Expand Up @@ -173,6 +174,9 @@ class ProcessInfoNode final : public IComponent
/// @brief Creates the ControlClientChannel from the process's IPC comms handle.
void setupControlClientChannel();

/// @brief Returns a standardized identity string for logging, e.g. "Name: my_component, PID: 1234".
[[nodiscard]] std::string logId() const;

/// @brief semaphore used to check termination with timeout
osal::Semaphore terminator_{};

Expand Down
Loading