RDKCOM-5467: RDKDEV-1147 Improvement in RDK Logger functionalities to handle race conditions

[sushil-shinde-infosys]

Root Cause:
The crash occurred because sd_hash_lookup() retrieved a bad entry (p) from the hash table.
When it attempted to compare a_key with p->key using strcmp(), the pointer in p was invalid,
causing the crash. In other words, strcmp() in log4c received an invalid pointer,
most likely due to thread-unsafe concurrent access to log4c’s hash table.
The Log4c API is not fully MT safe, the documentation for log4c does mention the problem of the use of log4c in a multithreaded environment
and considers all the functions which are not multi-thread safe, see chapter 5.4.3.1: https://www.slideshare.net/slideshow/log4-c-developers-guide-presentation/640301

Solution & Enhancements:
Added synchronization to prevent race conditions during initialization.
Introduced synchronization to ensure thread-safe message logging from multiple threads.
Implemented a shutdown mechanism to guarantee that all log messages are flushed before cleanup.

RDK logger APIs are called from most of the RDK modules, especially in negative scenarios where RDK logs many errors and warnings. These cases need to be considered during testing.

[github-actions]

All contributors have signed the CLA ✍️ ✅
_{Posted by the CLA Assistant Lite bot.}

[Copilot]

Pull request overview

This PR addresses critical race conditions in the RDK Logger that were causing crashes due to concurrent access to log4c's non-thread-safe hash table. The root cause was identified as strcmp() receiving invalid pointers from sd_hash_lookup() when multiple threads accessed the logger concurrently. The solution introduces synchronization mechanisms to protect initialization, logging operations, and shutdown sequences.

Key Changes:

• Added mutex protection around logger initialization to prevent concurrent initialization attempts
• Introduced atomic counter tracking active log calls with a wait mechanism in deinit to ensure graceful shutdown
• Protected log4c category access with a dedicated mutex to prevent concurrent access to log4c's internal data structures

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 12 comments.

File	Description
src/rdk_logger_init.c	Added initialization mutex, atomic counter for tracking active log calls, and shutdown wait mechanism with timeout to ensure all logging completes before cleanup
src/rdk_debug_priv.c	Added mutex protection around log4c_category_get() calls, atomic counter for tracking active vlog calls, and refactored switch statement for cleaner code

Comments suppressed due to low confidence (1)

src/rdk_logger_init.c:100

• Missing mutex unlock when isLogInited is already 1. If rdk_logger_init() is called when the logger is already initialized (line 69 check fails), the function returns at line 100 without unlocking the mutex that was locked at line 68, causing a deadlock on subsequent calls.

Add pthread_mutex_unlock(&g_rdk_logger_init_mutex); before line 100, or restructure the code to ensure the mutex is always unlocked on all paths.

    if (0 == isLogInited)
    {
        if (NULL == debugConfigFile)
        {
            debugConfigFile = DEBUG_CONF_FILE;
        }

        /* Read the config file & populate pre-configured log levels */
        ret = rdk_logger_parse_config(debugConfigFile);
        if ( RDK_SUCCESS != ret)
        {
            printf("%s:%d Adding debug config file %s failed\n", __FUNCTION__, __LINE__, debugConfigFile);
            pthread_mutex_unlock(&g_rdk_logger_init_mutex);
            return ret;
        }
        /* Perform Logger Internal Init */
        rdk_dbg_init();

        /* Perform Dynamin Logger Internal Init */
        rdk_dyn_log_init();

        pthread_mutex_unlock(&g_rdk_logger_init_mutex);

        /**
         * Requests not to send SIGPIPE on errors on stream oriented
         * sockets when the other end breaks the connection. The EPIPE
         * error is still returned.
         */
        signal(SIGPIPE, SIG_IGN);
        isLogInited = 1;
    }
    return RDK_SUCCESS;

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

[Copilot]

The IS_LOGGING_ENABLED_FOR_LEVEL macro calls log4c_category_get(module_name) again at line 397 without mutex protection. This is a TOCTOU (time-of-check-time-of-use) issue. The category obtained under mutex protection (line 376) could be modified or invalidated between the mutex unlock (line 395) and this check.

Store the result of the enabled check while still holding the mutex, or extend the mutex protection to cover this check as well.

Suggested change

	pthread_mutex_unlock(&g_log4c_cat_get_mutex);
	if (!IS_LOGGING_ENABLED_FOR_LEVEL(module_name, level))
	int is_enabled = 0;
	/* Check if logging is enabled for this level while still holding the mutex */
	if (cat) {
	int cat_priority = log4c_category_get_priority(cat);
	int req_priority = rdk_logLevel_to_log4c_priority(level);
	is_enabled = (cat_priority != LOG4C_PRIORITY_NONE && req_priority <= cat_priority);
	}
	pthread_mutex_unlock(&g_log4c_cat_get_mutex);
	if (!is_enabled)

[sushil-shinde-infosys]

Its valid suggestion.

[Copilot]

Typo in comment: "Dynamin" should be "Dynamic".

Suggested change

	/* Perform Dynamin Logger Internal Init */
	/* Perform Dynamic Logger Internal Init */

[sushil-shinde-infosys]

valid recommendations are addressed, few are ignored.

[sushil-shinde-infosys]

recheck

[sushil-shinde-infosys]

I have read the CLA Document and I hereby sign the CLA