From 63e1a9a804b09051b7c8d6bbd9a47cc924833450 Mon Sep 17 00:00:00 2001 From: Alexey Chernobaev Date: Tue, 28 Aug 2018 22:31:52 +0300 Subject: [PATCH] Improved logging --- profctl.c | 341 +++++++++++++++++++++++++++++++++++++++----------------------- 1 file changed, 216 insertions(+), 125 deletions(-) diff --git a/profctl.c b/profctl.c index 403a658..874271b 100644 --- a/profctl.c +++ b/profctl.c @@ -4,13 +4,15 @@ #define TIZEN 1 #endif +#include +#include +#include +#include #include #include -#include #include -#include -#include #include +#include #if TIZEN #include @@ -67,6 +69,54 @@ static struct option long_options[] = { {0, 0, 0, 0} }; +static void log_current_time() +{ + time_t t = time(NULL); + struct tm tm = *localtime(&t); + fprintf(stderr, "%04d-%02d-%02d %02d:%02d:%02d ", + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec); +} + +static pthread_mutex_t stderr_lock; + +static void log_error(const char *fmt, ...) +{ + pthread_mutex_lock(&stderr_lock); + log_current_time(); + va_list arg; + va_start(arg, fmt); + vfprintf(stderr, fmt, arg); + fprintf(stderr, "\n"); + va_end(arg); + fflush(stderr); + pthread_mutex_unlock(&stderr_lock); +} + +static void log_prefixed_system_error(const char *prefix, const char *msg) +{ + int t = errno; + pthread_mutex_lock(&stderr_lock); + if (prefix != NULL) { + fputs(prefix, stderr); + } + log_current_time(); + errno = t; + perror(msg); + fflush(stderr); + pthread_mutex_unlock(&stderr_lock); +} + +static void log_system_error(const char *msg) +{ + log_prefixed_system_error(NULL, msg); +} + +static void log_system_error_and_exit(const char *msg) +{ + log_prefixed_system_error("[FATAL] ", msg); + exit(1); +} + static void openFileProcess(); static FILE *tf; @@ -77,11 +127,15 @@ static void *output_thread(void *arg) openFileProcess(); + int linesRead = 0; while (getline(&buffer, &lsize, tf) != -1) { fputs(buffer, ofile); + ++linesRead; } free(buffer); - + if (verbose) { + log_error("output thread exits (%d lines read)", linesRead); + } exit(0); } @@ -90,6 +144,9 @@ static void *wait_thread(void *arg) { while (aul_app_get_status_bypid(pid) >= 0) sleep(1); + if (verbose) { + log_error("application finished"); + } exit(0); } #endif /* TIZEN */ @@ -108,6 +165,7 @@ static void finish() } } fflush(ofile); + log_error("=== finished ==="); kill(getpid(), SIGKILL); } @@ -138,85 +196,76 @@ static void split(char *line, char **array, int n) static void *outstat(void *arg) { - char *sline = NULL; - char *pline = NULL; - char *mtline = NULL; - char *mfline = NULL; - size_t slen = 0; - size_t plen = 0; - size_t mtlen = 0; - size_t mflen = 0; FILE *sstat = fopen("/proc/stat","r"); - FILE *pstat; - FILE *pmstat; - FILE *tf = fopen("/sys/devices/system/cpu/present","r"); - int tmp, ncpu; - char *statmname; - char *statname; - long psize = sysconf(_SC_PAGESIZE); - struct statvfs fstat; - - fprintf(sfile, "psize %ld\n", psize); - if (sstat == NULL ) { - perror("open /proc/stat"); - exit(1); + log_system_error_and_exit("open /proc/stat"); } - if (tf == NULL ) { - perror("open /sys/devices/system/cpu/present"); - exit(1); + FILE *cpuf = fopen("/sys/devices/system/cpu/present","r"); + if (cpuf == NULL ) { + log_system_error_and_exit("open /sys/devices/system/cpu/present"); } - - fscanf(tf, "%d-%d\n", &tmp, &ncpu); - fclose(tf); + int tmp, ncpu; + if (fscanf(cpuf, "%d-%d\n", &tmp, &ncpu) < 2) { + log_system_error_and_exit("fscanf(cpuf) failed"); + } + fclose(cpuf); ncpu = ncpu - tmp + 1; - tf = fopen("/proc/meminfo", "r"); - if (tf == NULL ) { - perror("open /proc/meminfo"); - exit(1); + long psize = sysconf(_SC_PAGESIZE); + fprintf(sfile, "psize %ld ncpu %d\n", psize, ncpu); + + FILE *memf = fopen("/proc/meminfo", "r"); + if (memf == NULL ) { + log_system_error_and_exit("open /proc/meminfo"); } + char *statmname; if (asprintf(&statmname, "/proc/%d/statm", pid) == -1) { - perror("asprintf"); - exit(1); + log_system_error_and_exit("asprintf"); } + char *statname; if (asprintf(&statname, "/proc/%d/stat", pid) == -1) { - perror("asprintf"); - exit(1); + log_system_error_and_exit("asprintf"); } // Sometimes we can't successfully open /proc/$pid files due to strange // permission problems, so we retry to open it several times. + FILE *pmstat; + int retry = 0; const int max_retry = 10; - for (; retry < max_retry; ++retry) { pmstat = fopen(statmname, "r"); if (pmstat == NULL) { - perror("open /proc/$pid/statm"); + log_system_error("open /proc/$pid/statm"); usleep(100000); continue; } break; } + if (pmstat == NULL) + { + exit(1); + } + + FILE *pstat; for (; retry < max_retry; ++retry) { pstat = fopen(statname, "r"); if (pstat == NULL) { - perror("open /proc/$pid/stat"); + log_system_error("open /proc/$pid/stat"); usleep(100000); continue; } break; } - if (statmname == NULL || statname == NULL) + if (pstat == NULL) { exit(1); } @@ -224,6 +273,10 @@ static void *outstat(void *arg) free(statmname); free(statname); + if (verbose) { + log_error("stat output started"); + } + while(1) { char *stats[5]; char *pstats[18]; @@ -253,37 +306,49 @@ static void *outstat(void *arg) fseek(sstat, 0, SEEK_SET); fflush(sstat); - slen = getline(&sline, &slen, sstat); - if (slen == -1) - exit(1); + char *sline = NULL; + ssize_t slen = getline(&sline, &slen, sstat); + if (slen == -1) { + log_system_error_and_exit("cannot read sstat"); + } split(sline, stats, 5); fseek(pstat, 0, SEEK_SET); fflush(pstat); - plen = getline(&pline, &plen, pstat); - if (plen == -1) - exit(1); + char *pline = NULL; + ssize_t plen = getline(&pline, &plen, pstat); + if (plen == -1) { + log_system_error_and_exit("cannot read pstat"); + } split(pline, pstats, sizeof(pstats) / sizeof(pstats[0])); fseek(pmstat, 0, SEEK_SET); fflush(pmstat); - fscanf(pmstat, "%ld", &pages); + if (fscanf(pmstat, "%ld", &pages) < 1) { + log_system_error_and_exit("fscanf(pmstat) failed"); + } - fseek(tf, 0, SEEK_SET); - fflush(tf); - mtlen = getline(&mtline, &mtlen, tf); - mflen = getline(&mfline, &mflen, tf); - if (mtlen == -1 || mflen == -1) - exit(1); + fseek(memf, 0, SEEK_SET); + fflush(memf); + char *mtline = NULL; + ssize_t mtlen = getline(&mtline, &mtlen, memf); + if (mtlen == -1) { + log_system_error_and_exit("cannot read memf"); + } + char *mfline = NULL; + ssize_t mflen = getline(&mfline, &mflen, memf); + if (mflen == -1) { + log_system_error_and_exit("cannot read memf"); + } split(mtline, mt, 3); split(mfline, mf, 3); + struct statvfs fstat; if (statvfs(".", &fstat) < 0) { - perror("statfs"); - exit(1); + log_system_error_and_exit("statfs"); } available = (fstat.f_bsize >= 1024) @@ -291,8 +356,8 @@ static void *outstat(void *arg) : fstat.f_bavail / (1024 / fstat.f_bsize); fprintf(sfile, - "%ld.%03d %d" " %s %s %s" " %s %s" " %s %s %ld %ld\n", - t, millisec, ncpu, + "%ld.%03d" " %s %s %s" " %s %s" " %s %s %ld %ld\n", + t, millisec, stats[1], stats[3], stats[4], /* user system idle */ pstats[14 - 1], pstats[15 - 1], /* puser psystem */ mt[1], mf[1], available, pages * psize); @@ -303,11 +368,10 @@ static void *outstat(void *arg) return NULL; } - static void CheckValue(char **value, const char *info) { if (value[0] != NULL) { - fprintf(stderr, "%s is already defined to %s\n", info, *value); + log_error("%s is already defined to %s", info, *value); exit(1); } value[0] = optarg; @@ -318,8 +382,8 @@ static int output_app_info(const aul_app_info *info, void *data) { if (info == NULL || info->appid == NULL) return -1; - fprintf(stderr, "pid %d status %d appid %s\n", - info->pid, info->status, info->appid); + log_error("pid %d status %d appid %s", + info->pid, info->status, info->appid); return 0; } #endif /* TIZEN */ @@ -344,7 +408,7 @@ static int process_option(int argc, char **argv) } else if (pname == NULL) { pname = optarg; } else { - fprintf(stderr, "Extra argument %s\n", optarg); + log_error("Extra argument %s", optarg); exit(1); } break; @@ -371,17 +435,14 @@ static void SimpleThread(void* (*func)(void *)) pthread_t thread; if (pthread_attr_init(&attr)) { - perror("pthread_attr_init"); - exit(1); + log_system_error_and_exit("pthread_attr_init"); } if (pthread_create(&thread, &attr, func, NULL)) { - perror("pthread_create"); - exit(1); + log_system_error_and_exit("pthread_create"); } } - #if TIZEN static int find_pid(const aul_app_info *info, void *data) { @@ -415,7 +476,7 @@ static void waitappid(int n) static int app_launch_handler(int npid, const char *app_id, void *data) { if (verbose) { - fprintf(stderr, "app_launch_handler %d - %s\n", npid, app_id); + log_error("app_launch_handler %d - %s", npid, app_id); } if (pid > 0 || strcmp(app_id, appid)) @@ -428,7 +489,7 @@ static int app_launch_handler(int npid, const char *app_id, void *data) static int app_dead_handler(int npid, void *data) { if (verbose) { - fprintf(stderr, "app_dead_handler %d\n", npid); + log_error("app_dead_handler %d", npid); } if (npid != pid) @@ -442,109 +503,135 @@ static int app_dead_handler(int npid, void *data) static void openFileProcess() { - int pipefd[2]; - int pid; - int id; - if (ename == NULL) { tf = fopen(pname, "r"); if (tf == NULL) { - perror("fopen"); - exit(1); + log_system_error_and_exit("fopen"); } return; } if (access(ename, X_OK)) { - perror("access"); - exit(1); + log_system_error_and_exit("access"); } /* We must start interpreter process */ + int pipefd[2]; if (pipe(pipefd)) { - perror("pipe"); - exit(1); + log_system_error_and_exit("pipe"); + } + + if (verbose) { + log_error("pipefd: [%d, %d]", pipefd[0], pipefd[1]); } - id = open(pname, O_RDONLY); + int id = open(pname, O_RDONLY); if (id < 0) { - perror("open"); - exit(1); + log_system_error_and_exit("open"); + } + + if (verbose) { + log_error("pname id: %d", id); } - pid = fork(); + int pid = fork(); if (pid == -1) { - perror("fork"); - exit(1); + log_system_error_and_exit("fork"); } if (pid == 0) { /* Child */ close(pipefd[0]); + if (verbose) { + log_error("CHILD close(%d)", pipefd[0]); + } dup2(pipefd[1], 1); /* stdout */ + if (verbose) { + log_error("CHILD dup2(%d, 1)", pipefd[1]); + } dup2(id, 0); /* stdin */ + if (verbose) { + log_error("CHILD dup2(%d, 0)", id); + } + if (verbose) { + log_error("CHILD execl(%s)", ename); + } execl(ename, ename, NULL); - perror("execl"); - exit(1); + log_system_error_and_exit("execl"); // execl returns only in case of error } /* Parent */ close(pipefd[1]); + if (verbose) { + log_error("PARENT close(%d)", pipefd[1]); + } + close(id); + if (verbose) { + log_error("PARENT close(%d)", id); + } tf = fdopen(pipefd[0], "r"); if (tf == NULL) { - perror("fopen"); - exit(1); + log_system_error_and_exit("fopen"); + } + if (verbose) { + log_error("PARENT fdopen(%d, \"r\")", pipefd[0]); } } static int openPort(int port) { - int result; - int enable = 1; - struct sockaddr_in saddr = {0}; - struct sockaddr_in caddr; - int csize = sizeof(caddr); int sock = socket(AF_INET, SOCK_STREAM, 0); - if (sock < 0) { - perror("socket"); - exit(1); + log_system_error_and_exit("socket"); } + int enable = 1; if (setsockopt(sock, SOL_SOCKET, SO_REUSEADDR, &enable, sizeof(int)) < 0) { - perror("setsockopt"); - exit(1); + log_system_error_and_exit("setsockopt"); } + struct sockaddr_in saddr = {0}; saddr.sin_family = AF_INET; saddr.sin_addr.s_addr = INADDR_ANY; saddr.sin_port = htons(port); if (bind(sock, (struct sockaddr *)&saddr, sizeof(saddr)) < 0) { - perror("bind"); - exit(1); + log_system_error_and_exit("bind"); } listen(sock, 5); - result = accept(sock, (struct sockaddr *) &caddr, &csize); + if (verbose) { + log_error("waiting for connection to port %d", port); + } + struct sockaddr_in caddr; + int csize = sizeof(caddr); + int result = accept(sock, (struct sockaddr *)&caddr, &csize); if (result < 0) { - perror("accept"); - exit(1); + log_system_error_and_exit("accept"); + } + if (verbose) { + log_error("accepted connection to port %d", port); } return result; } int main(int argc, char **argv) { + if (pthread_mutex_init(&stderr_lock, NULL) != 0) + { + perror("mutex init failed\n"); + return 1; + } + #if TIZEN struct termios term; #endif /* TIZEN */ char *line = NULL; - size_t len = 0; + ssize_t len = 0; cfile = stdin; ofile = stdout; @@ -554,7 +641,7 @@ int main(int argc, char **argv) #if TIZEN if (appid == NULL) { - fprintf(stderr, "Unknown app id\n"); + log_error("Unknown app id"); exit(1); } #endif /* TIZEN */ @@ -563,10 +650,15 @@ int main(int argc, char **argv) oname = "/tmp/profctl.log"; } - freopen(oname, "w", stderr); - setbuf(stderr, NULL); + FILE* redir_stderr = fopen(oname, "w"); + if (redir_stderr == NULL) { + log_system_error_and_exit("freopen"); + } + setlinebuf(redir_stderr); + stderr = redir_stderr; if (verbose) { + log_error("=== started ==="); int i; for (i = 0; i < argc; i++) { fprintf(stderr, "argv[%d] = %s\n", i, argv[i]); @@ -576,14 +668,13 @@ int main(int argc, char **argv) if (pname && isPipeOwner) { unlink(pname); if (mkfifo(pname, 0666)) { - perror("mkfifo"); - exit(1); + log_system_error_and_exit("mkfifo"); } #if TIZEN /* This may be useful for "root on" start */ if (setxattr(pname, "security.SMACK64", "User::App::Shared", strlen("User::App::Shared"),0)) { - perror("setattr"); + log_system_error("setattr"); } #endif /* TIZEN */ } @@ -604,10 +695,8 @@ int main(int argc, char **argv) if (controlPort > 0) { int s = openPort(controlPort); cfile = fdopen(s, "r"); - ofile = fdopen(s, "w"); - if (cfile == NULL || ofile == NULL) { - perror("fdopen"); - exit(1); + if (cfile == NULL) { + log_system_error_and_exit("fdopen(control,r)"); } } @@ -615,8 +704,7 @@ int main(int argc, char **argv) int s = openPort(statPort); sfile = fdopen(s, "w"); if (sfile == NULL) { - perror("fdopen"); - exit(1); + log_system_error_and_exit("fdopen(stat,w)"); } } @@ -634,20 +722,23 @@ int main(int argc, char **argv) /* Read command loop */ while((len = getline(&line, &len, cfile)) != -1) { if (verbose) { - fprintf(stderr, "line :%s#\n", line); + if ((len > 0) && (line[len - 1] == '\n')) { + line[len - 1] = 0; + } + log_error("line: %s", line); } if ((pid != -1) && !strncmp(line, "exit", 4)) { kill(pid, SIGHUP); break; } else if ((pid != -1) && !strncmp(line, "kill", 4)) { if (kill(pid, SIGINT)) - perror("kill"); + log_system_error("kill"); } else if ((pid != -1) && !strncmp(line, "start", 5)) { if (kill(pid, SIGRTMIN+8)) - perror("kill"); + log_system_error("kill"); } else if ((pid != -1) && !strncmp(line, "stop", 4)) { if (kill(pid, SIGRTMIN+7)) - perror("kill"); + log_system_error("kill"); } else if (!strncmp(line, "test", 4) && (pid == -1)) { #if TIZEN waitappid(10); /* try 10 seconds */ @@ -655,7 +746,7 @@ int main(int argc, char **argv) pid = getpid(); #endif /* TIZEN */ if (verbose) { - fprintf(stderr, "pid = %d\n", pid); + log_error("pid = %d", pid); } if (doinfo) { SimpleThread(&outstat); -- 2.7.4