From: Alexey Chernobaev <achernobaev@dev.rtsoft.ru>
Date: Tue, 28 Aug 2018 19:31:52 +0000 (+0300)
Subject: Improved logging
X-Git-Tag: accepted/tizen/5.0/unified/20181102.031931~31
X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=63e1a9a804b09051b7c8d6bbd9a47cc924833450;p=sdk%2Ftools%2Fprofctl.git

Improved logging
---

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 <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);