Skip to content
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.

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

[SDL-0117] Configurable time before shutdown #3740

Open
wants to merge 4 commits into
base: develop
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 1 commit
Commits
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
1 change: 1 addition & 0 deletions src/appMain/main.cc
Original file line number Diff line number Diff line change
Expand Up @@ -162,6 +162,7 @@ int32_t main(int32_t argc, char** argv) {
#endif // LOG4CXX_LOGGER

Choose a reason for hiding this comment

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

it is marked "not ready for review" in the PR summary , is that correct?

Choose a reason for hiding this comment

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

This means the PR is not ready for the Project Maintainer review.

Copy link

@yang1070 yang1070 Jul 27, 2021

Choose a reason for hiding this comment

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

@KhrystynaDubovyk got it, thank you


logger_impl->Init(std::move(logger));
logger_impl->InitLoggerSettings(&profile_instance);
}
#endif

Expand Down
6 changes: 6 additions & 0 deletions src/appMain/smartDeviceLink.ini
Original file line number Diff line number Diff line change
Expand Up @@ -411,3 +411,9 @@ RpcPassThroughTimeout = 10000
[RCModuleConsent]
; The period (in days) after which consent for module_id should be removed.
PeriodForConsentExpiration = 30

[Logger]
; Write all logs in queue to file system before shutdown

Choose a reason for hiding this comment

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

the comment "write all logs in queue" may not be correct, and it is misleading

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Fixed

FlushLogMessagesBeforeShutdown = false
; Maximum time to wait for writing all data before exit SDL in seconds
ShobhitAd marked this conversation as resolved.
Show resolved Hide resolved
MaxTimeBeforeShutdown = 30
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@
#include <signal.h>
#include <sys/types.h>
#include <unistd.h>
#include <chrono>

#include "application_manager/application_manager.h"
#include "application_manager/resumption/resume_ctrl.h"
Expand Down Expand Up @@ -104,6 +105,8 @@ void OnExitAllApplicationsNotification::Run() {
mob_reason) {
application_manager_.HeadUnitReset(mob_reason);
}

SDL_INIT_FLUSH_LOGS_TIME_POINT(std::chrono::system_clock::now());
kill(getpid(), SIGINT);
}

Expand Down
18 changes: 17 additions & 1 deletion src/components/config_profile/include/config_profile/profile.h
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,7 @@
#include "protocol_handler/protocol_handler_settings.h"
#include "smart_objects/smart_object.h"
#include "transport_manager/transport_manager_settings.h"
#include "utils/logger/logger_settings.h"
#include "utils/macro.h"

