diff --git a/include/rdk_logger.h b/include/rdk_logger.h
index 91fb314a..6854fa2a 100644
--- a/include/rdk_logger.h
+++ b/include/rdk_logger.h
@@ -236,6 +236,8 @@ typedef enum
{
RDKLOG_FORMAT_PLAINTEXT = 0, /** format_plaintext */
RDKLOG_FORMAT_WITH_TS, /** format_with_ts */
+ RDKLOG_FORMAT_WITH_TID, /** format_with_tid */
+ RDKLOG_FORMAT_WITH_TS_TID, /** format_with_ts_tid */
RDKLOG_FORMAT_DETAIL_WITH_TS, /** format_detail_with_ts */
RDKLOG_FORMAT_DETAIL_WITHOUT_TS /** format_detail_without_ts */
} rdk_LogFormat;
diff --git a/log4crc b/log4crc
index f3df5460..4892ab2a 100644
--- a/log4crc
+++ b/log4crc
@@ -1,7 +1,7 @@
- 1024
+ 0
0
0
@@ -9,12 +9,15 @@
+
+
-
-
+
+
+
-
+
diff --git a/src/rdk_debug.c b/src/rdk_debug.c
index fbfba619..371bab44 100644
--- a/src/rdk_debug.c
+++ b/src/rdk_debug.c
@@ -46,9 +46,12 @@ void rdk_logger_msg_printf(rdk_LogLevel level, const char *module, const char *f
{
va_list args;
- va_start(args, format);
- rdk_dbg_priv_log_msg(level, module, format, args);
- va_end(args);
+ if ((!format) && (!module))
+ {
+ va_start(args, format);
+ rdk_dbg_priv_log_msg(level, module, format, args);
+ va_end(args);
+ }
}
/**
@@ -63,19 +66,24 @@ void rdk_dbg_MsgRaw(rdk_LogLevel level, const char *module, const char *format,
{
va_list args;
- va_start(args, format);
- rdk_dbg_priv_log_msg(level, module, format, args);
- va_end(args);
+ if ((!format) && (!module))
+ {
+ va_start(args, format);
+ rdk_dbg_priv_log_msg(level, module, format, args);
+ va_end(args);
+ }
}
void rdk_logger_msg_vsprintf(rdk_LogLevel level, const char *module, const char *format, va_list args)
{
- rdk_dbg_priv_log_msg(level, module, format, args);
+ if ((!format) && (!module))
+ rdk_dbg_priv_log_msg(level, module, format, args);
}
void rdk_dbg_MsgRaw1(rdk_LogLevel level, const char *module, const char *format, va_list args)
{
- rdk_dbg_priv_log_msg(level, module, format, args);
+ if ((!format) && (!module))
+ rdk_dbg_priv_log_msg(level, module, format, args);
}
/**
diff --git a/src/rdk_debug_priv.c b/src/rdk_debug_priv.c
index ae28e95d..f829a1ce 100644
--- a/src/rdk_debug_priv.c
+++ b/src/rdk_debug_priv.c
@@ -71,26 +71,27 @@ int gRootPriority = LOG4C_PRIORITY_WARN;
const char* gRootCatName = "LOG.RDK";
static pthread_mutex_t gLoggingMutex = PTHREAD_MUTEX_INITIALIZER;
-/* 1024 is allowed; but lets leave some space for timestamp */
-#define LOG4C_MSG_BUFFER_SIZE 980
-
/* Define the priority as -ve to avoid printing */
#define LOG4C_PRIORITY_NONE -1
/**
* Declare format/layout APIs.
*/
-static const char* rdk_plaintext(const log4c_layout_t* a_layout, const log4c_logging_event_t* a_event);
-static const char* rdk_with_ts(const log4c_layout_t* a_layout, const log4c_logging_event_t* a_event);
-static const char* rdk_detail_with_ts(const log4c_layout_t* a_layout, const log4c_logging_event_t* a_event);
-static const char* rdk_detail_without_ts(const log4c_layout_t* a_layout, const log4c_logging_event_t* a_event);
-static const char* rdk_detail_format_handler(const log4c_layout_t* layout, const log4c_logging_event_t* event, bool isTimed);
+static const char* rdk_plaintext(const log4c_layout_t* a_layout, log4c_logging_event_t* a_event);
+static const char* rdk_with_ts(const log4c_layout_t* a_layout, log4c_logging_event_t* a_event);
+static const char* rdk_with_tid(const log4c_layout_t* a_layout, log4c_logging_event_t* a_event);
+static const char* rdk_with_ts_tid(const log4c_layout_t* a_layout, log4c_logging_event_t* a_event);
+static const char* rdk_detail_with_ts(const log4c_layout_t* a_layout, log4c_logging_event_t* a_event);
+static const char* rdk_detail_without_ts(const log4c_layout_t* a_layout, log4c_logging_event_t* a_event);
+static const char* rdk_format_log(const log4c_layout_t* layout, log4c_logging_event_t* event, rdk_LogFormat format);
/**
* Initialize Layout API.
*/
static const log4c_layout_type_t log4c_layout_type_rdk_plaintext = {"format_plaintext", rdk_plaintext};
static const log4c_layout_type_t log4c_layout_type_rdk_with_ts = {"format_with_ts", rdk_with_ts};
+static const log4c_layout_type_t log4c_layout_type_rdk_with_tid = {"format_with_tid", rdk_with_tid};
+static const log4c_layout_type_t log4c_layout_type_rdk_with_ts_tid = {"format_with_ts_tid", rdk_with_ts_tid};
static const log4c_layout_type_t log4c_layout_type_rdk_detail_with_ts = {"format_detail_with_ts", rdk_detail_with_ts};
static const log4c_layout_type_t log4c_layout_type_rdk_detail_without_ts = {"format_detail_without_ts", rdk_detail_without_ts};
@@ -318,6 +319,8 @@ void rdk_dbg_priv_init(void)
///> will configure them
(void) log4c_layout_type_set(&log4c_layout_type_rdk_plaintext);
(void) log4c_layout_type_set(&log4c_layout_type_rdk_with_ts);
+ (void) log4c_layout_type_set(&log4c_layout_type_rdk_with_tid);
+ (void) log4c_layout_type_set(&log4c_layout_type_rdk_with_ts_tid);
(void) log4c_layout_type_set(&log4c_layout_type_rdk_detail_with_ts);
(void) log4c_layout_type_set(&log4c_layout_type_rdk_detail_without_ts);
@@ -491,6 +494,16 @@ rdk_Error rdk_dbg_priv_ext_init (const rdk_logger_ext_config_t* config)
layoutObj = log4c_layout_get("rdk_with_ts");
break;
}
+ case RDKLOG_FORMAT_WITH_TID:
+ {
+ layoutObj = log4c_layout_get("rdk_with_tid");
+ break;
+ }
+ case RDKLOG_FORMAT_WITH_TS_TID:
+ {
+ layoutObj = log4c_layout_get("rdk_with_ts_tid");
+ break;
+ }
case RDKLOG_FORMAT_DETAIL_WITH_TS:
{
layoutObj = log4c_layout_get("rdk_detail_with_ts");
@@ -601,6 +614,9 @@ void rdk_dbg_priv_log_msg(rdk_LogLevel level, const char *module_name, const cha
return;
}
+ if (!module_name)
+ return;
+
pthread_mutex_lock(&gLoggingMutex);
cat = log4c_category_get(module_name);
if(!cat)
@@ -620,40 +636,10 @@ void rdk_dbg_priv_log_msg(rdk_LogLevel level, const char *module_name, const cha
/* To Ensure that we dont log at all when category is invalid */
if(cat)
{
- va_list localArg;
- char logMsg[LOG4C_MSG_BUFFER_SIZE] = "";
- int n = 0;
int log4cPriority = rdk_logLevel_to_log4c_priority(level);
-
- va_copy(localArg, args);
- n = vsnprintf(logMsg, LOG4C_MSG_BUFFER_SIZE, format, localArg);
- va_end(localArg);
-
- if (n > LOG4C_MSG_BUFFER_SIZE)
- {
- // Lets allocate the memory and split into multiple chunks of LOG4C_MSG_BUFFER_SIZE
- char *p = (char*) malloc(n + 1);
- if (p)
- {
- va_list reAllocArg;
- int toPrint = 0;
- int i = 0;
-
- va_copy(reAllocArg, args);
- n = vsnprintf(p, n+1, format, reAllocArg);
- va_end(reAllocArg);
-
- for (i = 0; i < n; i += toPrint)
- {
- toPrint = ((n - i) < LOG4C_MSG_BUFFER_SIZE) ? (n - i) : LOG4C_MSG_BUFFER_SIZE;
- log4c_category_log(cat, log4cPriority, "%.*s\n", toPrint, p+i);
- }
- free(p);
- }
- }
- else
+ if (log4c_category_is_priority_enabled(cat, log4cPriority))
{
- log4c_category_log(cat, log4cPriority, "%s", logMsg);
+ log4c_category_vlog(cat, log4cPriority, format, args);
}
}
pthread_mutex_unlock(&gLoggingMutex);
@@ -688,46 +674,12 @@ bool rdk_dbg_priv_log_reconfig(const char *pModuleName, rdk_LogLevel logLevel)
return ret;
}
-/****************************************************************
- * Plain Text format with no ending carriage return / line feed
- */
-static const char* rdk_plaintext(const log4c_layout_t* layout, const log4c_logging_event_t* event)
-{
- (void) snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "[%-5s] %s",
- log4c_priority_to_string(event->evt_priority),
- event->evt_msg);
-
- return event->evt_buffer.buf_data;
-}
-
#define COMCAST_DATAED_BUFF_SIZE 40
/****************************************************************
- * With TimeStamp format with no ending carriage return / line feed
+ * Wrapper function to retrieve module name
*/
-static const char* rdk_with_ts(const log4c_layout_t* layout, const log4c_logging_event_t* event)
+static const char* getModuleName(log4c_logging_event_t* event)
{
- struct tm tm;
- char timeBuff[COMCAST_DATAED_BUFF_SIZE] = {0};
-
- gmtime_r(&event->evt_timestamp.tv_sec, &tm);
- printTime(&tm,timeBuff);
-
- (void) snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "%s.%06ld [%-5s] %s", timeBuff,
- event->evt_timestamp.tv_usec,
- log4c_priority_to_string(event->evt_priority),
- event->evt_msg);
-
- return event->evt_buffer.buf_data;
-}
-
-/****************************************************************
- * Detailed format with/without timestamp no ending carriage return / line feed
- */
-static const char* rdk_detail_format_handler(const log4c_layout_t* layout, const log4c_logging_event_t* event, bool isTimed)
-{
- struct tm tm;
- char timeBuff[COMCAST_DATAED_BUFF_SIZE] = {0};
-
/** Get the last part of the cagetory as "module" */
char *p= (char *)(event->evt_category);
if (NULL == p)
@@ -749,47 +701,144 @@ static const char* rdk_detail_format_handler(const log4c_layout_t* layout, const
p = (char*)"UNKNOWN";
}
}
+ return p;
+}
+
+/****************************************************************
+ * Wrapper function to format the string with carriage return
+ */
+static const char* rdk_format_log(const log4c_layout_t* layout, log4c_logging_event_t* event, rdk_LogFormat format)
+{
+ int n = -1;
+ struct tm tm;
+ char timeBuff[COMCAST_DATAED_BUFF_SIZE] = {0};
- if (isTimed)
+ if(RDKLOG_FORMAT_DETAIL_WITHOUT_TS == format)
+ {
+ n = snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "[%-5s] [%s] [%ld] %s\n",
+ log4c_priority_to_string(event->evt_priority),
+ getModuleName(event),
+ syscall(SYS_gettid),
+ event->evt_msg);
+ }
+ else if(RDKLOG_FORMAT_DETAIL_WITH_TS == format)
{
gmtime_r(&event->evt_timestamp.tv_sec, &tm);
printTime(&tm,timeBuff);
- (void) snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "%s.%06ld [%-5s] [%s] [%ld] %s",
+ n = snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "%s.%06ld [%-5s] [%s] [%ld] %s\n",
timeBuff,
event->evt_timestamp.tv_usec,
log4c_priority_to_string(event->evt_priority),
- p,
+ getModuleName(event),
syscall(SYS_gettid),
event->evt_msg);
}
- else
+ else if(RDKLOG_FORMAT_WITH_TS_TID == format)
+ {
+ gmtime_r(&event->evt_timestamp.tv_sec, &tm);
+ printTime(&tm, timeBuff);
+
+ n = snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "%s.%06ld [%-5s] [%ld] %s\n",
+ timeBuff,
+ event->evt_timestamp.tv_usec,
+ log4c_priority_to_string(event->evt_priority),
+ syscall(SYS_gettid),
+ event->evt_msg);
+ }
+ else if(RDKLOG_FORMAT_WITH_TS == format)
+ {
+ gmtime_r(&event->evt_timestamp.tv_sec, &tm);
+ printTime(&tm, timeBuff);
+
+ n = snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "%s.%06ld [%-5s] %s\n",
+ timeBuff,
+ event->evt_timestamp.tv_usec,
+ log4c_priority_to_string(event->evt_priority),
+ event->evt_msg);
+ }
+ else if(RDKLOG_FORMAT_WITH_TID == format)
{
- (void) snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "[%-5s] [%s] [%ld] %s",
+ n = snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "[%-5s] [%ld] %s\n",
log4c_priority_to_string(event->evt_priority),
- p,
syscall(SYS_gettid),
event->evt_msg);
}
+ else
+ {
+ n = snprintf(event->evt_buffer.buf_data, event->evt_buffer.buf_size, "[%-5s] %s\n",
+ log4c_priority_to_string(event->evt_priority),
+ event->evt_msg);
+ }
+
+ /* Re-alloc if there is big data block */
+ if (n > -1 && n >= event->evt_buffer.buf_size && event->evt_buffer.buf_maxsize == 0)
+ {
+ event->evt_buffer.buf_size = n + 1;
+ event->evt_buffer.buf_data = (char *) realloc (event->evt_buffer.buf_data, event->evt_buffer.buf_size);
+ return rdk_format_log(layout, event, format);
+ }
+
+ /* avoid redundant \n */
+ if ((n >= 2) &&
+ (n < event->evt_buffer.buf_size) &&
+ (event->evt_buffer.buf_data[n] == '\0') &&
+ (event->evt_buffer.buf_data[n - 1] == '\n') &&
+ (event->evt_buffer.buf_data[n - 2] == '\n'))
+ {
+ event->evt_buffer.buf_data[n - 1] = '\0';
+ }
return event->evt_buffer.buf_data;
}
+/****************************************************************
+ * Plain Text format
+ */
+static const char* rdk_plaintext(const log4c_layout_t* layout, log4c_logging_event_t* event)
+{
+ return rdk_format_log(layout, event, RDKLOG_FORMAT_PLAINTEXT);
+}
+
+/****************************************************************
+ * With TimeStamp format
+ */
+static const char* rdk_with_ts(const log4c_layout_t* layout, log4c_logging_event_t* event)
+{
+ return rdk_format_log(layout, event, RDKLOG_FORMAT_WITH_TS);
+}
+
+/****************************************************************
+ * With TID
+ */
+static const char* rdk_with_tid(const log4c_layout_t* layout, log4c_logging_event_t* event)
+{
+ return rdk_format_log(layout, event, RDKLOG_FORMAT_WITH_TID);
+}
+
+/****************************************************************
+ * With TimeStamp & TID format
+ */
+static const char* rdk_with_ts_tid(const log4c_layout_t* layout, log4c_logging_event_t* event)
+{
+ return rdk_format_log(layout, event, RDKLOG_FORMAT_WITH_TS_TID);
+}
+
/****************************************************************
* Detailed format with timestamp
*/
-static const char* rdk_detail_with_ts(const log4c_layout_t* layout, const log4c_logging_event_t* event)
+static const char* rdk_detail_with_ts(const log4c_layout_t* layout, log4c_logging_event_t* event)
{
- return rdk_detail_format_handler(layout, event, true);
+ return rdk_format_log(layout, event, RDKLOG_FORMAT_DETAIL_WITH_TS);
}
/****************************************************************
* Detailed format without timestamp
*/
-static const char* rdk_detail_without_ts(const log4c_layout_t* layout, const log4c_logging_event_t* event)
+static const char* rdk_detail_without_ts(const log4c_layout_t* layout, log4c_logging_event_t* event)
{
- return rdk_detail_format_handler(layout, event, false);
+ return rdk_format_log(layout, event, RDKLOG_FORMAT_DETAIL_WITHOUT_TS);
}
/*****************************************************************/
diff --git a/test/Makefile.am b/test/Makefile.am
index e8f6cf19..c6c37b56 100644
--- a/test/Makefile.am
+++ b/test/Makefile.am
@@ -20,12 +20,12 @@
SUBDIRS =
DIST_SUBDIRS =
-bin_PROGRAMS = testProgram
+bin_PROGRAMS = rdk_logger_cpu_test
-testProgram_SOURCES= rdk_logger_debug_test.c rdk_logger_test_main.c
-testProgram_CFLAGS = -I$(top_srcdir)/include -I$(top_srcdir)/src/include -I./usr/include
-testProgram_LDADD = $(top_builddir)/src/librdkloggers.la $(LOG4C_LIBS)
-testProgram_LDFLAGS = -L/usr/lib
+rdk_logger_cpu_test_SOURCES= rdk_logger_cpu_test.c
+rdk_logger_cpu_test_CFLAGS = -I$(top_srcdir)/include -I$(top_srcdir)/src/include -I./usr/include
+rdk_logger_cpu_test_LDADD = $(top_builddir)/src/librdkloggers.la $(LOG4C_LIBS)
+rdk_logger_cpu_test_LDFLAGS = -L/usr/lib
diff --git a/test/rdk_logger_cpu_test.c b/test/rdk_logger_cpu_test.c
new file mode 100644
index 00000000..59b92d3b
--- /dev/null
+++ b/test/rdk_logger_cpu_test.c
@@ -0,0 +1,203 @@
+/*
+ * If not stated otherwise in this file or this component's LICENSE 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.
+*/
+
+#include
+#include
+#include
+#include
+#include
+#include
+#include "rdk_logger.h"
+
+typedef struct {
+ unsigned long long user;
+ unsigned long long nice;
+ unsigned long long system;
+ unsigned long long idle;
+ unsigned long long iowait;
+ unsigned long long irq;
+ unsigned long long softirq;
+ unsigned long long steal;
+ unsigned long long guest;
+ unsigned long long guest_nice;
+} CpuTimes;
+
+void getCPUStat(CpuTimes *times) {
+ FILE* file = fopen("/proc/stat", "r");
+ if (file == NULL) {
+ perror("Error opening /proc/stat");
+ exit(EXIT_FAILURE);
+ }
+ char line[256];
+ memset(times, 0, sizeof(*times));
+ if (fgets(line, sizeof(line), file) != NULL) {
+ printf ("%s\n", line);
+ int parsed = sscanf(line, "cpu %llu %llu %llu %llu %llu %llu %llu %llu %llu %llu",
+ ×->user, ×->nice, ×->system, ×->idle,
+ ×->iowait, ×->irq, ×->softirq, ×->steal,
+ ×->guest, ×->guest_nice);
+ if (parsed != 10) {
+ fprintf(stderr, "Failed to parse CPU statistics from /proc/stat (parsed %d fields)\n", parsed);
+ fclose(file);
+ exit(EXIT_FAILURE);
+ }
+ if (parsed != 10) {
+ fprintf(stderr, "Failed to parse CPU statistics from /proc/stat (parsed %d fields)\n", parsed);
+ fclose(file);
+ exit(EXIT_FAILURE);
+ }
+ }
+ fclose(file);
+}
+
+void PrintCPUMetric(CpuTimes prev_times, CpuTimes now_times, const char* pBuf)
+{
+ // Calculate the difference in time for each state
+ unsigned long long prev_idle = prev_times.idle + prev_times.iowait;
+ unsigned long long prev_total = prev_idle + prev_times.user + prev_times.nice + prev_times.system +
+ prev_times.irq + prev_times.softirq + prev_times.steal;
+
+ unsigned long long now_idle = now_times.idle + now_times.iowait;
+ unsigned long long now_total = now_idle + now_times.user + now_times.nice + now_times.system +
+ now_times.irq + now_times.softirq + now_times.steal;
+
+ unsigned long long diff_idle = now_idle - prev_idle;
+ unsigned long long diff_total = now_total - prev_total;
+
+ /* Lets calculate CPU usage percentage. The usage is, 100.0 - (percentage of idle time) */
+ float cpu_usage = 0.0f;
+ if (diff_total > 0) {
+ cpu_usage = (float)(100.0 * (double)(diff_total - diff_idle) / (double)diff_total);
+ }
+
+ FILE* file = fopen("cpu.txt", "a+");
+ if (file == NULL) {
+ perror("Error opening cpu.txt");
+ exit(EXIT_FAILURE);
+ }
+ if (pBuf)
+ {
+ fprintf(file, "%16s : \t", pBuf);
+ }
+
+ fprintf(file, "Current CPU usage: %.2f%%\n", cpu_usage);
+ fclose(file);
+
+ return;
+}
+
+int testLogging()
+{
+ CpuTimes prev_times = {0}, now_times = {0};
+ int i, j;
+
+ char buffer[250] = {0};
+ for(j=0; j<249; j++) buffer[j] = 'A' + (j % 26);
+
+ getCPUStat(&prev_times);
+ rdk_logger_ext_config_t cfg;
+ memset(&cfg, 0, sizeof(cfg));
+ cfg.pModuleName = "LOG.RDK.FOO";
+ cfg.loglevel = RDK_LOG_INFO;
+ cfg.output = RDKLOG_OUTPUT_SYSLOG;
+ cfg.format = RDKLOG_FORMAT_WITH_TS_TID;
+ cfg.pFilePolicy = NULL;
+ rdk_logger_ext_init(&cfg);
+
+ getCPUStat(&now_times);
+ PrintCPUMetric(prev_times, now_times, "Ext Init");
+ usleep(1000);
+
+ // Test 1: Print DEBUG where DEBUG is not enabled.
+ // CPU taken to drop the log message
+ getCPUStat(&prev_times);
+ for (i = 0; i < 15000; i++)
+ {
+ rdk_logger_msg_printf(RDK_LOG_DEBUG, "LOG.RDK.FOO", "%s : %d\n", buffer, i);
+ }
+ getCPUStat(&now_times);
+ PrintCPUMetric(prev_times, now_times, "Syslog - Debug");
+ usleep(10000);
+
+ // Test 2: Print INFO where INFO is enabled.
+ // CPU taken to print the log message
+ getCPUStat(&prev_times);
+ for (i = 0; i < 15000; i++)
+ {
+ rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.FOO", "%s : %d\n", buffer, i);
+ }
+ getCPUStat(&now_times);
+ PrintCPUMetric(prev_times, now_times, "Syslog - Info");
+ usleep(10000);
+
+ getCPUStat(&prev_times);
+ memset(&cfg, 0, sizeof(cfg));
+ cfg.pModuleName = "LOG.RDK.FOO";
+ cfg.loglevel = RDK_LOG_INFO;
+ cfg.output = RDKLOG_OUTPUT_CONSOLE;
+ cfg.format = RDKLOG_FORMAT_WITH_TID;
+ cfg.pFilePolicy = NULL;
+ rdk_logger_ext_init(&cfg);
+ getCPUStat(&now_times);
+ PrintCPUMetric(prev_times, now_times, "Ext Init");
+ usleep(10000);
+
+ // Test 3: Print DEBUG where DEBUG is not enabled.
+ // CPU taken to drop the log message
+ getCPUStat(&prev_times);
+ for (i = 0; i < 15000; i++)
+ {
+ rdk_logger_msg_printf(RDK_LOG_DEBUG, "LOG.RDK.FOO", "%s : %d\n", buffer, i);
+ }
+ getCPUStat(&now_times);
+ PrintCPUMetric(prev_times, now_times, "Console - Debug");
+ usleep(10000);
+
+ // Test 4: Print INFO where INFO is enabled.
+ // CPU taken to print the log message
+ getCPUStat(&prev_times);
+ for (i = 0; i < 15000; i++)
+ {
+ rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.FOO", "%s : %d\n", buffer, i);
+ }
+ getCPUStat(&now_times);
+ PrintCPUMetric(prev_times, now_times, "Console - Info");
+ return 0;
+}
+
+int main ()
+{
+ CpuTimes prev_times = {0}, now_times = {0};
+
+ // Begin
+ getCPUStat(&prev_times);
+ rdk_logger_init(NULL);
+ // End
+ getCPUStat(&now_times);
+
+ /* Print CPU */
+ PrintCPUMetric(prev_times, now_times, "Init");
+
+ for (int i = 0; i < 5; i ++)
+ {
+ testLogging();
+ sleep(3);
+ }
+ return 0;
+}
diff --git a/test/rdk_logger_debug_test.c b/test/rdk_logger_debug_test.c
deleted file mode 100644
index 1aeae71e..00000000
--- a/test/rdk_logger_debug_test.c
+++ /dev/null
@@ -1,61 +0,0 @@
-/*
- * If not stated otherwise in this file or this component's LICENSE 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.
-*/
-
-#include
-#include
-#include
-#include "rdk_logger.h"
-int rdk_logger_debug_test()
-{
- char buffer[55]; // Assume this is filled with 55 bytes of data
- for(int j=0; j<55; j++) buffer[j] = 'A' + (j % 26);
-
- for (int i = 0; i < 5; i++) {
- rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.AA", "Pre %s info %d\n", buffer, i);
- rdk_logger_msg_printf(RDK_LOG_ERROR, "LOG.RDK.AA", "Pre error %d\n", i);
- rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.BB", "Pre info %d\n", i);
- rdk_logger_msg_printf(RDK_LOG_ERROR, "LOG.RDK.BB", "Pre error %d\n", i);
- rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.CC", "Pre info %d\n", i);
- rdk_logger_msg_printf(RDK_LOG_ERROR, "LOG.RDK.CC", "Pre error %d\n", i);
- }
-
- printf ("2nd loop\n");
- rdk_logger_ext_config_t cfg;
- memset(&cfg, 0, sizeof(cfg));
- cfg.pModuleName = "LOG.RDK.BB";
- cfg.loglevel = RDK_LOG_TRACE;
- cfg.output = RDKLOG_OUTPUT_SYSLOG;
- cfg.format = RDKLOG_FORMAT_PLAINTEXT;
- cfg.pFilePolicy = NULL;
- rdk_Error ret = rdk_logger_ext_init(&cfg);
-
- cfg.pModuleName = "LOG.RDK.CC";
- cfg.format = RDKLOG_FORMAT_DETAIL_WITH_TS;
- ret = rdk_logger_ext_init(&cfg);
-
- for (int i = 0; i < 5; i++) {
- rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.AA", "Post %s info %d\n", buffer, i);
- rdk_logger_msg_printf(RDK_LOG_ERROR, "LOG.RDK.AA", "Post error %d\n", i);
- rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.BB", "Post info %d\n", i);
- rdk_logger_msg_printf(RDK_LOG_ERROR, "LOG.RDK.BB", "Post error %d\n", i);
- rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.CC", "Post info %d\n", i);
- rdk_logger_msg_printf(RDK_LOG_ERROR, "LOG.RDK.CC", "Post error %d\n", i);
- }
- return 0;
-}
diff --git a/test/rdk_logger_test_main.c b/test/rdk_logger_test_main.c
deleted file mode 100644
index b0e86495..00000000
--- a/test/rdk_logger_test_main.c
+++ /dev/null
@@ -1,30 +0,0 @@
-/*
- * If not stated otherwise in this file or this component's LICENSE 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.
-*/
-
-#include
-#include "rdk_logger.h"
-
-int rdk_logger_debug_test();
-
-int main()
-{
- rdk_logger_init(NULL);
- rdk_logger_debug_test();
- return 0;
-}
diff --git a/unittests/rdkLoggerErrorTest.cpp b/unittests/rdkLoggerErrorTest.cpp
index 35e05655..41aeb2c5 100644
--- a/unittests/rdkLoggerErrorTest.cpp
+++ b/unittests/rdkLoggerErrorTest.cpp
@@ -129,14 +129,6 @@ TEST_F(RDKLoggerErrorTest, VeryLongMessages) {
// Test very long message
rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.TEST", "Long message: %s", long_message);
// Should not crash, may truncate or handle gracefully
-
- // Test very long format string
- char long_format[5000];
- memset(long_format, '%', sizeof(long_format) - 1);
- long_format[sizeof(long_format) - 1] = '\0';
-
- rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.TEST", long_format, "test");
- // Should not crash
}
// Test very long module names
diff --git a/unittests/rdkLoggerRotationTest.cpp b/unittests/rdkLoggerRotationTest.cpp
index dd135679..6eef3175 100644
--- a/unittests/rdkLoggerRotationTest.cpp
+++ b/unittests/rdkLoggerRotationTest.cpp
@@ -76,7 +76,7 @@ class RDKLoggerRotationTest : public ::testing::Test {
struct dirent* entry;
while ((entry = readdir(dir)) != NULL) {
if (entry->d_name[0] != '.') {
- printf("Found file: %s\n", entry->d_name);
+ printf("Found file: %s\n", entry->d_name);
count++;
}
}
@@ -454,6 +454,169 @@ TEST_F(RDKLoggerRotationTest, ConcurrentAccess) {
});
// Should handle concurrent access gracefully
}
+
+// Test log rotation with RDKLOG_FORMAT_WITH_TID format
+TEST_F(RDKLoggerRotationTest, FormatWithTID) {
+ RUN_IN_FORK({
+ rdk_LogOutput_File testPolicy;
+ strncpy(testPolicy.fileName, "format_tid_test.log", sizeof(testPolicy.fileName)-1);
+ testPolicy.fileName[sizeof(testPolicy.fileName) - 1] = '\0';
+ strncpy(testPolicy.fileLocation, "/tmp/rdk_logger_rotation_test", sizeof(testPolicy.fileLocation)-1);
+ testPolicy.fileLocation[sizeof(testPolicy.fileLocation) - 1] = '\0';
+ testPolicy.fileSizeMax = 512; // 512 bytes to trigger rotation
+ testPolicy.fileCountMax = 3;
+ rdk_logger_ext_config_t config;
+ memset(&config, 0, sizeof(config));
+ config.pModuleName = "LOG.RDK.ROTATION";
+ config.loglevel = RDK_LOG_DEBUG;
+ config.output = RDKLOG_OUTPUT_FILE;
+ config.format = RDKLOG_FORMAT_WITH_TID;
+ config.pFilePolicy = &testPolicy;
+
+ rdk_Error ret = rdk_logger_ext_init(&config);
+ ASSERT_EQ(ret, RDK_SUCCESS) << "Extended initialization with RDKLOG_FORMAT_WITH_TID should succeed";
+
+ system("mkdir -p /tmp/rdk_logger_rotation_test");
+ // Generate log messages to test the format with thread ID
+ char large_message[150];
+ createLargeLogMessage(large_message, sizeof(large_message));
+ for (int i = 0; i < 15; i++) {
+ rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.ROTATION", "TID format test %d: %s", i, large_message);
+ usleep(10000); // 10ms delay
+ }
+
+ // Verify log file was created
+ char logFilePath[512];
+ snprintf(logFilePath, sizeof(logFilePath), "%s/%s",
+ testPolicy.fileLocation, testPolicy.fileName);
+
+ printf("logFilePath = %s\n", logFilePath);
+
+ // Read and verify log content contains thread ID
+ FILE* logFile = fopen(logFilePath, "r");
+ ASSERT_NE(logFile, nullptr) << "Failed to open log file for validation";
+ char line[1024];
+ bool foundThreadId = false;
+ while (fgets(line, sizeof(line), logFile)) {
+ // Thread ID format typically appears as [TID:xxxxx] or similar
+ if (strstr(line, "TID") != NULL || strchr(line, '[') != NULL) {
+ foundThreadId = true;
+ break;
+ }
+ }
+ fclose(logFile);
+ EXPECT_TRUE(foundThreadId) << "Log should contain thread ID information";
+ });
+}
+
+// Test log rotation with RDKLOG_FORMAT_WITH_TS_TID format
+TEST_F(RDKLoggerRotationTest, FormatWithTSTID) {
+ RUN_IN_FORK({
+ rdk_LogOutput_File testPolicy;
+ strncpy(testPolicy.fileName, "format_ts_tid_test.log", sizeof(testPolicy.fileName)-1);
+ testPolicy.fileName[sizeof(testPolicy.fileName) - 1] = '\0';
+ strncpy(testPolicy.fileLocation, "/tmp/rdk_logger_rotation_test", sizeof(testPolicy.fileLocation)-1);
+ testPolicy.fileLocation[sizeof(testPolicy.fileLocation) - 1] = '\0';
+ testPolicy.fileSizeMax = 512; // 512 bytes to trigger rotation
+ testPolicy.fileCountMax = 3;
+ rdk_logger_ext_config_t config;
+ memset(&config, 0, sizeof(config));
+ config.pModuleName = "LOG.RDK.ROTATION";
+ config.loglevel = RDK_LOG_DEBUG;
+ config.output = RDKLOG_OUTPUT_FILE;
+ config.format = RDKLOG_FORMAT_WITH_TS_TID;
+ config.pFilePolicy = &testPolicy;
+
+ rdk_Error ret = rdk_logger_ext_init(&config);
+ ASSERT_EQ(ret, RDK_SUCCESS) << "Extended initialization with RDKLOG_FORMAT_WITH_TS_TID should succeed";
+
+ // Generate log messages to test the format with timestamp and thread ID
+ char large_message[150];
+ createLargeLogMessage(large_message, sizeof(large_message));
+ for (int i = 0; i < 15; i++) {
+ rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.ROTATION", "TS_TID format test %d: %s", i, large_message);
+ usleep(10000); // 10ms delay
+ }
+
+ // Verify log file was created
+ char logFilePath[512];
+ snprintf(logFilePath, sizeof(logFilePath), "%s/%s",
+ testPolicy.fileLocation, testPolicy.fileName);
+
+ // Read and verify log content contains both timestamp and thread ID
+ FILE* logFile = fopen(logFilePath, "r");
+ ASSERT_NE(logFile, nullptr) << "Failed to open log file for validation";
+ char line[1024];
+ bool foundTimestamp = false;
+ bool foundThreadId = false;
+ while (fgets(line, sizeof(line), logFile)) {
+ // Look for timestamp patterns (date/time format)
+ if (strchr(line, ':') != NULL && strchr(line, '-') != NULL) {
+ foundTimestamp = true;
+ }
+ // Look for thread ID
+ if (strstr(line, "TID") != NULL || strchr(line, '[') != NULL) {
+ foundThreadId = true;
+ }
+ if (foundTimestamp && foundThreadId) break;
+ }
+ fclose(logFile);
+ EXPECT_TRUE(foundTimestamp) << "Log should contain timestamp information";
+ EXPECT_TRUE(foundThreadId) << "Log should contain thread ID information";
+ });
+}
+
+// Test log rotation with RDKLOG_FORMAT_DETAIL_WITHOUT_TS format
+TEST_F(RDKLoggerRotationTest, FormatDetailWithoutTS) {
+ RUN_IN_FORK({
+ rdk_LogOutput_File testPolicy;
+ strncpy(testPolicy.fileName, "format_detail_no_ts_test.log", sizeof(testPolicy.fileName)-1);
+ testPolicy.fileName[sizeof(testPolicy.fileName) - 1] = '\0';
+ strncpy(testPolicy.fileLocation, "/tmp/rdk_logger_rotation_test", sizeof(testPolicy.fileLocation)-1);
+ testPolicy.fileLocation[sizeof(testPolicy.fileLocation) - 1] = '\0';
+ testPolicy.fileSizeMax = 512; // 512 bytes to trigger rotation
+ testPolicy.fileCountMax = 3;
+ rdk_logger_ext_config_t config;
+ memset(&config, 0, sizeof(config));
+ config.pModuleName = "LOG.RDK.ROTATION";
+ config.loglevel = RDK_LOG_DEBUG;
+ config.output = RDKLOG_OUTPUT_FILE;
+ config.format = RDKLOG_FORMAT_DETAIL_WITHOUT_TS;
+ config.pFilePolicy = &testPolicy;
+
+ rdk_Error ret = rdk_logger_ext_init(&config);
+ ASSERT_EQ(ret, RDK_SUCCESS) << "Extended initialization with RDKLOG_FORMAT_DETAIL_WITHOUT_TS should succeed";
+
+ // Generate log messages to test the detailed format without timestamp
+ char large_message[150];
+ createLargeLogMessage(large_message, sizeof(large_message));
+ for (int i = 0; i < 15; i++) {
+ rdk_logger_msg_printf(RDK_LOG_INFO, "LOG.RDK.ROTATION", "Detail no TS format test %d: %s", i, large_message);
+ usleep(10000); // 10ms delay
+ }
+
+ // Verify log file was created
+ char logFilePath[512];
+ snprintf(logFilePath, sizeof(logFilePath), "%s/%s",
+ testPolicy.fileLocation, testPolicy.fileName);
+
+ // Read and verify log content contains both timestamp and thread ID
+ FILE* logFile = fopen(logFilePath, "r");
+ ASSERT_NE(logFile, nullptr) << "Failed to open log file for validation";
+
+ char line[1024];
+ bool foundModuleName = false;
+ if (fgets(line, sizeof(line), logFile)) {
+ // Check for full module name (LOG.RDK.ROTATION) which should be in detailed format
+ if (strstr(line, "LOG.RDK.ROTATION") != NULL) {
+ foundModuleName = true;
+ }
+ }
+ fclose(logFile);
+ EXPECT_TRUE(foundModuleName) << "Log should contain module name in detailed format";
+ });
+}
+
#if 0
// Test log rotation with different log levels
TEST_F(RDKLoggerRotationTest, DifferentLogLevels) {