better logging

diff --git a/logging.c b/logging.c
index 10beacc..642deaa 100644 (file)
--- a/logging.c
+++ b/logging.c
@@ -1,11 +1,19 @@
+#define _GNU_SOURCE
+
 #include <errno.h>
 #include <pthread.h>
 #include <stdarg.h>
 #include <stdlib.h>
 #include <string.h>
+#include <unistd.h>
+#include <sys/syscall.h>
+#include <sys/types.h>
 
 #include "logging.h"
 
+extern int log_pid = 0;
+extern int log_tid = 0;
+
 static FILE *log_file = NULL;
 
 static pthread_mutex_t log_lock;
@@ -89,10 +97,26 @@ static void log_current_time()
                tm.tm_year + 1900 - 2000, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, millisec);
 }
 
+static void log_current_data()
+{
+       log_current_time();
+       if (log_pid) {
+               fprintf(log_file, "P=%ld ", (long)getpid());
+       }
+       if (log_tid) {
+#ifdef SYS_gettid
+               pid_t tid = syscall(SYS_gettid);
+#else
+               #error "SYS_gettid unavailable on this system"
+#endif
+               fprintf(log_file, "T=%ld ", (long)tid);
+       }
+}
+
 void log_message(const char *fmt, ...)
 {
        pthread_mutex_lock(&log_lock);
-       log_current_time();
+       log_current_data();
        va_list arg;
        va_start(arg, fmt);
        vfprintf(log_file, fmt, arg);
@@ -106,7 +130,7 @@ void log_error(const char *fmt, ...)
 {
        pthread_mutex_lock(&log_lock);
        fputs("[ERROR] ", log_file);
-       log_current_time();
+       log_current_data();
        va_list arg;
        va_start(arg, fmt);
        vfprintf(log_file, fmt, arg);
@@ -128,7 +152,7 @@ static void log_prefixed_system_error(FILE *file, int error_code, const char *pr
        if (prefix != NULL) {
                fputs(prefix, file);
        }
-       log_current_time();
+       log_current_data();
        vfprintf(file, fmt, arg);
        fprintf(file, ": %s\n", strerror(error_code));
        fflush(file);

diff --git a/logging.h b/logging.h
index 80ce126..9d777b6 100644 (file)
--- a/logging.h
+++ b/logging.h
@@ -3,6 +3,9 @@
 #include <stdio.h>
 #include <sys/time.h>
 
+extern int log_pid;
+extern int log_tid;
+
 int log_init();
 void log_uninit();
 void log_set_file(FILE *file);

diff --git a/profctl.c b/profctl.c
index 5cc9020..aeb24f2 100644 (file)
--- a/profctl.c
+++ b/profctl.c
@@ -92,7 +92,14 @@ static void *data_output_thread(void *arg)
                size_t lsize = 0;
                while (!global_stop) {
                        if (getline(&buffer, &lsize, pipef) == -1) {
-                               log_system_error("cannot read data from pipe");
+                               if (feof(pipef)) {
+                                       if (verbose) {
+                                               log_message("pipe eof");
+                                       }
+                               }
+                               else {
+                                       log_system_error("cannot read data from pipe");
+                               }
                                break;
                        }
                        ++linesRead;
@@ -145,20 +152,8 @@ static void close_stdio()
        fclose(stderr);
 }
 
-static void finish()
+static void close_files_and_sockets()
 {
-       log_message("exit handler called");
-#if TIZEN
-       if (controlPort < 0) {
-               tcsetattr(0, TCSANOW, &sterm);
-       }
-#endif /* TIZEN */
-       if (pipef != NULL) {
-               fclose(pipef);
-               if (isPipeOwner) {
-                       unlink(pname);
-               }
-       }
        if (ctrl_file_in != NULL && ctrl_file_in != stdin) {
                fclose(ctrl_file_in);
        }
@@ -180,6 +175,23 @@ static void finish()
        if (stat_socket >= 0) {
                close(stat_socket);
        }
+}
+
+static void finish()
+{
+       log_message("exit handler called");
+#if TIZEN
+       if (controlPort < 0) {
+               tcsetattr(0, TCSANOW, &sterm);
+       }
+#endif /* TIZEN */
+       if (pipef != NULL) {
+               fclose(pipef);
+               if (isPipeOwner) {
+                       unlink(pname);
+               }
+       }
+       close_files_and_sockets();
        log_message("=== finished ===");
        log_uninit();
        kill(getpid(), SIGKILL);
@@ -289,6 +301,8 @@ static int openFileProcess()
                return 0;
        }
 
+       // --exec option used
+
        if (access(ename, X_OK)) {
                log_system_error("access(%s)", ename);
                return -1;
@@ -322,44 +336,53 @@ static int openFileProcess()
        }
 
        if (pid == 0) { /* Child */
-               close(pipefd[0]);
-               if (verbose) {
-                       log_message("CHILD close(%d)", pipefd[0]);
+               if (close(pipefd[0]) != 0) {
+                        // not critical
+                       log_system_error("CHILD close(%d)", pipefd[0]);
+               }
+               if (dup2(pipefd[1], 1) == -1) { /* stdout */
+                       log_system_error("CHILD dup2(%d, 1)", pipefd[1]);
+                       return -1;
+               }
+               if (dup2(id, 0) == -1) { /* stdin */
+                       log_system_error("CHILD dup2(%d, 0)", id);
+                       return -1;
                }
-               dup2(pipefd[1], 1);     /* stdout */
                if (verbose) {
-                       log_message("CHILD dup2(%d, 1)", pipefd[1]);
+                       log_message("CHILD close(%d); dup2(%d, 1); dup2(%d, 0)", pipefd[0], pipefd[1], id);
                }
-               dup2(id, 0);            /* stdin */
+               close_files_and_sockets();
                if (verbose) {
-                       log_message("CHILD dup2(%d, 0)", id);
+                       log_message("CHILD closed files and sockets");
                }
                if (verbose) {
-                       log_message("CHILD execl(%s)", ename);
+                       log_message("CHILD calling execl(%s)", ename);
                }
+               log_uninit();
                execl(ename, ename, NULL);
                log_system_error("CHILD execl(%s)", ename); // execl returns only in case of error
                return -1;
        }
 
        /* Parent */
-       close(pipefd[1]);
-       if (verbose) {
-               log_message("PARENT close(%d)", pipefd[1]);
+       if (close(pipefd[1]) != 0) {
+               // not critical
+               log_system_error("PARENT close(%d)", pipefd[1]);
        }
 
-       close(id);
-       if (verbose) {
-               log_message("PARENT close(%d)", id);
+       if (close(id) != 0) {
+               // not critical
+               log_system_error("PARENT close(%d)", id);
        }
 
        pipef = fdopen(pipefd[0], "r");
        if (pipef == NULL) {
-               log_system_error("PARENT fdopen(%d, \"r\")", pipefd[0]);
+               log_system_error("PARENT fdopen(%d, r)", pipefd[0]);
                return -1;
        }
+
        if (verbose) {
-               log_message("PARENT fdopen(%d, \"r\")", pipefd[0]);
+               log_message("PARENT close(%d); close(%d); fdopen(%d, r)", pipefd[1], id, pipefd[0]);
        }
 
        return 0;
@@ -466,7 +489,14 @@ static void *command_loop_thread(void *arg)
        char *line = malloc(len = 16);
        while (!global_stop) {
                if ((len = getline(&line, &len, ctrl_file_in)) == -1) {
-                       log_system_error("cannot read command");
+                       if (feof(ctrl_file_in)) {
+                               if (verbose) {
+                                       log_message("command stream eof");
+                               }
+                       }
+                       else {
+                               log_system_error("cannot read command");
+                       }
                        break;
                }
                if (global_stop) {
@@ -568,6 +598,9 @@ int main(int argc, char **argv)
                return 1;
        }
 
+       log_pid = 1;
+       log_tid = 1;
+
        log_set_file(stderr);
 
        while (!process_option(argc, argv));
@@ -636,11 +669,11 @@ int main(int argc, char **argv)
                }
                ctrl_file_in = fdopen(control_socket, "r");
                if (ctrl_file_in == NULL) {
-                       log_system_error_and_exit("fdopen(control,r)");
+                       log_system_error_and_exit("fdopen(control, r)");
                }
                ctrl_file_out = fdopen(control_socket, "w");
                if (ctrl_file_out == NULL) {
-                       log_system_error_and_exit("fdopen(control,w)");
+                       log_system_error_and_exit("fdopen(control, w)");
                }
                if (fprintf(ctrl_file_out, "ready\n") < 0 || fflush(ctrl_file_out) != 0) {
                        log_system_error_and_exit("cannot write 'ready' prompt to control stream");