[libcamera-devel] [PATCH] libcamera: log: Destroy LogCategory instances in a controlled way

[Kieran Bingham]

Hi Laurent,

On 15/06/2021 10:31, Laurent Pinchart wrote:
> Hi Kieran,
> 
> On Thu, Jun 10, 2021 at 09:34:57AM +0100, Kieran Bingham wrote:
>> On 23/05/2021 01:04, Laurent Pinchart wrote:
>>> The LogCategory instances are constructed on first use as static
>>> variables in accessor functions, following the Meyers singleton pattern.
>>> As a result, their destruction order is not guaranteed. This can cause
>>> issues as the global Logger object, constructed in a similar fashion, is
>>> accessed from the LogCategory destructor and may be destroyed first.
>>>
>>> To fix this, keep the same singleton pattern, but allocate the
>>> LogCategory instances dynamically. As they get registered with the
>>> global Logger instance, we can destroy them in the Logger destructor.
>>>
>>> This only avoids destruction order issues between LogCategory and
>>> Logger, and doesn't address yet the fact that LOG() calls from
>>> destructors of global objects may access an already destroyed Logger.
>>
>> Are log categories now the only dynamic thing that could be referenced
>> after the destructor is called?
> 
> I'm not sure to understand your question here. Both the Logger and the
> category can still be referenced after being destroyed, if that's what
> you're asking.

I think I was asking, of these components which are allocated with
malloc/new.


>> This may be well into the direction of hack-on-hack - but as the
>> Logger->instance() is static - we know it has a defined region of memory
>> - so even after the destructor is called - it is still 'there' (It can't
>> be freed).
>>
>> So - when the destructor is called - the LogCategories are now removed -
>> but perhaps that's ok - at that point, we can disable all filtering -
>> and any log message that occurs after 'destructor' could be written to
>> std-out - perhaps with some 'emergency' / 'destruct' constant category.
> 
> That's an interesting idea. I fear rabbit holes though :-)
> 
>> Anyway, that's all musings on how to consider the next issues.
>>
>> If this helps prevent crashes, then it's worthwhile on it's own.
>>
>> Reviewed-by: Kieran Bingham <kieran.bingham at ideasonboard.com>
>>
>> Although - now thinking further - Is the crash that can occur because a
>> Log is reported with a LogCategory that has been unregistered?
>>
>> And if we can detect that, can we apply the same logic and report the
>> log output as an always print, 'Emergency' or 'Shutdown' category?
>>
>> In otherwords, if we can detect the parts we can't access - we should
>> still be able to print the log message without crashing ...
> 
> We won't be able to process log levels, which means that we'd have to
> decide at compile time the minimum level that gets printed for those
> messages. Coupled with the fact that an application may direct the log
> to a file because it wants to use stdout and/or stderr for its own
> purposes (I'm thinking about a machine-readable output), this may become
> annoying.
> 
> What could possibly be done is dropping those messages instead of
> crashing, or possibly assert()ing in a controlled way.

I guess you could silently drop them too - I assumed logging them by
default was better than dropping them by default, but as you say above -
it could be a compile time constant.

The point would be - make sure we don't fail in a messy way ...

Asserting perhaps might be better - as then it will simply tell someone
they need to remove or reconsider that print as it can't be guaranteed
to output....

Which sounds better perhaps as then they likely will think about the
shutdown sequences more...



>>> Signed-off-by: Laurent Pinchart <laurent.pinchart at ideasonboard.com>
>>> ---
>>>  include/libcamera/internal/log.h |  5 ++---
>>>  src/libcamera/log.cpp            | 32 +++++++++++---------------------
>>>  2 files changed, 13 insertions(+), 24 deletions(-)
>>>
>>> diff --git a/include/libcamera/internal/log.h b/include/libcamera/internal/log.h
>>> index b66bf55bc57d..1032bdd93e7c 100644
>>> --- a/include/libcamera/internal/log.h
>>> +++ b/include/libcamera/internal/log.h
>>> @@ -29,7 +29,6 @@ class LogCategory
>>>  {
>>>  public:
>>>  	explicit LogCategory(const char *name);
>>> -	~LogCategory();
>>>  
>>>  	const char *name() const { return name_; }
>>>  	LogSeverity severity() const { return severity_; }
>>> @@ -48,8 +47,8 @@ extern const LogCategory &_LOG_CATEGORY(name)();
>>>  #define LOG_DEFINE_CATEGORY(name)					\
>>>  const LogCategory &_LOG_CATEGORY(name)()				\
>>>  {									\
>>> -	static LogCategory category(#name);				\
>>> -	return category;						\
>>> +	static LogCategory *category = new LogCategory(#name);		\
>>> +	return *category;						\
>>>  }
>>>  
>>>  class LogMessage
>>> diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
>>> index dd991647b9bc..74829a56916e 100644
>>> --- a/src/libcamera/log.cpp
>>> +++ b/src/libcamera/log.cpp
>>> @@ -248,6 +248,8 @@ void LogOutput::writeStream(const std::string &str)
>>>  class Logger
>>>  {
>>>  public:
>>> +	~Logger();
>>> +
>>>  	static Logger *instance();
>>>  
>>>  	void write(const LogMessage &msg);
>>> @@ -267,7 +269,6 @@ private:
>>>  
>>>  	friend LogCategory;
>>>  	void registerCategory(LogCategory *category);
>>> -	void unregisterCategory(LogCategory *category);
>>>  
>>>  	std::unordered_set<LogCategory *> categories_;
>>>  	std::list<std::pair<std::string, LogSeverity>> levels_;
>>> @@ -369,6 +370,12 @@ void logSetLevel(const char *category, const char *level)
>>>  	Logger::instance()->logSetLevel(category, level);
>>>  }
>>>  
>>> +Logger::~Logger()
>>> +{
>>> +	for (LogCategory *category : categories_)
>>> +		delete category;
>>> +}
>>> +
>>>  /**
>>>   * \brief Retrieve the logger instance
>>>   *
>>> @@ -665,18 +672,6 @@ void Logger::registerCategory(LogCategory *category)
>>>  	}
>>>  }
>>>  
>>> -/**
>>> - * \brief Unregister a log category from the logger
>>> - * \param[in] category The log category
>>> - *
>>> - * If the \a category hasn't been registered with the logger this function
>>> - * performs no operation.
>>> - */
>>> -void Logger::unregisterCategory(LogCategory *category)
>>> -{
>>> -	categories_.erase(category);
>>> -}
>>> -
>>>  /**
>>>   * \enum LogSeverity
>>>   * Log message severity
>>> @@ -711,11 +706,6 @@ LogCategory::LogCategory(const char *name)
>>>  	Logger::instance()->registerCategory(this);
>>>  }
>>>  
>>> -LogCategory::~LogCategory()
>>> -{
>>> -	Logger::instance()->unregisterCategory(this);
>>> -}
>>> -
>>>  /**
>>>   * \fn LogCategory::name()
>>>   * \brief Retrieve the log category name
>>> @@ -746,12 +736,12 @@ void LogCategory::setSeverity(LogSeverity severity)
>>>   * The default log category is named "default" and is used by the LOG() macro
>>>   * when no log category is specified.
>>>   *
>>> - * \return A pointer to the default log category
>>> + * \return A reference to the default log category
>>>   */
>>>  const LogCategory &LogCategory::defaultCategory()
>>>  {
>>> -	static const LogCategory category("default");
>>> -	return category;
>>> +	static const LogCategory *category = new LogCategory("default");
>>> +	return *category;
>>>  }
>>>  
>>>  /**
> 

-- 
Regards
--
Kieran