From fe76f369dead3ce374cc229ec657d4cd93376f5c Mon Sep 17 00:00:00 2001 From: YoungHun Kim Date: Tue, 7 Mar 2017 16:51:54 +0900 Subject: [PATCH] Add info at muse log file for debugging Change-Id: I78859ea09ea0d1be7c84a78257714cee65d0923a --- include/muse_core_log.h | 1 + packaging/mused.spec | 2 +- src/muse_core_log.c | 89 ++++++++++++++++++++++++------------------------- src/muse_core_module.c | 6 ++++ src/muse_core_signal.c | 15 +++++++-- 5 files changed, 65 insertions(+), 48 deletions(-) diff --git a/include/muse_core_log.h b/include/muse_core_log.h index 11f0074..3c23cbf 100644 --- a/include/muse_core_log.h +++ b/include/muse_core_log.h @@ -46,6 +46,7 @@ typedef struct muse_core_log { void(*flush_msg)(void); void(*log_api_name)(int, gpointer); void(*save_debug_info)(pid_t pid); + void(*log_write)(char *); void(*free)(void); GMutex log_lock; char latest_msgs[MUSE_LOG_MSG_NUM][MUSE_LOG_MSG_LEN]; diff --git a/packaging/mused.spec b/packaging/mused.spec index 85dee75..ada0312 100644 --- a/packaging/mused.spec +++ b/packaging/mused.spec @@ -1,6 +1,6 @@ Name: mused Summary: A Multimedia Daemon in Tizen Native API -Version: 0.1.54 +Version: 0.1.55 Release: 0 Group: System/Libraries License: Apache-2.0 diff --git a/src/muse_core_log.c b/src/muse_core_log.c index 03cb019..81e22a5 100644 --- a/src/muse_core_log.c +++ b/src/muse_core_log.c @@ -39,6 +39,7 @@ static muse_core_log_t *g_muse_core_log = NULL; static gboolean _muse_core_log_pid_is_valid(pid_t pid); +static void _muse_core_log_write_call(char *buf); static void _muse_core_log_latest_msgs(void); static void _muse_core_log_pid_info(pid_t pid); static void _muse_core_log_cmdline(pid_t pid); @@ -59,7 +60,7 @@ static void _muse_core_log_flush_msg(void); static void _muse_core_log_free(void); static void _muse_core_log_init_instance(void(*log)(char *), void(*log_attr)(const char *, ...), void(*fatal)(char *), void(*set_msg)(char *), char *(*get_msg)(void), void(*flush_msg)(void), - void(*log_api_name)(int, gpointer), void(*save_debug_info)(pid_t), void(*free)(void)); + void(*log_api_name)(int, gpointer), void(*save_debug_info)(pid_t), void(*log_write) (char *), void(*free)(void)); static gboolean _muse_core_log_pid_is_valid(pid_t pid) { @@ -77,6 +78,19 @@ static gboolean _muse_core_log_pid_is_valid(pid_t pid) return TRUE; } +static void _muse_core_log_write_call(char *buf) +{ + g_return_if_fail(muse_core_is_log_enabled()); + g_return_if_fail(g_muse_core_log); + g_return_if_fail(muse_core_ipc_fd_is_valid(g_muse_core_log->log_fd)); + g_return_if_fail(buf); + + if (write(g_muse_core_log->log_fd, buf, strlen(buf)) == WRITE_FAIL) + LOGE("There was an error writing client pid to logfile"); + else if (write(g_muse_core_log->log_fd, "\n", 1) == WRITE_FAIL) + LOGE("fail to write new line character"); +} + static void _muse_core_log_latest_msgs(void) { int idx = 0; @@ -88,20 +102,11 @@ static void _muse_core_log_latest_msgs(void) if (muse_core_ipc_fd_is_valid(g_muse_core_log->log_fd)) { LOGE("----------LATEST MUSE COMMAND----------"); - for (idx = g_muse_core_log->currnt_index; idx < MUSE_LOG_MSG_NUM; idx++) { - LOGE("%s", g_muse_core_log->latest_msgs[idx]); - if (write(g_muse_core_log->log_fd, g_muse_core_log->latest_msgs[idx], strlen(g_muse_core_log->latest_msgs[idx])) == WRITE_FAIL) - LOGE("fail to write sequentially the latest message by first step"); - else if (write(g_muse_core_log->log_fd, "\n", 1) == WRITE_FAIL) - LOGE("fail to write new line character"); - } - for (idx = 0; idx < g_muse_core_log->currnt_index; idx++) { - LOGE("%s", g_muse_core_log->latest_msgs[idx]); - if (write(g_muse_core_log->log_fd, g_muse_core_log->latest_msgs[idx], strlen(g_muse_core_log->latest_msgs[idx])) == WRITE_FAIL) - LOGE("fail to write sequentially the latest message by second step"); - else if (write(g_muse_core_log->log_fd, "\n", 1) == WRITE_FAIL) - LOGE("fail to write new line character"); - } + for (idx = g_muse_core_log->currnt_index; idx < MUSE_LOG_MSG_NUM; idx++) + _muse_core_log_write_call(g_muse_core_log->latest_msgs[idx]); + + for (idx = 0; idx < g_muse_core_log->currnt_index; idx++) + _muse_core_log_write_call(g_muse_core_log->latest_msgs[idx]); LOGE("---------------------------------------"); } @@ -111,17 +116,20 @@ static void _muse_core_log_latest_msgs(void) static void _muse_core_log_pid_info(pid_t pid) { char client_buf[MUSE_MAX_MSG_LEN]; + struct tm newtime; + struct timeval tv; + char time_buf[MUSE_LOG_LEN]; g_return_if_fail(muse_core_is_log_enabled()); g_return_if_fail(g_muse_core_log); g_return_if_fail(muse_core_ipc_fd_is_valid(g_muse_core_log->log_fd)); g_return_if_fail(_muse_core_log_pid_is_valid(pid)); - snprintf(client_buf, sizeof(client_buf), "[PID] %d", (int)pid); - if (write(g_muse_core_log->log_fd, client_buf, strlen(client_buf)) == WRITE_FAIL) - LOGE("There was an error writing client pid to logfile"); - else if (write(g_muse_core_log->log_fd, "\n", 1) != WRITE_FAIL) - LOGE("%s", client_buf); + gettimeofday(&tv, NULL); + strftime(time_buf, sizeof(time_buf), "%m-%d %H:%M:%S", localtime_r(&(tv.tv_sec), &newtime)); + snprintf(client_buf, sizeof(client_buf), "[PID] %d %s.%03ld", pid, time_buf, tv.tv_usec / 1000); + + _muse_core_log_write_call(client_buf); } static void _muse_core_log_cmdline(pid_t pid) @@ -140,11 +148,7 @@ static void _muse_core_log_cmdline(pid_t pid) size_t size = fread(client_buf, sizeof(char), MUSE_MAX_MSG_LEN, fp); client_buf[size] = '\0'; - if (write(g_muse_core_log->log_fd, client_buf, strlen(client_buf)) == WRITE_FAIL) - LOGE("There was an error writing client name to logfile"); - else if (write(g_muse_core_log->log_fd, "\n", 1) != WRITE_FAIL) - LOGE("[Process Name] %s", client_buf); - + _muse_core_log_write_call(client_buf); fclose(fp); } } @@ -162,15 +166,13 @@ static void _muse_core_log_process_info(pid_t pid) snprintf(client_buf, sizeof(client_buf), "ps -Lo pcpu,pmem,tid,comm -p %d", (int)pid); fp = popen(client_buf, "r"); if (fp) { - if (write(g_muse_core_log->log_fd, client_buf, strlen(client_buf)) == WRITE_FAIL) - LOGE("muse-server %d writing command to logfile", (int)pid); - else if (write(g_muse_core_log->log_fd, "\n", 1) == WRITE_FAIL) - LOGE("fail to write process command"); + _muse_core_log_write_call(client_buf); while (fgets(client_buf, MUSE_MAX_MSG_LEN, fp)) { if (write(g_muse_core_log->log_fd, client_buf, strlen(client_buf)) == WRITE_FAIL) LOGE("fail to write command info to logfile"); } + if (pclose(fp) == -1) LOGE("fail to pclose"); } @@ -207,8 +209,7 @@ static void _muse_core_log_api_info(void) memset(&info, 0, sizeof(info)); if (dladdr((const void *) ptr, &info) && info.dli_sname) { snprintf(client_buf, sizeof(client_buf), "[The latest called api name] %s\n[The latest message] %s\n", (char *)info.dli_sname, _muse_core_log_get_msg()); - if (write(g_muse_core_log->log_fd, client_buf, strlen(client_buf)) == WRITE_FAIL) - LOGE("There was an error writing client's latest called api to logfile"); + _muse_core_log_write_call(client_buf); } } } @@ -233,12 +234,10 @@ static void _muse_core_log_binary_info(void) if (label) { if (strncmp(label, BUILD_ID, strlen(BUILD_ID)) == 0) { value = strtok_r(NULL, delimiter, &ptr); - if (value) { - if (write(g_muse_core_log->log_fd, value, strlen(value)) != WRITE_FAIL) - LOGE("[%s] %s", BUILD_ID, value); - } else { + if (value) + _muse_core_log_write_call(value); + else LOGE("strtok_r (value) returns null"); - } } } else { LOGE("strtok_r (label) returns null"); @@ -253,9 +252,6 @@ static void _muse_core_log_save_debug_info(pid_t pid) g_return_if_fail(muse_core_is_log_enabled()); g_return_if_fail(g_muse_core_log); - /* latest api */ - _muse_core_log_latest_msgs(); - /* pid */ _muse_core_log_pid_info(pid); @@ -270,6 +266,9 @@ static void _muse_core_log_save_debug_info(pid_t pid) /* binary version */ _muse_core_log_binary_info(); + + /* latest api */ + _muse_core_log_latest_msgs(); } static int _muse_core_log_fd_set_block(int fd) @@ -468,10 +467,8 @@ static void _muse_core_log_flush_msg(void) g_mutex_lock(&g_muse_core_log->log_lock); - if (str_len < MUSE_MSG_MAX_LENGTH) { - if (write(g_muse_core_log->log_fd, g_muse_core_log->cache, str_len) == WRITE_FAIL) - LOGE("There was an error writing to logfile [%d] %s", str_len, g_muse_core_log->cache); - } + if (str_len < MUSE_MSG_MAX_LENGTH) + _muse_core_log_write_call(g_muse_core_log->cache); memset(g_muse_core_log->cache, 0, MUSE_MSG_MAX_LENGTH + 1); @@ -481,7 +478,7 @@ static void _muse_core_log_flush_msg(void) static void _muse_core_log_init_instance(void(*log)(char *), void(*log_attr)(const char *, ...), void(*fatal)(char *), void(*set_msg)(char *), char *(*get_msg)(void), void(*flush_msg)(void), - void(*log_api_name)(int, gpointer), void(*save_debug_info)(pid_t), void(*free)(void)) + void(*log_api_name)(int, gpointer), void(*save_debug_info)(pid_t), void(*log_write) (char *), void(*free)(void)) { g_return_if_fail(log); g_return_if_fail(fatal); @@ -498,6 +495,7 @@ static void _muse_core_log_init_instance(void(*log)(char *), void(*log_attr)(con g_muse_core_log->flush_msg = flush_msg; g_muse_core_log->log_api_name = log_api_name; g_muse_core_log->save_debug_info = save_debug_info; + g_muse_core_log->log_write = log_write; g_muse_core_log->free = free; g_mutex_init(&g_muse_core_log->log_lock); } @@ -517,7 +515,8 @@ void muse_core_log_init(void) if (g_muse_core_log == NULL) _muse_core_log_init_instance(_muse_core_log_monitor, _muse_core_log_attributes, _muse_core_log_fatal, _muse_core_log_set_msg, _muse_core_log_get_msg, _muse_core_log_flush_msg, - _muse_core_log_api_name, _muse_core_log_save_debug_info, _muse_core_log_free); + _muse_core_log_api_name, _muse_core_log_save_debug_info, _muse_core_log_write_call, + _muse_core_log_free); _muse_core_log_set_log_fd(); diff --git a/src/muse_core_module.c b/src/muse_core_module.c index a047b6f..7319348 100644 --- a/src/muse_core_module.c +++ b/src/muse_core_module.c @@ -69,6 +69,7 @@ static GModule *_muse_core_module_load(int api_module) static gboolean _muse_core_module_dispatch_callback(gpointer data) { muse_module_h module = (muse_module_h)data; + char client_buf[MUSE_MAX_MSG_LEN]; LOGE("Restart muse server"); @@ -79,6 +80,11 @@ static gboolean _muse_core_module_dispatch_callback(gpointer data) LOGE("invalid pointer for module"); } + if (muse_core_is_log_enabled()) { + snprintf(client_buf, sizeof(client_buf), "DEADLOCK %s %d", muse_core_config_get_instance()->host[module->api_module], module->last_cmd); + muse_core_log_get_instance()->log_write(client_buf); + } + muse_core_respawn(SIGABRT); return FALSE; diff --git a/src/muse_core_signal.c b/src/muse_core_signal.c index 24fb7d7..fac6bcc 100644 --- a/src/muse_core_signal.c +++ b/src/muse_core_signal.c @@ -41,6 +41,11 @@ static void _muse_core_signal_sigaction(int signo, siginfo_t *si, void *arg); static void _muse_core_signal_handler(int signo) { + char client_buf[MUSE_MAX_MSG_LEN]; + + snprintf(client_buf, sizeof(client_buf), "signo (%d)", signo); + muse_core_log_get_instance()->log_write(client_buf); + LOGD("signo(%d)", signo); switch (signo) { @@ -81,6 +86,7 @@ static void _muse_core_signal_backtrace(void *arg) char **strings = NULL; ucontext_t *uctxt = NULL; char err_msg[MUSE_MAX_MSG_LEN] = {'\0',}; + char client_buf[MUSE_MAX_MSG_LEN]; LOGE("----------BEGIN MUSE DYING MESSAGE----------"); @@ -107,8 +113,13 @@ static void _muse_core_signal_backtrace(void *arg) LOGE("backtrace_symbols error: %s", err_msg); } else { /* skip the first stack frame because it just points here. */ - for (i = 1; i < tracesize; ++i) + for (i = 1; i < tracesize; ++i) { LOGE("[%u] %s", i - 1, strings[i]); + if (muse_core_is_log_enabled()) { + snprintf(client_buf, sizeof(client_buf), "[%u] %s", i - 1, strings[i]); + muse_core_log_get_instance()->log_write(client_buf); + } + } MUSE_FREE(strings); } @@ -129,8 +140,8 @@ static void _muse_core_signal_sigaction(int signo, siginfo_t *si, void *arg) remove(MUSE_SERVER_READY); #endif - _muse_core_signal_backtrace(arg); _muse_core_signal_save_debug_info(si->si_pid); + _muse_core_signal_backtrace(arg); _muse_core_signal_handler(signo); } -- 2.7.4