namespace profile {
Expand All @@ -59,7 +60,8 @@ class Profile : public protocol_handler::ProtocolHandlerSettings,
public media_manager::MediaManagerSettings,
public policy::PolicySettings,
public transport_manager::TransportManagerSettings,
public application_manager::ApplicationManagerSettings {
public application_manager::ApplicationManagerSettings,
public logger::LoggerSettings {
public:
// Methods section

Expand Down Expand Up @@ -589,6 +591,18 @@ class Profile : public protocol_handler::ProtocolHandlerSettings,

const std::vector<std::string>& embedded_services() const OVERRIDE;
const std::string hmi_origin_id() const OVERRIDE;

/**
* @brief Returns true if writing all logs to file system before shutdown is

Choose a reason for hiding this comment

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

please remove "all" in comment

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@yang1070 Done

* enabled
*/
bool flush_log_messages_before_shutdown() const OVERRIDE;
/**
* @brief Returns waximum time to wait for writing all data before exit SDL

Choose a reason for hiding this comment

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

typo waximum

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@yang1070 Done

* in seconds
*/
uint16_t max_time_before_shutdown() const OVERRIDE;

/**
* @brief Reads a string value from the profile
*
Expand Down Expand Up @@ -1164,6 +1178,8 @@ class Profile : public protocol_handler::ProtocolHandlerSettings,
int ignition_off_signal_offset_;
uint32_t rpc_pass_through_timeout_;
uint16_t period_for_consent_expiration_;
bool flush_log_messages_before_shutdown_;
uint16_t max_time_before_shutdown_;

std::vector<std::string> embedded_services_;

Expand Down
29 changes: 28 additions & 1 deletion src/components/config_profile/src/profile.cc
Original file line number Diff line number Diff line change
Expand Up @@ -97,6 +97,7 @@ const char* kLowBandwidthTransportResumptionLevelSection =
"LowBandwidthTransportResumptionLevel";
const char* kAppServicesSection = "AppServices";
const char* kRCModuleConsentSection = "RCModuleConsent";
const char* kLoggerSection = "Logger";

const char* kSDLVersionKey = "SDLVersion";
const char* kHmiCapabilitiesKey = "HMICapabilities";
Expand Down Expand Up @@ -307,6 +308,8 @@ const char* kMediaLowBandwidthResumptionLevelKey =
"MediaLowBandwidthResumptionLevel";
const char* kHMIOriginIDKey = "HMIOriginID";
const char* kEmbeddedServicesKey = "EmbeddedServices";
const char* kFlushLogMessagesBeforeShutdown = "FlushLogMessagesBeforeShutdown";
const char* kMaxTimeBeforeShutdown = "MaxTimeBeforeShutdown";

#ifdef WEB_HMI
const char* kDefaultLinkToWebHMI = "HMI/index.html";
Expand Down Expand Up @@ -442,6 +445,9 @@ const char* kDefaultAOAFilterDescription = "SmartDeviceLink Core Component USB";
const char* kDefaultAOAFilterVersion = "1.0";
const char* kDefaultAOAFilterURI = "http://www.smartdevicelink.org";
const char* kDefaultAOAFilterSerialNumber = "N000000";

const bool kDefaultFlushLogMessagesBeforeShutdown = false;
const uint16_t kDefaultMaxTimeBeforeShutdown = 30;
} // namespace

namespace profile {
Expand Down Expand Up @@ -571,7 +577,10 @@ Profile::Profile()
, wake_up_signal_offset_(kDefaultWakeUpSignalOffset)
, ignition_off_signal_offset_(kDefaultIgnitionOffSignalOffset)
, rpc_pass_through_timeout_(kDefaultRpcPassThroughTimeout)
, period_for_consent_expiration_(kDefaultPeriodForConsentExpiration) {
, period_for_consent_expiration_(kDefaultPeriodForConsentExpiration)
, flush_log_messages_before_shutdown_(
kDefaultFlushLogMessagesBeforeShutdown)
, max_time_before_shutdown_(kDefaultMaxTimeBeforeShutdown) {
}

Profile::~Profile() {}
Expand Down Expand Up @@ -1197,6 +1206,14 @@ const std::vector<std::string>& Profile::video_service_transports() const {
return video_service_transports_;
}

bool Profile::flush_log_messages_before_shutdown() const {
return flush_log_messages_before_shutdown_;
}

uint16_t Profile::max_time_before_shutdown() const {
return max_time_before_shutdown_;
}

const bool Profile::ErrorOccured() const {
return error_occured_;
}
Expand Down Expand Up @@ -2681,6 +2698,16 @@ void Profile::UpdateValues() {

LOG_UPDATED_VALUE(hmi_origin_id_, kHMIOriginIDKey, kAppServicesSection);

ReadBoolValue(&flush_log_messages_before_shutdown_,
kDefaultFlushLogMessagesBeforeShutdown,
kLoggerSection,
kFlushLogMessagesBeforeShutdown);

ReadUIntValue(&max_time_before_shutdown_,
kDefaultMaxTimeBeforeShutdown,
kLoggerSection,
kMaxTimeBeforeShutdown);

{ // App Services map
struct KeyPair {
std::vector<std::string>* ini_vector;
Expand Down
4 changes: 4 additions & 0 deletions src/components/include/utils/conditional_variable.h
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@
#include <stdint.h>
#include <boost/thread/condition_variable.hpp>

#include <functional>
#include "utils/lock.h"
#include "utils/macro.h"

Expand Down Expand Up @@ -73,6 +74,9 @@ class ConditionalVariable {
bool Wait(AutoLock& auto_lock);
bool Wait(BaseLock& lock);
WaitStatus WaitFor(AutoLock& auto_lock, uint32_t milliseconds);
void WaitFor(AutoLock& lock,
uint16_t seconds,
std::function<bool()> predicate);

private:
boost::condition_variable_any cond_var_;
Expand Down
4 changes: 4 additions & 0 deletions src/components/include/utils/ilogger.h
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,8 @@
#include <string>
#include <thread>

#include "utils/logger/logger_settings.h"

namespace logger {

enum class LogLevel {
Expand Down Expand Up @@ -71,6 +73,8 @@ class Logger {
virtual void DeInit() = 0;
virtual void Flush() = 0;
virtual void PushLog(const LogMessage& log_message) = 0;
virtual void InitLoggerSettings(LoggerSettings* settings) = 0;
virtual void InitFlushLogsTimePoint(const TimePoint& time_point) = 0;
static Logger& instance(Logger* pre_init = nullptr);
};

Expand Down
5 changes: 5 additions & 0 deletions src/components/include/utils/logger.h
Original file line number Diff line number Diff line change
Expand Up @@ -52,6 +52,9 @@
// it's needed, for example, when crash happened
#define SDL_FLUSH_LOGGER() logger::Logger::instance().Flush();

#define SDL_INIT_FLUSH_LOGS_TIME_POINT(time_point) \
logger::Logger::instance().InitFlushLogsTimePoint(time_point);

// Logger deinitilization function and macro, need to stop log4cxx writing
// without this deinitilization log4cxx threads continue using some instances
// destroyed by exit()
Expand Down Expand Up @@ -108,6 +111,8 @@

#define SDL_CREATE_LOCAL_LOG_VARIABLE(x)

#define SDL_INIT_FLUSH_LOGS_TIME_POINT(x)

#define SDL_DEINIT_LOGGER()

#define SDL_FLUSH_LOGGER()
Expand Down
14 changes: 14 additions & 0 deletions src/components/include/utils/message_queue.h
Original file line number Diff line number Diff line change
Expand Up @@ -102,6 +102,12 @@ class MessageQueue {
*/
void WaitUntilEmpty();

/**
* \brief Wait until message queue is empty for certain time
* \param seconds seconds to wait
*/
void TimedWaitUntilEmpty(uint16_t seconds);

/**
* \brief Shutdown the queue.
* This leads to waking up everyone waiting on the queue
Expand Down Expand Up @@ -152,6 +158,14 @@ void MessageQueue<T, Q>::WaitUntilEmpty() {
}
}

template <typename T, class Q>
void MessageQueue<T, Q>::TimedWaitUntilEmpty(uint16_t seconds) {
sync_primitives::AutoLock auto_lock(queue_lock_);
queue_new_items_.WaitFor(auto_lock, seconds, [this] {
return (queue_.empty() || shutting_down_);
});
}

template <typename T, class Q>
size_t MessageQueue<T, Q>::size() const {
sync_primitives::AutoLock auto_lock(queue_lock_);
Expand Down
11 changes: 11 additions & 0 deletions src/components/include/utils/threads/message_loop_thread.h
Original file line number Diff line number Diff line change
Expand Up @@ -96,6 +96,12 @@ class MessageLoopThread {
*/
void WaitDumpQueue();

/**
* \brief Wait until message queue is empty for certain time
* \param seconds seconds to wait
*/
void TimedWaitDumpQueue(uint16_t seconds);

private:
/*
* Implementation of ThreadDelegate that actually pumps the queue and is
Expand Down Expand Up @@ -168,6 +174,11 @@ void MessageLoopThread<Q>::WaitDumpQueue() {
message_queue_.WaitUntilEmpty();
}

template <class Q>
void MessageLoopThread<Q>::TimedWaitDumpQueue(uint16_t seconds) {
message_queue_.TimedWaitUntilEmpty(seconds);
}

//////////
template <class Q>
MessageLoopThread<Q>::LoopThreadDelegate::LoopThreadDelegate(
Expand Down
4 changes: 4 additions & 0 deletions src/components/utils/include/utils/logger/logger_impl.h
Original file line number Diff line number Diff line change
Expand Up @@ -74,10 +74,14 @@ class LoggerImpl : public Logger, public LoggerInitializer {
bool IsEnabledFor(const std::string& component,
LogLevel log_level) const override;
void PushLog(const LogMessage& log_message) override;
void InitLoggerSettings(LoggerSettings* settings) override;
void InitFlushLogsTimePoint(const TimePoint& time_point) override;

std::unique_ptr<ThirdPartyLoggerInterface> impl_;
LoggerSettings* settings_;
LoopThreadPtr<LogMessageLoopThread> loop_thread_;
bool use_message_loop_thread_;
TimePoint flush_logs_time_point_;

Choose a reason for hiding this comment

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

what's the default value of flush_logs_time_point_ if it is not initialized?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Default constructor, creates a time_point representing the Clock's epoch (i.e., time_since_epoch() is zero).

Choose a reason for hiding this comment

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

@VladSemenyuk Got it. Thank you

};

} // namespace logger
Expand Down
15 changes: 15 additions & 0 deletions src/components/utils/include/utils/logger/logger_settings.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
#ifndef SRC_COMPONENTS_UTILS_INCLUDE_UTILS_LOGGER_SETTINGS_H_
#define SRC_COMPONENTS_UTILS_INCLUDE_UTILS_LOGGER_SETTINGS_H_

#include <stdint.h>
ShobhitAd marked this conversation as resolved.
Show resolved Hide resolved

namespace logger {
class LoggerSettings {
public:
virtual bool flush_log_messages_before_shutdown() const = 0;
virtual uint16_t max_time_before_shutdown() const = 0;
};

} // namespace logger

#endif // SRC_COMPONENTS_UTILS_INCLUDE_UTILS_LOGGER_SETTINGS_H_
20 changes: 20 additions & 0 deletions src/components/utils/src/conditional_variable_boost.cc
Original file line number Diff line number Diff line change
Expand Up @@ -132,4 +132,24 @@ ConditionalVariable::WaitStatus ConditionalVariable::WaitFor(
return wait_status;
}

void ConditionalVariable::WaitFor(AutoLock& auto_lock,
uint16_t seconds,
std::function<bool()> predicate) {
try {
BaseLock& lock = auto_lock.GetLock();

lock.AssertTakenAndMarkFree();

cond_var_.timed_wait<boost::mutex>(dynamic_cast<Lock*>(&lock)->mutex_,
boost::posix_time::seconds(seconds),
predicate);

lock.AssertFreeAndMarkTaken();
} catch (const boost::exception& error) {
std::string error_string = boost::diagnostic_information(error);
SDL_LOG_FATAL(error_string);
NOTREACHED();
}
}

} // namespace sync_primitives
27 changes: 24 additions & 3 deletions src/components/utils/src/logger/logger_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,9 @@
namespace logger {

LoggerImpl::LoggerImpl(bool use_message_loop_thread)
: impl_(nullptr), use_message_loop_thread_(use_message_loop_thread) {}
: impl_(nullptr)
, settings_(nullptr)
, use_message_loop_thread_(use_message_loop_thread) {}

void LoggerImpl::Init(std::unique_ptr<ThirdPartyLoggerInterface>&& impl) {
assert(impl_ == nullptr);
Expand Down Expand Up @@ -71,9 +73,20 @@ void LoggerImpl::DeInit() {
}

void LoggerImpl::Flush() {
if (use_message_loop_thread_) {
if (loop_thread_) {
if (use_message_loop_thread_ && loop_thread_) {
assert(settings_);

if (0 == flush_logs_time_point_.time_since_epoch().count()) {

Choose a reason for hiding this comment

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

why do we have such a condition? it seems impossible to me that count() is zero, thus impossible to execute next line

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Default constructor, creates a time_point representing the Clock's epoch (i.e., time_since_epoch() is zero).

Choose a reason for hiding this comment

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

@VladSemenyuk in file on_exit_all_applications_notification.cc and function void OnExitAllApplicationsNotification::Run()
it calls SDL_INIT_FLUSH_LOGS_TIME_POINT(std::chrono::system_clock::now()); to set the value of flush_logs_time_point_ to non-zero, what's the condition that next line get executed? during the SDL running without receiving ExitAllApplicationsNotification?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes, ExitAllApplicationsNotification is not the only exit point for SDL.

Copy link

@yang1070 yang1070 Jul 27, 2021

Choose a reason for hiding this comment

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

@VladSemenyuk could you list what are other conditions or exit point to call logger Flush()?

Copy link
Contributor Author

@VladSemenyuk VladSemenyuk Jul 27, 2021

Choose a reason for hiding this comment

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

@yang1070 The proposal is old and at the time it was written the logger worked differently, and now it does`nt match the proposal. So before this implementation SDL flushed all logs always on logger deinitialization, and now configurable timeout shutdown for IGNITION_OFF situation is added.

Choose a reason for hiding this comment

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

@VladSemenyuk in that case I'm not sure the proposal is still valid and whether or not we need this change.

the proposal solves the problem that SDL drops off log and give options to continue write the log with maximum allowed time configured by the SDL settings in ini file.

Now (before this PR), SDL get some update, it always flush the log, SDL no long drop off the log, the old problem does not exist any more. The problem may change to SDL takes too much time for flushing the logs? Why we still need to implement the proposal?

Copy link
Contributor Author

@VladSemenyuk VladSemenyuk Jul 27, 2021

Choose a reason for hiding this comment

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

The problem may change to SDL takes too much time for flushing the logs? Why we still need to implement the proposal?

@yang1070 Yes. Problem is it takes too much time for flushing the logs in some cases on weak environment.

Copy link

@yang1070 yang1070 Jul 27, 2021

Choose a reason for hiding this comment

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

@VladSemenyuk in that case, I would like to see an update of SDL-117 and get the update proposal approved first

Copy link

@yang1070 yang1070 Jul 27, 2021

Choose a reason for hiding this comment

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

since the default SDL behavior is to flush log,
as in the code change, the setting FlushLogMessagesBeforeShutdown will only impact the normal IGNITION_OFF situation. the name shall be change to something else that is more proper and can describe the situation
or if the name does not change, shall FlushLogMessagesBeforeShutdown=false to force SDL drop off log no matter the what the exit point is?

loop_thread_->WaitDumpQueue();
} else if (settings_->flush_log_messages_before_shutdown()) {
// Calculate elapsed seconds since IGNITION_OFF
const auto seconds = std::chrono::duration_cast<std::chrono::seconds>(
std::chrono::high_resolution_clock::now() - flush_logs_time_point_);
int16_t seconds_before_shutdown =
settings_->max_time_before_shutdown() - seconds.count();
if (0 < seconds_before_shutdown) {
loop_thread_->TimedWaitDumpQueue(seconds_before_shutdown);
}
}
}
}
Expand Down Expand Up @@ -116,6 +129,14 @@ void LogMessageLoopThread::Handle(const LogMessage message) {
force_log_(message);
}

void LoggerImpl::InitLoggerSettings(LoggerSettings* settings) {
settings_ = settings;
}

void LoggerImpl::InitFlushLogsTimePoint(const TimePoint& time_point) {
flush_logs_time_point_ = time_point;
}

LogMessageLoopThread::~LogMessageLoopThread() {
// we'll have to drop messages
// while deleting logger thread
Expand Down