From 5cb526e29682b5542499e1fd9ebf98683d85580a Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Wed, 25 Mar 2026 14:59:31 +0000 Subject: [PATCH 01/12] Remove accountId validation gates from idm_client.c Remove all accountId-based pairing restrictions so devices pair irrespective of accountId value when both run new code, and work correctly with valid accountId in mixed scenarios. Changes: - Remove while(1) blocking loop in start_discovery that waited for RFC accountId to become non-Unknown (XLE could never start discovery when RFC was not yet provisioned) - Remove digit-only validation that rejected accountIds containing non-digit characters (rejected 'Unknown') - Remove accountId match check that required peer accountId to equal own accountId (prevented XLE from being added when it returned Unknown) - Remove now-unused static accountId[] global declaration idm_server.c is unchanged. Coverage: XLE new + XB new : works for valid and Unknown accountId XLE new + XB old : works when XLE RFC accountId is valid XLE old + XB new : works when XLE RFC accountId is valid --- src/idm_client.c | 52 +++++------------------------------------------- 1 file changed, 5 insertions(+), 47 deletions(-) diff --git a/src/idm_client.c b/src/idm_client.c index 5907c9b..b5ea70a 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -75,7 +75,6 @@ char se_cert_conf_file[128]; static int fd = -1; static gboolean idm_upnp_init_status = FALSE; -static char accountId[ACCOUNTID_SIZE]; static GUPnPContext *upnpContextDeviceProtect; static GMainLoop *main_loop; typedef GTlsInteraction XupnpTlsInteraction; @@ -712,37 +711,12 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) } if ( processStringRequest((GUPnPServiceProxy *)gwydata->sproxy_i, "GetAccountId","AccountId", &temp, FALSE)) { - int valid_account=1,loop=0; g_message("Discovered device sent accountId as %s",temp); - for(loop=0;loop<(int)(strlen(temp));loop++) - { - if(temp[loop] < '0' || temp[loop] > '9') - { - g_message("not a valid account due to %c presence",temp[loop]); - valid_account=0; - break; - } - } - if(valid_account==1) - { - g_message("Discovered device AccountId is valid"); - if(g_strcmp0(g_strstrip(accountId),temp)==0) - { - g_mutex_lock(mutex); - xdevlist = g_list_insert_sorted_with_data(xdevlist, gwydata,(GCompareDataFunc)g_list_compare_sno, NULL); - g_mutex_unlock(mutex); - g_message("Inserted new/updated device %s in the list as accountId %s is same", sno,temp); - callback(&di,1,1); - } - else - { - g_message("Not adding to the list as accountId %s is different",temp); - } - } - else - { - g_message("Its not valid accountID so accountId %s not adding to the list",temp); - } + g_mutex_lock(mutex); + xdevlist = g_list_insert_sorted_with_data(xdevlist, gwydata,(GCompareDataFunc)g_list_compare_sno, NULL); + g_mutex_unlock(mutex); + g_message("Associating device %s accountId=%s", sno,temp); + callback(&di,1,1); g_free(temp); } } @@ -917,22 +891,6 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info getserialnum(ownSerialNo); callback=func_callback; #ifndef IDM_DEBUG - int ind=-1; - errno_t rc = -1; - memset(accountId,0,ACCOUNTID_SIZE); - while(1) - { - getAccountId(accountId); - g_message("%s:AccountId=%s",__FUNCTION__,accountId); - rc = strcasecmp_s("unknown",strlen("unknown"),accountId,&ind); - ERR_CHK(rc); - if(ind || rc != EOK) - { - break; - } - sleep(5); - } - g_message("%s:Account ID complete.AccountId = %s", __FUNCTION__, accountId); #endif #ifndef IDM_DEBUG #ifndef ENABLE_HW_CERT_USAGE From 6d07c438a54ac3b17651123a2b514d519cd67e79 Mon Sep 17 00:00:00 2001 From: veeraputhiran-thangavel Date: Thu, 26 Mar 2026 19:04:20 +0530 Subject: [PATCH 02/12] Apply suggestion from @Copilot Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- src/idm_client.c | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/idm_client.c b/src/idm_client.c index b5ea70a..5f3af54 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -891,8 +891,6 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info getserialnum(ownSerialNo); callback=func_callback; #ifndef IDM_DEBUG -#endif -#ifndef IDM_DEBUG #ifndef ENABLE_HW_CERT_USAGE memset(caFile, 0 , sizeof(caFile)); memset(certFile, 0 , sizeof(certFile)); From 8d346a1c34f79733e6889c6c3d45e5d5a363c0b5 Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Thu, 26 Mar 2026 12:39:46 +0000 Subject: [PATCH 03/12] Make device association unconditional; treat GetAccountId as optional Device list insertion and callback now happen regardless of whether GetAccountId succeeds, so devices that don't implement the action or return an error are still associated. When GetAccountId succeeds the accountId is logged as metadata. When it fails a diagnostic message is logged and pairing continues. This fully removes accountId-based pairing restrictions from the client side. --- src/idm_client.c | 15 +++++---------- 1 file changed, 5 insertions(+), 10 deletions(-) diff --git a/src/idm_client.c b/src/idm_client.c index 5f3af54..0236621 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -709,16 +709,11 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) g_message("GatewayIPv6=%s",di.Ipv6); g_free(temp); } - if ( processStringRequest((GUPnPServiceProxy *)gwydata->sproxy_i, "GetAccountId","AccountId", &temp, FALSE)) - { - g_message("Discovered device sent accountId as %s",temp); - g_mutex_lock(mutex); - xdevlist = g_list_insert_sorted_with_data(xdevlist, gwydata,(GCompareDataFunc)g_list_compare_sno, NULL); - g_mutex_unlock(mutex); - g_message("Associating device %s accountId=%s", sno,temp); - callback(&di,1,1); - g_free(temp); - } + g_mutex_lock(mutex); + xdevlist = g_list_insert_sorted_with_data(xdevlist, gwydata,(GCompareDataFunc)g_list_compare_sno, NULL); + g_mutex_unlock(mutex); + g_message("Associating device %s", sno); + callback(&di,1,1); } else { From 52dc00b963c3a6f44170c3fc8153be39aa5c9b29 Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Fri, 27 Mar 2026 09:14:27 +0000 Subject: [PATCH 04/12] Add Consolelog and T2 telemetry markers for IDM pairing events - New idm_log.h / idm_log.c: shared logging module for idm_client and idm_server. Writes timestamped lines to /rdklogs/logs/InterDeviceManager.txt.0 with RDK log format: YYMMDD-HH:MM:SS.uuuuuu [mod=INTERDEVICEMANAGER, lvl=] [tid=NNN] func line - message - Persistent file descriptor with inode-check reopen on rdklogger rotation - Thread-safe via pthread_mutex_t; _GNU_SOURCE guard for localtime_r/syscall - IDM_LOG_INFO(fmt, ...) macro for INFO-level logging - IDM_LOG_ERR(fmt, ...) macro for ERROR-level logging - Format attribute __attribute__((format(printf, 4, 5))) for compile-time format-string validation - T2 telemetry: t2_event_s("IDM_DISCOVERY_STARTED_split", ...) and t2_event_s("IDM_DEVICE_ASSOCIATED_split", ...) at key events - Makefile.am: idm_log.c added to libupnpidm_la_SOURCES --- src/Makefile.am | 2 +- src/idm_client.c | 19 ++++++++++ src/idm_log.c | 96 ++++++++++++++++++++++++++++++++++++++++++++++++ src/idm_log.h | 50 +++++++++++++++++++++++++ 4 files changed, 166 insertions(+), 1 deletion(-) create mode 100644 src/idm_log.c create mode 100644 src/idm_log.h diff --git a/src/Makefile.am b/src/Makefile.am index 7f6a717..7c728c7 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -75,7 +75,7 @@ if BROADBAND_SUPPORT xcal_device_LDADD = $(top_builddir)/broadband/lib/libxdevice.la if RDKB_INTER_DEVICE_MANAGER_SUPPORT lib_LTLIBRARIES = libupnpidm.la -libupnpidm_la_SOURCES = idm_server.c idm_client.c idm_library.c +libupnpidm_la_SOURCES = idm_server.c idm_client.c idm_library.c idm_log.c endif endif if VIDEO_SUPPORT diff --git a/src/idm_client.c b/src/idm_client.c index 0236621..99636fc 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -59,6 +59,10 @@ #ifdef ENABLE_HW_CERT_USAGE #include "rdkconfig.h" #endif +#if defined(ENABLE_FEATURE_TELEMETRY2_0) +#include +#endif +#include "idm_log.h" #define CLIENT_CONTEXT_PORT 50767 #define IDM_CLIENT_DEVICE "urn:schemas-upnp-org:device:IDM:1" #define IDM_SERVICE "urn:schemas-upnp-org:service:X1IDM:1" @@ -713,6 +717,11 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) xdevlist = g_list_insert_sorted_with_data(xdevlist, gwydata,(GCompareDataFunc)g_list_compare_sno, NULL); g_mutex_unlock(mutex); g_message("Associating device %s", sno); + g_message("TELEMETRY_IDM_DEVICE_ASSOCIATED:%s", sno); + IDM_LOG_INFO("device associated sno=%s\n", sno); +#if defined(ENABLE_FEATURE_TELEMETRY2_0) + t2_event_s("IDM_DEVICE_ASSOCIATED_split", sno); +#endif callback(&di,1,1); } else @@ -810,6 +819,11 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * xdevlist = g_list_insert_sorted_with_data(xdevlist, gwydata,(GCompareDataFunc)g_list_compare_sno, NULL); g_mutex_unlock(mutex); g_message("Inserted new/updated device %s in the list", sno); + g_message("TELEMETRY_IDM_DEVICE_ASSOCIATED:%s", sno); + IDM_LOG_INFO("device associated sno=%s\n", sno); +#if defined(ENABLE_FEATURE_TELEMETRY2_0) + t2_event_s("IDM_DEVICE_ASSOCIATED_split", sno); +#endif callback(&di,1,0); } else @@ -885,6 +899,11 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info ownSerialNo=g_string_new(NULL); getserialnum(ownSerialNo); callback=func_callback; + g_message("TELEMETRY_IDM_DISCOVERY_STARTED:%s", ownSerialNo->str); + IDM_LOG_INFO("start_discovery called for serial %s\n", ownSerialNo->str); +#if defined(ENABLE_FEATURE_TELEMETRY2_0) + t2_event_s("IDM_DISCOVERY_STARTED_split", ownSerialNo->str); +#endif #ifndef IDM_DEBUG #ifndef ENABLE_HW_CERT_USAGE memset(caFile, 0 , sizeof(caFile)); diff --git a/src/idm_log.c b/src/idm_log.c new file mode 100644 index 0000000..d42abab --- /dev/null +++ b/src/idm_log.c @@ -0,0 +1,96 @@ +/* + * If not stated otherwise in this file or this component's Licenses.txt file the + * following copyright and licenses apply: + * + * Copyright 2016 RDK Management + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +/** + * @file idm_log.c + * @brief IDM logging implementation — single shared fd for idm_client and idm_server. + */ +#ifndef _GNU_SOURCE + #define _GNU_SOURCE +#endif +#include +#include +#include +#include +#include +#include +#include +#include +#include "idm_log.h" + +static FILE *idm_log_fp = NULL; +static pthread_mutex_t idm_log_mutex = PTHREAD_MUTEX_INITIALIZER; + +/** + * idm_log_reopen — return the current log fd, reopening if rdklogger has + * rotated the file (detected via inode mismatch). + */ +static FILE *idm_log_reopen(void) +{ + struct stat st_fd, st_file; + /* Check if open fd still points to the same inode as the named file */ + if (idm_log_fp) + { + int stale = (fstat(fileno(idm_log_fp), &st_fd) != 0 || + stat(IDM_LOG_FILE, &st_file) != 0 || + st_fd.st_ino != st_file.st_ino); + if (stale) + { + fclose(idm_log_fp); + idm_log_fp = NULL; + } + } + if (!idm_log_fp) + idm_log_fp = fopen(IDM_LOG_FILE, "a"); + return idm_log_fp; +} + +/** + * idm_consolelog — write one timestamped log line. + * Called via the IDM_LOG_INFO() macro which supplies __func__ and __LINE__. + */ +void idm_consolelog(const char *func, int line, const char *level, + const char *fmt, ...) +{ + pthread_mutex_lock(&idm_log_mutex); + FILE *out = idm_log_reopen(); + if (!out) + { + pthread_mutex_unlock(&idm_log_mutex); + return; + } + + /* Timestamp: YYMMDD-HH:MM:SS.uuuuuu */ + struct timeval tv; + gettimeofday(&tv, NULL); + struct tm tm_info; + localtime_r(&tv.tv_sec, &tm_info); + char ts[32]; + strftime(ts, sizeof(ts), "%y%m%d-%H:%M:%S", &tm_info); + long tid = (long)syscall(SYS_gettid); + + fprintf(out, "%s.%06ld [mod=INTERDEVICEMANAGER, lvl=%s] [tid=%ld] %s %d - ", + ts, (long)tv.tv_usec, level, tid, func, line); + + va_list args; + va_start(args, fmt); + vfprintf(out, fmt, args); + va_end(args); + fflush(out); + pthread_mutex_unlock(&idm_log_mutex); +} diff --git a/src/idm_log.h b/src/idm_log.h new file mode 100644 index 0000000..bc0a15f --- /dev/null +++ b/src/idm_log.h @@ -0,0 +1,50 @@ +/* + * If not stated otherwise in this file or this component's Licenses.txt file the + * following copyright and licenses apply: + * + * Copyright 2016 RDK Management + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +/** + * @file idm_log.h + * @brief IDM logging interface — shared between idm_client.c and idm_server.c. + * + * All writes go to /rdklogs/logs/InterDeviceManager.txt.0. + * Log rotation is handled externally by rdklogger; the open file descriptor + * is transparently reopened after rotation via inode comparison. + */ + +#ifndef IDM_LOG_H +#define IDM_LOG_H + +#define IDM_LOG_FILE "/rdklogs/logs/InterDeviceManager.txt.0" + +/** + * IDM_LOG_INFO(fmt, ...) — write a timestamped INFO line to InterDeviceManager.txt.0. + * IDM_LOG_ERR(fmt, ...) — write a timestamped ERROR line. + * + * Format matches the standard RDK log pattern: + * YYMMDD-HH:MM:SS.uuuuuu [mod=INTERDEVICEMANAGER, lvl=] [tid=NNN] func line - message + */ +#define IDM_LOG_INFO(fmt, ...) \ + idm_consolelog(__func__, __LINE__, "INFO", fmt, ##__VA_ARGS__) + +#define IDM_LOG_ERR(fmt, ...) \ + idm_consolelog(__func__, __LINE__, "ERROR", fmt, ##__VA_ARGS__) + +void idm_consolelog(const char *func, int line, const char *level, + const char *fmt, ...) + __attribute__((format(printf, 4, 5))); + +#endif /* IDM_LOG_H */ From f4755b1ac0c8921a6af67bc69958406fd817133b Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Mon, 13 Apr 2026 05:13:35 +0000 Subject: [PATCH 05/12] idm: redirect IDM logs to Consolelog.txt.0 Change IDM_LOG_FILE from /rdklogs/logs/InterDeviceManager.txt.0 to /rdklogs/logs/Consolelog.txt.0 so IDM log output is consolidated into the standard console log file. --- src/idm_log.h | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/idm_log.h b/src/idm_log.h index bc0a15f..f72cdf0 100644 --- a/src/idm_log.h +++ b/src/idm_log.h @@ -20,7 +20,7 @@ * @file idm_log.h * @brief IDM logging interface — shared between idm_client.c and idm_server.c. * - * All writes go to /rdklogs/logs/InterDeviceManager.txt.0. + * All writes go to /rdklogs/logs/Consolelog.txt.0. * Log rotation is handled externally by rdklogger; the open file descriptor * is transparently reopened after rotation via inode comparison. */ @@ -28,10 +28,10 @@ #ifndef IDM_LOG_H #define IDM_LOG_H -#define IDM_LOG_FILE "/rdklogs/logs/InterDeviceManager.txt.0" +#define IDM_LOG_FILE "/rdklogs/logs/Consolelog.txt.0" /** - * IDM_LOG_INFO(fmt, ...) — write a timestamped INFO line to InterDeviceManager.txt.0. + * IDM_LOG_INFO(fmt, ...) — write a timestamped INFO line to Consolelog.txt.0. * IDM_LOG_ERR(fmt, ...) — write a timestamped ERROR line. * * Format matches the standard RDK log pattern: From 45c2ccf4bb12543231e8b2506261ed09a735d7b8 Mon Sep 17 00:00:00 2001 From: veeraputhiran-thangavel Date: Mon, 13 Apr 2026 10:47:37 +0530 Subject: [PATCH 06/12] Update src/idm_log.c Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- src/idm_log.c | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/idm_log.c b/src/idm_log.c index d42abab..d2acfd0 100644 --- a/src/idm_log.c +++ b/src/idm_log.c @@ -43,12 +43,14 @@ static pthread_mutex_t idm_log_mutex = PTHREAD_MUTEX_INITIALIZER; static FILE *idm_log_reopen(void) { struct stat st_fd, st_file; - /* Check if open fd still points to the same inode as the named file */ + /* Check if open fd still points to the same file as the named path */ if (idm_log_fp) { int stale = (fstat(fileno(idm_log_fp), &st_fd) != 0 || stat(IDM_LOG_FILE, &st_file) != 0 || - st_fd.st_ino != st_file.st_ino); + st_fd.st_ino != st_file.st_ino || + st_fd.st_dev != st_file.st_dev || + st_fd.st_mode != st_file.st_mode); if (stale) { fclose(idm_log_fp); From 2bdb3a339c90506996469b4e53555e36233bd5f8 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 13 Apr 2026 05:20:46 +0000 Subject: [PATCH 07/12] idm_log: append newline automatically in idm_consolelog; update call sites Agent-Logs-Url: https://github.com/rdkcentral/secure-upnp/sessions/a0e5b975-4a9e-4407-8e68-8d5db314bb62 Co-authored-by: veeraputhiran-thangavel <224542127+veeraputhiran-thangavel@users.noreply.github.com> --- src/idm_client.c | 6 +++--- src/idm_log.c | 4 +++- src/idm_log.h | 1 + 3 files changed, 7 insertions(+), 4 deletions(-) diff --git a/src/idm_client.c b/src/idm_client.c index 99636fc..200f261 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -718,7 +718,7 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) g_mutex_unlock(mutex); g_message("Associating device %s", sno); g_message("TELEMETRY_IDM_DEVICE_ASSOCIATED:%s", sno); - IDM_LOG_INFO("device associated sno=%s\n", sno); + IDM_LOG_INFO("device associated sno=%s", sno); #if defined(ENABLE_FEATURE_TELEMETRY2_0) t2_event_s("IDM_DEVICE_ASSOCIATED_split", sno); #endif @@ -820,7 +820,7 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * g_mutex_unlock(mutex); g_message("Inserted new/updated device %s in the list", sno); g_message("TELEMETRY_IDM_DEVICE_ASSOCIATED:%s", sno); - IDM_LOG_INFO("device associated sno=%s\n", sno); + IDM_LOG_INFO("device associated sno=%s", sno); #if defined(ENABLE_FEATURE_TELEMETRY2_0) t2_event_s("IDM_DEVICE_ASSOCIATED_split", sno); #endif @@ -900,7 +900,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info getserialnum(ownSerialNo); callback=func_callback; g_message("TELEMETRY_IDM_DISCOVERY_STARTED:%s", ownSerialNo->str); - IDM_LOG_INFO("start_discovery called for serial %s\n", ownSerialNo->str); + IDM_LOG_INFO("start_discovery called for serial %s", ownSerialNo->str); #if defined(ENABLE_FEATURE_TELEMETRY2_0) t2_event_s("IDM_DISCOVERY_STARTED_split", ownSerialNo->str); #endif diff --git a/src/idm_log.c b/src/idm_log.c index d2acfd0..5b4c618 100644 --- a/src/idm_log.c +++ b/src/idm_log.c @@ -63,8 +63,9 @@ static FILE *idm_log_reopen(void) } /** - * idm_consolelog — write one timestamped log line. + * idm_consolelog — write one timestamped log line (with automatic newline). * Called via the IDM_LOG_INFO() macro which supplies __func__ and __LINE__. + * Callers should not include a trailing "\n" in fmt. */ void idm_consolelog(const char *func, int line, const char *level, const char *fmt, ...) @@ -93,6 +94,7 @@ void idm_consolelog(const char *func, int line, const char *level, va_start(args, fmt); vfprintf(out, fmt, args); va_end(args); + fputc('\n', out); fflush(out); pthread_mutex_unlock(&idm_log_mutex); } diff --git a/src/idm_log.h b/src/idm_log.h index f72cdf0..fe40f55 100644 --- a/src/idm_log.h +++ b/src/idm_log.h @@ -34,6 +34,7 @@ * IDM_LOG_INFO(fmt, ...) — write a timestamped INFO line to Consolelog.txt.0. * IDM_LOG_ERR(fmt, ...) — write a timestamped ERROR line. * + * A newline is appended automatically; do not include a trailing "\n" in fmt. * Format matches the standard RDK log pattern: * YYMMDD-HH:MM:SS.uuuuuu [mod=INTERDEVICEMANAGER, lvl=] [tid=NNN] func line - message */ From b94fc4a96e6aa1543be39e5cdf45ea62d57d61c9 Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Mon, 13 Apr 2026 11:30:52 +0000 Subject: [PATCH 08/12] idm: add IDM_LOG_ERR dual-logging for all error paths in idm_client.c MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add IDM_LOG_ERR() alongside every existing g_message/g_critical error print so errors appear in both the GLib log (g_message) and the RDK console log (Consolelog.txt.0 via idm_log.c). Errors covered (30 call sites): - SE cert passcode retrieval failure (rdkconfig_get) - g_tls_certificate_new_from_file_with_password failure - HW cert fallback path: NULL certFile/keyFile, file not found, g_tls_certificate_new_from_files failure - Normal cert path: same three cases - GUPnP service proxy action error (processStringRequest) - gssdp_resource_browser_rescan failures (cp and cp_bgw variants) - xupnp stuck >5 minutes — all four code paths (IDM_DEBUG and production, inactive and null-count variants) - NULL cp/dproxy received in available callbacks (broadband + gateway) - Gateway receiver id NULL, UDN NULL - Memory allocation failure for GwyDeviceData - sproxy NULL on device available - Device receiver id NULL, device UDN NULL (non-broadband path) - Missing mandatory start_discovery parameters - p12 cert file creation failure - SE HW certificate not accessible - idm_server_start failure - pthread_create failure for EventHandler thread - Mandatory TLS cert files absent - GUPnP context creation failure g_message/g_critical calls are preserved unchanged. --- src/idm_client.c | 36 ++++++++++++++++++++++++++++++++++++ 1 file changed, 36 insertions(+) diff --git a/src/idm_client.c b/src/idm_client.c index 200f261..111382c 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -273,6 +273,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if(rdkconfig_get(&pass_phrase, &pass_size, se_cert_conf_file) == RDKCONFIG_FAIL) { g_message("Error in getting passcode\n"); + IDM_LOG_ERR("rdkconfig_get failed for SE cert passcode\n"); } else { @@ -291,6 +292,8 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac else { g_message(" Failed to generate g_tls cert from SE certificate\n"); + IDM_LOG_ERR("g_tls_certificate_new_from_file_with_password failed: %s\n", + xupnp_error ? xupnp_error->message : "unknown error"); if(xupnp_error) { g_message(" %s\n",xupnp_error->message); @@ -314,12 +317,14 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if ((certFile[0] == '\0') || (keyFile[0] == '\0')) { g_message(" Certificate or Key file NULL"); + IDM_LOG_ERR("certFile or keyFile path is empty (HW cert fallback path)\n"); return G_TLS_INTERACTION_FAILED; } if((access(certFile,F_OK ) != 0) || (access(keyFile,F_OK ) != 0)) { g_message(" Certificate or Key file does not exist"); + IDM_LOG_ERR("certFile or keyFile not found certFile=%s keyFile=%s\n", certFile, keyFile); return G_TLS_INTERACTION_FAILED; } @@ -329,6 +334,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if(cert == NULL) { g_message("Certificate creation failed from cert and key files"); + IDM_LOG_ERR("g_tls_certificate_new_from_files failed certFile=%s keyFile=%s\n", certFile, keyFile); if(xupnp_error != NULL) { @@ -344,12 +350,14 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if ((certFile[0] == '\0') || (keyFile[0] == '\0')) { g_message(" Certificate or Key file NULL"); + IDM_LOG_ERR("certFile or keyFile path is empty\n"); return G_TLS_INTERACTION_FAILED; } if((access(certFile,F_OK ) != 0) || (access(keyFile,F_OK ) != 0)) { g_message(" Certificate or Key file does not exist"); + IDM_LOG_ERR("certFile or keyFile not found certFile=%s keyFile=%s\n", certFile, keyFile); return G_TLS_INTERACTION_FAILED; } @@ -359,6 +367,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if(cert == NULL) { g_message("Certificate creation failed from cert and key files"); + IDM_LOG_ERR("g_tls_certificate_new_from_files failed certFile=%s keyFile=%s\n", certFile, keyFile); if(xupnp_error != NULL) { g_message("Failure reason for certificate creation: %s\n", xupnp_error->message ); @@ -424,6 +433,7 @@ GError *error = NULL; if ( NULL != error ) //Didn't went well { g_message ("%s process gw services Error: %s\n", requestFn, error->message); + IDM_LOG_ERR("gupnp_service_proxy_send_action failed fn=%s error=%s\n", requestFn, error->message); if ( isInCriticalPath ) // Update telemetry { g_message("TELEMETRY_XUPNP_PARTIAL_DISCOVERY:%d,%s",error->code, requestFn); @@ -463,11 +473,13 @@ void* verify_devices() if (gssdp_resource_browser_rescan(GSSDP_RESOURCE_BROWSER(cp))==FALSE) { g_message("Forced rescan failed"); + IDM_LOG_ERR("gssdp_resource_browser_rescan failed (cp)\n"); cp_bgw_inactive_count++; if(cp_bgw_inactive_count > 5) { //xupnp thread is stuck for 5 minutes g_message("xupnp is stuck for more than 5 minutes. Triggering IDM restart..."); + IDM_LOG_ERR("xupnp stuck >5min cp inactive, triggering restart\n"); cp_bgw_inactive_count = 0; v_secure_system("touch /tmp/idm_upnp_not_operational"); } @@ -488,6 +500,7 @@ void* verify_devices() { //xupnp got stuck for 5 minutes g_message("xupnp is stuck for more than 5 minutes. Triggering IDM restart..."); + IDM_LOG_ERR("xupnp stuck >5min cp null, triggering restart\n"); cp_bgw_null_count = 0; v_secure_system("touch /tmp/idm_upnp_not_operational"); // this is for information to confirm upnp locked with date and time @@ -501,11 +514,13 @@ void* verify_devices() if (gssdp_resource_browser_rescan(GSSDP_RESOURCE_BROWSER(cp_bgw))==FALSE) { g_message("Forced rescan failed for broadband"); + IDM_LOG_ERR("gssdp_resource_browser_rescan failed (cp_bgw)\n"); cp_bgw_inactive_count++; if(cp_bgw_inactive_count > 5) { //xupnp got stuck for 5 minutes g_message("xupnp is stuck for more than 5 minutes. Triggering IDM restart..."); + IDM_LOG_ERR("xupnp stuck >5min cp_bgw inactive, triggering restart\n"); cp_bgw_inactive_count = 0; v_secure_system("touch /tmp/idm_upnp_not_operational"); // this is for information to confirm upnp locked with date and time @@ -528,6 +543,7 @@ void* verify_devices() { //xupnp got stuck for 5 minutes g_message("xupnp is stuck for more than 5 minutes. Triggering IDM restart..."); + IDM_LOG_ERR("xupnp stuck >5min cp_bgw null, triggering restart\n"); cp_bgw_null_count = 0; v_secure_system("touch /tmp/idm_upnp_not_operational"); // this is for information to confirm upnp locked with date and time @@ -660,6 +676,7 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) { deviceAddNo--; g_message("WARNING - Received a null pointer for broadband device device no %u",deviceAddNo); + IDM_LOG_ERR("null pointer received for broadband device no %u\n", deviceAddNo); return; } gchar* sno = gupnp_device_info_get_serial_number (GUPNP_DEVICE_INFO (dproxy)); @@ -727,12 +744,14 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) else { g_message("In available_cb_bgw gateway device receiver id is NULL"); + IDM_LOG_ERR("gateway device receiver id is NULL sno=%s\n", sno); } } } else { g_message("Gateway UDN is NULL"); + IDM_LOG_ERR("gateway UDN is NULL sno=%s\n", sno); } } g_free(sno); @@ -748,6 +767,7 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * { deviceAddNo--; g_message("WARNING - Received a null pointer for gateway device device no %u",deviceAddNo); + IDM_LOG_ERR("null pointer received for gateway device no %u\n", deviceAddNo); return; } gchar* sno = gupnp_device_info_get_serial_number (GUPNP_DEVICE_INFO (dproxy)); @@ -767,6 +787,7 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * else { g_critical("Could not allocate memory for Gwydata. Exiting..."); + IDM_LOG_ERR("could not allocate memory for GwyData, exiting\n"); exit(1); } gwydata->sproxy = gupnp_device_info_get_service(GUPNP_DEVICE_INFO (dproxy), IDM_SERVICE); @@ -774,6 +795,7 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * { deviceAddNo--; g_message("Unable to get the services, sproxy null. returning"); + IDM_LOG_ERR("unable to get services sproxy null sno=%s\n", sno ? sno : "NULL"); return; } if (sno != NULL) @@ -827,11 +849,17 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * callback(&di,1,0); } else + { g_message("Device receiver id is NULL"); + IDM_LOG_ERR("device receiver id is NULL sno=%s\n", sno); + } } } else + { g_message("Device UDN is NULL"); + IDM_LOG_ERR("device UDN is NULL sno=%s\n", sno); + } } g_free(sno); deviceAddNo--; @@ -890,6 +918,8 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info { g_message("some of mandatory values are missing"); g_message("interface=%s port=%d discovery_interval=%d loss_detection_window=%d\n", dc_obj->interface, dc_obj->port, dc_obj->discovery_interval, dc_obj->loss_detection_window); + IDM_LOG_ERR("mandatory values missing interface=%s port=%d interval=%d window=%d\n", + dc_obj->interface, dc_obj->port, dc_obj->discovery_interval, dc_obj->loss_detection_window); return; } g_message("interface=%s port=%d",dc_obj->interface,dc_obj->port); @@ -936,6 +966,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if(access(se_cert_p12, F_OK ) == -1) { g_message("Cannot create p12 cert file"); + IDM_LOG_ERR("cannot create p12 cert file from %s\n", certFile); } else { @@ -952,6 +983,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info strncpy(certFile, dc_obj->sslCert, sizeof(certFile) -1); strncpy(keyFile, dc_obj->sslKey, sizeof(keyFile) -1); g_message("SE HW certificate is not accessible."); + IDM_LOG_ERR("SE HW certificate not accessible, falling back to software cert\n"); } #endif @@ -960,6 +992,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if(rvalue==1) { g_message("id_server_start has facing some issue"); + IDM_LOG_ERR("idm_server_start failed rvalue=%d\n", rvalue); return; } mutex = g_mutex_new (); @@ -1026,6 +1059,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if(0 != err) { g_message("%s: create the event handle thread error!\n", __FUNCTION__); + IDM_LOG_ERR("pthread_create EventHandler failed err=%d\n", err); } } cp_bgw = gupnp_control_point_new(upnpContextDeviceProtect, IDM_DP_CLIENT_DEVICE); @@ -1038,6 +1072,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info else { g_message("%s:mandatory files doesn't present",__FUNCTION__); + IDM_LOG_ERR("mandatory cert/key files not present, running without TLS\n"); } #ifdef GUPNP_0_19 main_loop = g_main_loop_new (NULL, FALSE); @@ -1059,6 +1094,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if (error) { g_message ("Error creating the GUPnP context: %s", error->message); g_critical("%s:Error creating the XUPnP context on %s:%d Error:%s", __FUNCTION__,dc_obj->interface, CLIENT_CONTEXT_PORT, error->message); + IDM_LOG_ERR("GUPnP context creation failed on %s:%d error=%s\n", dc_obj->interface, CLIENT_CONTEXT_PORT, error->message); g_error_free (error); return; } From 5a31a2b35911c61b8d7b18bada290f946eeb56a4 Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Mon, 13 Apr 2026 11:38:59 +0000 Subject: [PATCH 09/12] idm: remove flooding-risk IDM_LOG_ERR calls from verify_devices loop Remove the 6 IDM_LOG_ERR calls inside the verify_devices() polling loop that fire every ~30s when gssdp is broken: - gssdp_resource_browser_rescan failed (cp and cp_bgw) - xupnp stuck >5min cp/cp_bgw inactive count threshold - xupnp stuck >5min cp/cp_bgw null count threshold These will be re-added with rate-limiting in a follow-up commit. The existing g_message calls in the same paths are left untouched. The remaining 24 IDM_LOG_ERR calls (startup / event-driven paths) carry no flooding risk and are retained. --- src/idm_client.c | 6 ------ 1 file changed, 6 deletions(-) diff --git a/src/idm_client.c b/src/idm_client.c index 111382c..8530067 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -473,13 +473,11 @@ void* verify_devices() if (gssdp_resource_browser_rescan(GSSDP_RESOURCE_BROWSER(cp))==FALSE) { g_message("Forced rescan failed"); - IDM_LOG_ERR("gssdp_resource_browser_rescan failed (cp)\n"); cp_bgw_inactive_count++; if(cp_bgw_inactive_count > 5) { //xupnp thread is stuck for 5 minutes g_message("xupnp is stuck for more than 5 minutes. Triggering IDM restart..."); - IDM_LOG_ERR("xupnp stuck >5min cp inactive, triggering restart\n"); cp_bgw_inactive_count = 0; v_secure_system("touch /tmp/idm_upnp_not_operational"); } @@ -500,7 +498,6 @@ void* verify_devices() { //xupnp got stuck for 5 minutes g_message("xupnp is stuck for more than 5 minutes. Triggering IDM restart..."); - IDM_LOG_ERR("xupnp stuck >5min cp null, triggering restart\n"); cp_bgw_null_count = 0; v_secure_system("touch /tmp/idm_upnp_not_operational"); // this is for information to confirm upnp locked with date and time @@ -514,13 +511,11 @@ void* verify_devices() if (gssdp_resource_browser_rescan(GSSDP_RESOURCE_BROWSER(cp_bgw))==FALSE) { g_message("Forced rescan failed for broadband"); - IDM_LOG_ERR("gssdp_resource_browser_rescan failed (cp_bgw)\n"); cp_bgw_inactive_count++; if(cp_bgw_inactive_count > 5) { //xupnp got stuck for 5 minutes g_message("xupnp is stuck for more than 5 minutes. Triggering IDM restart..."); - IDM_LOG_ERR("xupnp stuck >5min cp_bgw inactive, triggering restart\n"); cp_bgw_inactive_count = 0; v_secure_system("touch /tmp/idm_upnp_not_operational"); // this is for information to confirm upnp locked with date and time @@ -543,7 +538,6 @@ void* verify_devices() { //xupnp got stuck for 5 minutes g_message("xupnp is stuck for more than 5 minutes. Triggering IDM restart..."); - IDM_LOG_ERR("xupnp stuck >5min cp_bgw null, triggering restart\n"); cp_bgw_null_count = 0; v_secure_system("touch /tmp/idm_upnp_not_operational"); // this is for information to confirm upnp locked with date and time From 39718043dc8305164803b24054c307be16489782 Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Tue, 14 Apr 2026 05:16:08 +0000 Subject: [PATCH 10/12] idm: fix fopen fallback, strip trailing \n from log call sites - idm_log.c: when fopen(IDM_LOG_FILE) fails, emit a rate-limited diagnostic via stderr (once per 60 s) with errno string instead of silently dropping the message. Add and includes. - idm_client.c: remove trailing \n from all 24 IDM_LOG_ERR/INFO fmt strings; idm_consolelog already appends a newline via fputc, so the extra \n was producing blank lines between log entries. Addresses Copilot review comments #1-#4 on idm_log.c/idm_log.h. --- src/idm_client.c | 48 ++++++++++++++++++++++++------------------------ src/idm_log.c | 18 ++++++++++++++++++ 2 files changed, 42 insertions(+), 24 deletions(-) diff --git a/src/idm_client.c b/src/idm_client.c index 8530067..5505ff8 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -273,7 +273,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if(rdkconfig_get(&pass_phrase, &pass_size, se_cert_conf_file) == RDKCONFIG_FAIL) { g_message("Error in getting passcode\n"); - IDM_LOG_ERR("rdkconfig_get failed for SE cert passcode\n"); + IDM_LOG_ERR("rdkconfig_get failed for SE cert passcode"); } else { @@ -292,7 +292,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac else { g_message(" Failed to generate g_tls cert from SE certificate\n"); - IDM_LOG_ERR("g_tls_certificate_new_from_file_with_password failed: %s\n", + IDM_LOG_ERR("g_tls_certificate_new_from_file_with_password failed: %s", xupnp_error ? xupnp_error->message : "unknown error"); if(xupnp_error) { @@ -317,14 +317,14 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if ((certFile[0] == '\0') || (keyFile[0] == '\0')) { g_message(" Certificate or Key file NULL"); - IDM_LOG_ERR("certFile or keyFile path is empty (HW cert fallback path)\n"); + IDM_LOG_ERR("certFile or keyFile path is empty (HW cert fallback path)"); return G_TLS_INTERACTION_FAILED; } if((access(certFile,F_OK ) != 0) || (access(keyFile,F_OK ) != 0)) { g_message(" Certificate or Key file does not exist"); - IDM_LOG_ERR("certFile or keyFile not found certFile=%s keyFile=%s\n", certFile, keyFile); + IDM_LOG_ERR("certFile or keyFile not found certFile=%s keyFile=%s", certFile, keyFile); return G_TLS_INTERACTION_FAILED; } @@ -334,7 +334,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if(cert == NULL) { g_message("Certificate creation failed from cert and key files"); - IDM_LOG_ERR("g_tls_certificate_new_from_files failed certFile=%s keyFile=%s\n", certFile, keyFile); + IDM_LOG_ERR("g_tls_certificate_new_from_files failed certFile=%s keyFile=%s", certFile, keyFile); if(xupnp_error != NULL) { @@ -350,14 +350,14 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if ((certFile[0] == '\0') || (keyFile[0] == '\0')) { g_message(" Certificate or Key file NULL"); - IDM_LOG_ERR("certFile or keyFile path is empty\n"); + IDM_LOG_ERR("certFile or keyFile path is empty"); return G_TLS_INTERACTION_FAILED; } if((access(certFile,F_OK ) != 0) || (access(keyFile,F_OK ) != 0)) { g_message(" Certificate or Key file does not exist"); - IDM_LOG_ERR("certFile or keyFile not found certFile=%s keyFile=%s\n", certFile, keyFile); + IDM_LOG_ERR("certFile or keyFile not found certFile=%s keyFile=%s", certFile, keyFile); return G_TLS_INTERACTION_FAILED; } @@ -367,7 +367,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if(cert == NULL) { g_message("Certificate creation failed from cert and key files"); - IDM_LOG_ERR("g_tls_certificate_new_from_files failed certFile=%s keyFile=%s\n", certFile, keyFile); + IDM_LOG_ERR("g_tls_certificate_new_from_files failed certFile=%s keyFile=%s", certFile, keyFile); if(xupnp_error != NULL) { g_message("Failure reason for certificate creation: %s\n", xupnp_error->message ); @@ -433,7 +433,7 @@ GError *error = NULL; if ( NULL != error ) //Didn't went well { g_message ("%s process gw services Error: %s\n", requestFn, error->message); - IDM_LOG_ERR("gupnp_service_proxy_send_action failed fn=%s error=%s\n", requestFn, error->message); + IDM_LOG_ERR("gupnp_service_proxy_send_action failed fn=%s error=%s", requestFn, error->message); if ( isInCriticalPath ) // Update telemetry { g_message("TELEMETRY_XUPNP_PARTIAL_DISCOVERY:%d,%s",error->code, requestFn); @@ -670,7 +670,7 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) { deviceAddNo--; g_message("WARNING - Received a null pointer for broadband device device no %u",deviceAddNo); - IDM_LOG_ERR("null pointer received for broadband device no %u\n", deviceAddNo); + IDM_LOG_ERR("null pointer received for broadband device no %u", deviceAddNo); return; } gchar* sno = gupnp_device_info_get_serial_number (GUPNP_DEVICE_INFO (dproxy)); @@ -738,14 +738,14 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) else { g_message("In available_cb_bgw gateway device receiver id is NULL"); - IDM_LOG_ERR("gateway device receiver id is NULL sno=%s\n", sno); + IDM_LOG_ERR("gateway device receiver id is NULL sno=%s", sno); } } } else { g_message("Gateway UDN is NULL"); - IDM_LOG_ERR("gateway UDN is NULL sno=%s\n", sno); + IDM_LOG_ERR("gateway UDN is NULL sno=%s", sno); } } g_free(sno); @@ -761,7 +761,7 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * { deviceAddNo--; g_message("WARNING - Received a null pointer for gateway device device no %u",deviceAddNo); - IDM_LOG_ERR("null pointer received for gateway device no %u\n", deviceAddNo); + IDM_LOG_ERR("null pointer received for gateway device no %u", deviceAddNo); return; } gchar* sno = gupnp_device_info_get_serial_number (GUPNP_DEVICE_INFO (dproxy)); @@ -781,7 +781,7 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * else { g_critical("Could not allocate memory for Gwydata. Exiting..."); - IDM_LOG_ERR("could not allocate memory for GwyData, exiting\n"); + IDM_LOG_ERR("could not allocate memory for GwyData, exiting"); exit(1); } gwydata->sproxy = gupnp_device_info_get_service(GUPNP_DEVICE_INFO (dproxy), IDM_SERVICE); @@ -789,7 +789,7 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * { deviceAddNo--; g_message("Unable to get the services, sproxy null. returning"); - IDM_LOG_ERR("unable to get services sproxy null sno=%s\n", sno ? sno : "NULL"); + IDM_LOG_ERR("unable to get services sproxy null sno=%s", sno ? sno : "NULL"); return; } if (sno != NULL) @@ -845,14 +845,14 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * else { g_message("Device receiver id is NULL"); - IDM_LOG_ERR("device receiver id is NULL sno=%s\n", sno); + IDM_LOG_ERR("device receiver id is NULL sno=%s", sno); } } } else { g_message("Device UDN is NULL"); - IDM_LOG_ERR("device UDN is NULL sno=%s\n", sno); + IDM_LOG_ERR("device UDN is NULL sno=%s", sno); } } g_free(sno); @@ -912,7 +912,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info { g_message("some of mandatory values are missing"); g_message("interface=%s port=%d discovery_interval=%d loss_detection_window=%d\n", dc_obj->interface, dc_obj->port, dc_obj->discovery_interval, dc_obj->loss_detection_window); - IDM_LOG_ERR("mandatory values missing interface=%s port=%d interval=%d window=%d\n", + IDM_LOG_ERR("mandatory values missing interface=%s port=%d interval=%d window=%d", dc_obj->interface, dc_obj->port, dc_obj->discovery_interval, dc_obj->loss_detection_window); return; } @@ -960,7 +960,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if(access(se_cert_p12, F_OK ) == -1) { g_message("Cannot create p12 cert file"); - IDM_LOG_ERR("cannot create p12 cert file from %s\n", certFile); + IDM_LOG_ERR("cannot create p12 cert file from %s", certFile); } else { @@ -977,7 +977,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info strncpy(certFile, dc_obj->sslCert, sizeof(certFile) -1); strncpy(keyFile, dc_obj->sslKey, sizeof(keyFile) -1); g_message("SE HW certificate is not accessible."); - IDM_LOG_ERR("SE HW certificate not accessible, falling back to software cert\n"); + IDM_LOG_ERR("SE HW certificate not accessible, falling back to software cert"); } #endif @@ -986,7 +986,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if(rvalue==1) { g_message("id_server_start has facing some issue"); - IDM_LOG_ERR("idm_server_start failed rvalue=%d\n", rvalue); + IDM_LOG_ERR("idm_server_start failed rvalue=%d", rvalue); return; } mutex = g_mutex_new (); @@ -1053,7 +1053,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if(0 != err) { g_message("%s: create the event handle thread error!\n", __FUNCTION__); - IDM_LOG_ERR("pthread_create EventHandler failed err=%d\n", err); + IDM_LOG_ERR("pthread_create EventHandler failed err=%d", err); } } cp_bgw = gupnp_control_point_new(upnpContextDeviceProtect, IDM_DP_CLIENT_DEVICE); @@ -1066,7 +1066,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info else { g_message("%s:mandatory files doesn't present",__FUNCTION__); - IDM_LOG_ERR("mandatory cert/key files not present, running without TLS\n"); + IDM_LOG_ERR("mandatory cert/key files not present, running without TLS"); } #ifdef GUPNP_0_19 main_loop = g_main_loop_new (NULL, FALSE); @@ -1088,7 +1088,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if (error) { g_message ("Error creating the GUPnP context: %s", error->message); g_critical("%s:Error creating the XUPnP context on %s:%d Error:%s", __FUNCTION__,dc_obj->interface, CLIENT_CONTEXT_PORT, error->message); - IDM_LOG_ERR("GUPnP context creation failed on %s:%d error=%s\n", dc_obj->interface, CLIENT_CONTEXT_PORT, error->message); + IDM_LOG_ERR("GUPnP context creation failed on %s:%d error=%s", dc_obj->interface, CLIENT_CONTEXT_PORT, error->message); g_error_free (error); return; } diff --git a/src/idm_log.c b/src/idm_log.c index 5b4c618..d526253 100644 --- a/src/idm_log.c +++ b/src/idm_log.c @@ -31,10 +31,14 @@ #include #include #include +#include +#include #include "idm_log.h" static FILE *idm_log_fp = NULL; static pthread_mutex_t idm_log_mutex = PTHREAD_MUTEX_INITIALIZER; +/* Rate-limit fopen() failure reports: log at most once every 60 seconds */ +static time_t idm_log_fopen_fail_last = 0; /** * idm_log_reopen — return the current log fd, reopening if rdklogger has @@ -58,7 +62,21 @@ static FILE *idm_log_reopen(void) } } if (!idm_log_fp) + { idm_log_fp = fopen(IDM_LOG_FILE, "a"); + if (!idm_log_fp) + { + /* Report fopen failure via stderr, rate-limited to once per 60s */ + time_t now = time(NULL); + if (now - idm_log_fopen_fail_last >= 60) + { + idm_log_fopen_fail_last = now; + fprintf(stderr, + "IDM: fopen(%s) failed: %s\n", + IDM_LOG_FILE, strerror(errno)); + } + } + } return idm_log_fp; } From 13ff1a74b7a730b8d7fea0a19b53c010df24485a Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Tue, 14 Apr 2026 09:44:48 +0000 Subject: [PATCH 11/12] idm: remove IDM_LOG_INFO calls already covered by CcspTraceInfo The three IDM_LOG_INFO prints: - start_discovery called for serial %s (line 927) - device associated sno=%s (BGW path, line 732) - device associated sno=%s (XB path, line 839) are redundant with CcspTraceInfo prints in rdk-interdevicemanager: - discovery start: CcspTraceInfo line 770 logs base MAC + start - pairing: CcspTraceInfo line 378 in discovery_cb logs IPv4/IPv6/MAC/ discovery_status/authentication_status for every callback() invocation Removing avoids duplicate entries in Consolelog.txt.0 and eliminates the noisy self-association entries seen in field logs (MWN2983C0544 appearing as 'device associated' alongside the real XB serial). --- src/idm_client.c | 3 --- 1 file changed, 3 deletions(-) diff --git a/src/idm_client.c b/src/idm_client.c index 5505ff8..3b0a404 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -729,7 +729,6 @@ device_proxy_available_cb_bgw (GUPnPControlPoint *cp, GUPnPDeviceProxy *dproxy) g_mutex_unlock(mutex); g_message("Associating device %s", sno); g_message("TELEMETRY_IDM_DEVICE_ASSOCIATED:%s", sno); - IDM_LOG_INFO("device associated sno=%s", sno); #if defined(ENABLE_FEATURE_TELEMETRY2_0) t2_event_s("IDM_DEVICE_ASSOCIATED_split", sno); #endif @@ -836,7 +835,6 @@ static void device_proxy_available_cb (GUPnPControlPoint *cp, GUPnPDeviceProxy * g_mutex_unlock(mutex); g_message("Inserted new/updated device %s in the list", sno); g_message("TELEMETRY_IDM_DEVICE_ASSOCIATED:%s", sno); - IDM_LOG_INFO("device associated sno=%s", sno); #if defined(ENABLE_FEATURE_TELEMETRY2_0) t2_event_s("IDM_DEVICE_ASSOCIATED_split", sno); #endif @@ -924,7 +922,6 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info getserialnum(ownSerialNo); callback=func_callback; g_message("TELEMETRY_IDM_DISCOVERY_STARTED:%s", ownSerialNo->str); - IDM_LOG_INFO("start_discovery called for serial %s", ownSerialNo->str); #if defined(ENABLE_FEATURE_TELEMETRY2_0) t2_event_s("IDM_DISCOVERY_STARTED_split", ownSerialNo->str); #endif From 407ce533d9e6f7a53fe4017860352443a8636fff Mon Sep 17 00:00:00 2001 From: veeraputhiran Date: Tue, 12 May 2026 08:33:30 +0000 Subject: [PATCH 12/12] xupnp: route IDM logs to InterDeviceManager.txt.0; redact cert paths MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 1. Restore IDM_LOG_FILE to /rdklogs/logs/InterDeviceManager.txt.0 (reverts commit f4755b1 which changed it to Consolelog.txt.0). UPNP/IDM log output now lands in the same file used by the rdk-interdevicemanager component — InterDeviceManager.txt.0 — consistent with the log4crc appender for LOG.RDK.INTERDEVICEMANAGER. All rotation/permissions behaviour is unchanged (rdklogger still owns the file; idm_log_reopen() detects inode change on rotation). 2. Sanitize sensitive file-path logging in idm_client.c (5 call sites introduced by veeraputhiran commit b94fc4a): - 'certFile or keyFile not found certFile=%s keyFile=%s' (×2) - 'g_tls_certificate_new_from_files failed certFile=%s keyFile=%s' (×2) - 'cannot create p12 cert file from %s' Each now logs only the high-level failure without the actual path. 3. Remove absolute-path exposure in idm_log.c stderr fallback (introduced by commit 3971804): the rate-limited fopen-failure message no longer emits IDM_LOG_FILE in the format string. No new log files created. No functional behaviour changed. --- src/idm_client.c | 10 +++++----- src/idm_log.c | 4 ++-- src/idm_log.h | 6 +++--- 3 files changed, 10 insertions(+), 10 deletions(-) diff --git a/src/idm_client.c b/src/idm_client.c index 3b0a404..cecd0d1 100644 --- a/src/idm_client.c +++ b/src/idm_client.c @@ -324,7 +324,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if((access(certFile,F_OK ) != 0) || (access(keyFile,F_OK ) != 0)) { g_message(" Certificate or Key file does not exist"); - IDM_LOG_ERR("certFile or keyFile not found certFile=%s keyFile=%s", certFile, keyFile); + IDM_LOG_ERR("certFile or keyFile not found"); return G_TLS_INTERACTION_FAILED; } @@ -334,7 +334,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if(cert == NULL) { g_message("Certificate creation failed from cert and key files"); - IDM_LOG_ERR("g_tls_certificate_new_from_files failed certFile=%s keyFile=%s", certFile, keyFile); + IDM_LOG_ERR("g_tls_certificate_new_from_files failed"); if(xupnp_error != NULL) { @@ -357,7 +357,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if((access(certFile,F_OK ) != 0) || (access(keyFile,F_OK ) != 0)) { g_message(" Certificate or Key file does not exist"); - IDM_LOG_ERR("certFile or keyFile not found certFile=%s keyFile=%s", certFile, keyFile); + IDM_LOG_ERR("certFile or keyFile not found"); return G_TLS_INTERACTION_FAILED; } @@ -367,7 +367,7 @@ xupnp_tls_interaction_request_certificate (GTlsInteraction *interac if(cert == NULL) { g_message("Certificate creation failed from cert and key files"); - IDM_LOG_ERR("g_tls_certificate_new_from_files failed certFile=%s keyFile=%s", certFile, keyFile); + IDM_LOG_ERR("g_tls_certificate_new_from_files failed"); if(xupnp_error != NULL) { g_message("Failure reason for certificate creation: %s\n", xupnp_error->message ); @@ -957,7 +957,7 @@ void start_discovery(discovery_config_t* dc_obj,int (*func_callback)(device_info if(access(se_cert_p12, F_OK ) == -1) { g_message("Cannot create p12 cert file"); - IDM_LOG_ERR("cannot create p12 cert file from %s", certFile); + IDM_LOG_ERR("cannot create p12 cert file"); } else { diff --git a/src/idm_log.c b/src/idm_log.c index d526253..41911e9 100644 --- a/src/idm_log.c +++ b/src/idm_log.c @@ -72,8 +72,8 @@ static FILE *idm_log_reopen(void) { idm_log_fopen_fail_last = now; fprintf(stderr, - "IDM: fopen(%s) failed: %s\n", - IDM_LOG_FILE, strerror(errno)); + "IDM: log file unavailable: %s\n", + strerror(errno)); } } } diff --git a/src/idm_log.h b/src/idm_log.h index fe40f55..f661cc7 100644 --- a/src/idm_log.h +++ b/src/idm_log.h @@ -20,7 +20,7 @@ * @file idm_log.h * @brief IDM logging interface — shared between idm_client.c and idm_server.c. * - * All writes go to /rdklogs/logs/Consolelog.txt.0. + * All writes go to /rdklogs/logs/InterDeviceManager.txt.0. * Log rotation is handled externally by rdklogger; the open file descriptor * is transparently reopened after rotation via inode comparison. */ @@ -28,10 +28,10 @@ #ifndef IDM_LOG_H #define IDM_LOG_H -#define IDM_LOG_FILE "/rdklogs/logs/Consolelog.txt.0" +#define IDM_LOG_FILE "/rdklogs/logs/InterDeviceManager.txt.0" /** - * IDM_LOG_INFO(fmt, ...) — write a timestamped INFO line to Consolelog.txt.0. + * IDM_LOG_INFO(fmt, ...) — write a timestamped INFO line to InterDeviceManager.txt.0. * IDM_LOG_ERR(fmt, ...) — write a timestamped ERROR line. * * A newline is appended automatically; do not include a trailing "\n" in fmt.