Improved logging
authorAlexey Chernobaev <achernobaev@dev.rtsoft.ru>
Tue, 28 Aug 2018 19:31:52 +0000 (22:31 +0300)
committerAleksei Vereshchagin <avereschagin@dev.rtsoft.ru>
Mon, 3 Sep 2018 15:21:42 +0000 (18:21 +0300)
profctl.c

index 403a658..874271b 100644 (file)
--- a/profctl.c
+++ b/profctl.c
@@ -4,13 +4,15 @@
 #define TIZEN 1
 #endif
 
+#include <errno.h>
+#include <getopt.h>
+#include <signal.h>
+#include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
-#include <unistd.h>
 #include <string.h>
-#include <getopt.h>
-#include <signal.h>
 #include <pthread.h>
+#include <unistd.h>
 
 #if TIZEN
 #include <termios.h>
@@ -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);