logwrapper: Add ability to log to kernel log (96e11b5b) · Commits · e / os / android_system_core

logwrapper/Android.mk

+1 −1

Original line number	Diff line number	Diff line
		@@ -30,5 +30,5 @@ include $(BUILD_SHARED_LIBRARY)
		include $(CLEAR_VARS)
		LOCAL_SRC_FILES:= logwrapper.c
		LOCAL_MODULE := logwrapper
		LOCAL_STATIC_LIBRARIES := liblog liblogwrap
		LOCAL_STATIC_LIBRARIES := liblog liblogwrap libcutils
		include $(BUILD_EXECUTABLE)

logwrapper/include/logwrap/logwrap.h

+26 −3

Original line number	Diff line number	Diff line
		@@ -43,7 +43,12 @@ __BEGIN_DECLS
		* SIGQUIT while logwrap is running. This may force the end-user to
		* send a signal twice to signal the caller (once for the child, and
		* once for the caller)
		* logwrap: when true, log messages from the child
		* log_target: Specify where to log the output of the child, either LOG_NONE,
		* LOG_ALOG (for the Android system log) or LOG_KLOG (for the kernel
		* log).
		* abbreviated: If true, capture up to the first 100 lines and last 4K of
		* output from the child. The abbreviated output is not dumped to
		* the specified log until the child has exited.
		*
		* Return value:
		* 0 when logwrap successfully run the child process and captured its status
		@@ -52,8 +57,26 @@ __BEGIN_DECLS
		* the return value of the child if it exited properly and status is NULL
		*
		*/
		int android_fork_execvp(int argc, char* argv[], int *status, bool ignore_int_quit,
		bool logwrap);

		/* Values for the log_target parameter android_fork_exec_ext() */
		#define LOG_NONE 0
		#define LOG_ALOG 1
		#define LOG_KLOG 2

		int android_fork_execvp_ext(int argc, char* argv[], int *status, bool ignore_int_quit,
		int log_target, bool abbreviated);

		/* Similar to above, except abbreviated logging is not available, and if logwrap
		* is true, logging is to the Android system log, and if false, there is no
		* logging.
		*/
		static inline int android_fork_execvp(int argc, char* argv[], int *status,
		bool ignore_int_quit, bool logwrap)
		{
		return android_fork_execvp_ext(argc, argv, status, ignore_int_quit,
		(logwrap ? LOG_ALOG : LOG_NONE), false);
		}


		__END_DECLS

logwrapper/logwrap.c

+311 −30

Original line number	Diff line number	Diff line
		@@ -31,8 +31,10 @@
		#include <logwrap/logwrap.h>
		#include "private/android_filesystem_config.h"
		#include "cutils/log.h"
		#include <cutils/klog.h>

		#define ARRAY_SIZE(x) (sizeof(x) / sizeof(*(x)))
		#define MIN(a,b) (((a)<(b))?(a):(b))

		static pthread_mutex_t fd_mutex = PTHREAD_MUTEX_INITIALIZER;

		@@ -48,8 +50,247 @@ do { \
		_exit(-1); \
		} while(0)

		static int parent(const char tag, int parent_read, pid_t pid, int chld_sts,
		bool logwrap) {
		#define MAX_KLOG_TAG 16

		/* This is a simple buffer that holds up to the first beginning_buf->buf_size
		* bytes of output from a command.
		*/
		#define BEGINNING_BUF_SIZE 0x1000
		struct beginning_buf {
		char *buf;
		size_t alloc_len;
		/* buf_size is the usable space, which is one less than the allocated size */
		size_t buf_size;
		size_t used_len;
		};

		/* This is a circular buf that holds up to the last ending_buf->buf_size bytes
		* of output from a command after the first beginning_buf->buf_size bytes
		* (which are held in beginning_buf above).
		*/
		#define ENDING_BUF_SIZE 0x1000
		struct ending_buf {
		char *buf;
		ssize_t alloc_len;
		/* buf_size is the usable space, which is one less than the allocated size */
		ssize_t buf_size;
		ssize_t used_len;
		/* read and write offsets into the circular buffer */
		int read;
		int write;
		};

		/* A structure to hold all the abbreviated buf data */
		struct abbr_buf {
		struct beginning_buf b_buf;
		struct ending_buf e_buf;
		int beginning_buf_full;
		};

		/* Collect all the various bits of info needed for logging in one place. */
		struct log_info {
		int log_target;
		char klog_fmt[MAX_KLOG_TAG * 2];
		char *btag;
		bool abbreviated;
		struct abbr_buf a_buf;
		};

		/* Forware declaration */
		static void add_line_to_abbr_buf(struct abbr_buf a_buf, char linebuf, int linelen);

		/* Return 0 on success, and 1 when full */
		static int add_line_to_linear_buf(struct beginning_buf *b_buf,
		char *line, ssize_t line_len)
		{
		size_t new_len;
		char *new_buf;
		int full = 0;

		if ((line_len + b_buf->used_len) > b_buf->buf_size) {
		full = 1;
		} else {
		/* Add to the end of the buf */
		memcpy(b_buf->buf + b_buf->used_len, line, line_len);
		b_buf->used_len += line_len;
		}

		return full;
		}

		static void add_line_to_circular_buf(struct ending_buf *e_buf,
		char *line, ssize_t line_len)
		{
		ssize_t free_len;
		ssize_t needed_space;
		char *new_buf;
		int cnt;

		if (e_buf->buf == NULL) {
		return;
		}

		if (line_len > e_buf->buf_size) {
		return;
		}

		free_len = e_buf->buf_size - e_buf->used_len;

		if (line_len > free_len) {
		/* remove oldest entries at read, and move read to make
		* room for the new string */
		needed_space = line_len - free_len;
		e_buf->read = (e_buf->read + needed_space) % e_buf->buf_size;
		e_buf->used_len -= needed_space;
		}

		/* Copy the line into the circular buffer, dealing with possible
		* wraparound.
		*/
		cnt = MIN(line_len, e_buf->buf_size - e_buf->write);
		memcpy(e_buf->buf + e_buf->write, line, cnt);
		if (cnt < line_len) {
		memcpy(e_buf->buf, line + cnt, line_len - cnt);
		}
		e_buf->used_len += line_len;
		e_buf->write = (e_buf->write + line_len) % e_buf->buf_size;
		}

		/* Log directly to the specified log */
		static void do_log_line(struct log_info log_info, char line) {
		if (log_info->log_target == LOG_KLOG) {
		klog_write(6, log_info->klog_fmt, line);
		} else if (log_info->log_target == LOG_ALOG) {
		ALOG(LOG_INFO, log_info->btag, "%s", line);
		}
		}

		/* Log to either the abbreviated buf, or directly to the specified log
		* via do_log_line() above.
		*/
		static void log_line(struct log_info log_info, char line, int len) {
		if (log_info->abbreviated) {
		add_line_to_abbr_buf(&log_info->a_buf, line, len);
		} else {
		do_log_line(log_info, line);
		}
		}

		/*
		* The kernel will take a maximum of 1024 bytes in any single write to
		* the kernel logging device file, so find and print each line one at
		* a time. The allocated size for buf should be at least 1 byte larger
		* than buf_size (the usable size of the buffer) to make sure there is
		* room to temporarily stuff a null byte to terminate a line for logging.
		*/
		static void print_buf_lines(struct log_info log_info, char buf, int buf_size)
		{
		char *line_start;
		char c;
		int line_len;
		int i;

		line_start = buf;
		for (i = 0; i < buf_size; i++) {
		if (*(buf + i) == '\n') {
		/* Found a line ending, print the line and compute new line_start */
		/* Save the next char and replace with \0 */
		c = *(buf + i + 1);
		*(buf + i + 1) = '\0';
		do_log_line(log_info, line_start);
		/* Restore the saved char */
		*(buf + i + 1) = c;
		line_start = buf + i + 1;
		} else if (*(buf + i) == '\0') {
		/* The end of the buffer, print the last bit */
		do_log_line(log_info, line_start);
		break;
		}
		}
		/* If the buffer was completely full, and didn't end with a newline, just
		* ignore the partial last line.
		*/
		}

		static void init_abbr_buf(struct abbr_buf *a_buf) {
		char *new_buf;

		memset(a_buf, 0, sizeof(struct abbr_buf));
		new_buf = malloc(BEGINNING_BUF_SIZE);
		if (new_buf) {
		a_buf->b_buf.buf = new_buf;
		a_buf->b_buf.alloc_len = BEGINNING_BUF_SIZE;
		a_buf->b_buf.buf_size = BEGINNING_BUF_SIZE - 1;
		}
		new_buf = malloc(ENDING_BUF_SIZE);
		if (new_buf) {
		a_buf->e_buf.buf = new_buf;
		a_buf->e_buf.alloc_len = ENDING_BUF_SIZE;
		a_buf->e_buf.buf_size = ENDING_BUF_SIZE - 1;
		}
		}

		static void free_abbr_buf(struct abbr_buf *a_buf) {
		free(a_buf->b_buf.buf);
		free(a_buf->e_buf.buf);
		}

		static void add_line_to_abbr_buf(struct abbr_buf a_buf, char linebuf, int linelen) {
		if (!a_buf->beginning_buf_full) {
		a_buf->beginning_buf_full =
		add_line_to_linear_buf(&a_buf->b_buf, linebuf, linelen);
		}
		if (a_buf->beginning_buf_full) {
		add_line_to_circular_buf(&a_buf->e_buf, linebuf, linelen);
		}
		}

		static void print_abbr_buf(struct log_info *log_info) {
		struct abbr_buf *a_buf = &log_info->a_buf;

		/* Add the abbreviated output to the kernel log */
		if (a_buf->b_buf.alloc_len) {
		print_buf_lines(log_info, a_buf->b_buf.buf, a_buf->b_buf.used_len);
		}

		/* Print an ellipsis to indicate that the buffer has wrapped or
		* is full, and some data was not logged.
		*/
		if (a_buf->e_buf.used_len == a_buf->e_buf.buf_size) {
		do_log_line(log_info, "...\n");
		}

		if (a_buf->e_buf.used_len == 0) {
		return;
		}

		/* Simplest way to print the circular buffer is allocate a second buf
		* of the same size, and memcpy it so it's a simple linear buffer,
		* and then cal print_buf_lines on it */
		if (a_buf->e_buf.read < a_buf->e_buf.write) {
		/* no wrap around, just print it */
		print_buf_lines(log_info, a_buf->e_buf.buf + a_buf->e_buf.read,
		a_buf->e_buf.used_len);
		} else {
		/* The circular buffer will always have at least 1 byte unused,
		* so by allocating alloc_len here we will have at least
		* 1 byte of space available as required by print_buf_lines().
		*/
		char * nbuf = malloc(a_buf->e_buf.alloc_len);
		if (!nbuf) {
		return;
		}
		int first_chunk_len = a_buf->e_buf.buf_size - a_buf->e_buf.read;
		memcpy(nbuf, a_buf->e_buf.buf + a_buf->e_buf.read, first_chunk_len);
		/* copy second chunk */
		memcpy(nbuf + first_chunk_len, a_buf->e_buf.buf, a_buf->e_buf.write);
		print_buf_lines(log_info, nbuf, first_chunk_len + a_buf->e_buf.write);
		free(nbuf);
		}
		}

		static int parent(const char *tag, int parent_read, pid_t pid,
		int *chld_sts, int log_target, bool abbreviated) {
		int status = 0;
		char buffer[4096];
		struct pollfd poll_fds[] = {
		@@ -60,13 +301,32 @@ static int parent(const char tag, int parent_read, pid_t pid, int chld_sts,
		};
		int rc = 0;

		struct log_info log_info;

		int a = 0; // start index of unprocessed data
		int b = 0; // end index of unprocessed data
		int sz;
		bool found_child = false;
		char tmpbuf[256];

		log_info.log_target = log_target;
		log_info.abbreviated = abbreviated;
		log_info.btag = basename(tag);
		if (!log_info.btag) {
		log_info.btag = (char*) tag;
		}

		char *btag = basename(tag);
		if (!btag) btag = (char*) tag;
		if (abbreviated && (log_target == LOG_NONE)) {
		abbreviated = 0;
		}
		if (abbreviated) {
		init_abbr_buf(&log_info.a_buf);
		}

		if (log_target == LOG_KLOG) {
		snprintf(log_info.klog_fmt, sizeof(log_info.klog_fmt),
		"<6>%.*s: %%s", MAX_KLOG_TAG, log_info.btag);
		}

		while (!found_child) {
		if (TEMP_FAILURE_RETRY(poll(poll_fds, ARRAY_SIZE(poll_fds), -1)) < 0) {
		@@ -82,11 +342,21 @@ static int parent(const char tag, int parent_read, pid_t pid, int chld_sts,
		// Log one line at a time
		for (b = 0; b < sz; b++) {
		if (buffer[b] == '\r') {
		if (abbreviated) {
		/* The abbreviated logging code uses newline as
		* the line separator. Lucikly, the pty layer
		* helpfully cooks the output of the command
		* being run and inserts a CR before NL. So
		* I just change it to NL here when doing
		* abbreviated logging.
		*/
		buffer[b] = '\n';
		} else {
		buffer[b] = '\0';
		}
		} else if (buffer[b] == '\n') {
		buffer[b] = '\0';
		if (logwrap)
		ALOG(LOG_INFO, btag, "%s", &buffer[a]);
		log_line(&log_info, &buffer[a], b - a);
		a = b + 1;
		}
		}
		@@ -94,8 +364,7 @@ static int parent(const char tag, int parent_read, pid_t pid, int chld_sts,
		if (a == 0 && b == sizeof(buffer) - 1) {
		// buffer is full, flush
		buffer[b] = '\0';
		if (logwrap)
		ALOG(LOG_INFO, btag, "%s", &buffer[a]);
		log_line(&log_info, &buffer[a], b - a);
		b = 0;
		} else if (a != b) {
		// Keep left-overs
		@@ -132,32 +401,44 @@ static int parent(const char tag, int parent_read, pid_t pid, int chld_sts,
		rc = -ECHILD;
		}

		if (logwrap) {
		// Flush remaining data
		if (a != b) {
		buffer[b] = '\0';
		ALOG(LOG_INFO, btag, "%s", &buffer[a]);
		log_line(&log_info, &buffer[a], b - a);
		}

		/* All the output has been processed, time to dump the abbreviated output */
		if (abbreviated) {
		print_abbr_buf(&log_info);
		}

		if (WIFEXITED(status)) {
		if (WEXITSTATUS(status))
		ALOG(LOG_INFO, "logwrapper", "%s terminated by exit(%d)", btag,
		WEXITSTATUS(status));
		if (WEXITSTATUS(status)) {
		snprintf(tmpbuf, sizeof(tmpbuf),
		"%s terminated by exit(%d)\n", log_info.btag, WEXITSTATUS(status));
		do_log_line(&log_info, tmpbuf);
		}
		} else {
		if (WIFSIGNALED(status))
		ALOG(LOG_INFO, "logwrapper", "%s terminated by signal %d", btag,
		WTERMSIG(status));
		else if (WIFSTOPPED(status))
		ALOG(LOG_INFO, "logwrapper", "%s stopped by signal %d", btag,
		WSTOPSIG(status));
		if (WIFSIGNALED(status)) {
		snprintf(tmpbuf, sizeof(tmpbuf),
		"%s terminated by signal %d\n", log_info.btag, WTERMSIG(status));
		do_log_line(&log_info, tmpbuf);
		} else if (WIFSTOPPED(status)) {
		snprintf(tmpbuf, sizeof(tmpbuf),
		"%s stopped by signal %d\n", log_info.btag, WSTOPSIG(status));
		do_log_line(&log_info, tmpbuf);
		}
		}

		err_waitpid:
		err_poll:
		if (abbreviated) {
		free_abbr_buf(&log_info.a_buf);
		}
		return rc;
		}

		static void child(int argc, char* argv[], bool logwrap) {
		static void child(int argc, char* argv[]) {
		// create null terminated argv_child array
		char* argv_child[argc + 1];
		memcpy(argv_child, argv, argc * sizeof(char *));
		@@ -169,8 +450,8 @@ static void child(int argc, char* argv[], bool logwrap) {
		}
		}

		int android_fork_execvp(int argc, char* argv[], int *status, bool ignore_int_quit,
		bool logwrap) {
		int android_fork_execvp_ext(int argc, char* argv[], int *status, bool ignore_int_quit,
		int log_target, bool abbreviated) {
		pid_t pid;
		int parent_ptty;
		int child_ptty;
		@@ -230,7 +511,7 @@ int android_fork_execvp(int argc, char* argv[], int *status, bool ignore_int_qui
		dup2(child_ptty, 2);
		close(child_ptty);

		child(argc, argv, logwrap);
		child(argc, argv);
		} else {
		close(child_ptty);
		if (ignore_int_quit) {
		@@ -242,7 +523,7 @@ int android_fork_execvp(int argc, char* argv[], int *status, bool ignore_int_qui
		sigaction(SIGQUIT, &ignact, &quitact);
		}

		rc = parent(argv[0], parent_ptty, pid, status, logwrap);
		rc = parent(argv[0], parent_ptty, pid, status, log_target, abbreviated);
		}

		if (ignore_int_quit) {

logwrapper/logwrapper.c

+33 −12

Original line number	Diff line number	Diff line
		@@ -17,8 +17,10 @@
		#include <stdio.h>
		#include <stdlib.h>
		#include <sys/wait.h>
		#include <unistd.h>

		#include <logwrap/logwrap.h>
		#include <cutils/klog.h>

		#include "cutils/log.h"

		@@ -30,36 +32,55 @@ void fatal(const char *msg) {

		void usage() {
		fatal(
		"Usage: logwrapper [-d] BINARY [ARGS ...]\n"
		"Usage: logwrapper [-a] [-d] [-k] BINARY [ARGS ...]\n"
		"\n"
		"Forks and executes BINARY ARGS, redirecting stdout and stderr to\n"
		"the Android logging system. Tag is set to BINARY, priority is\n"
		"always LOG_INFO.\n"
		"\n"
		"-a: Causes logwrapper to do abbreviated logging.\n"
		" This logs up to the first 4K and last 4K of the command\n"
		" being run, and logs the output when the command exits\n"
		"-d: Causes logwrapper to SIGSEGV when BINARY terminates\n"
		" fault address is set to the status of wait()\n");
		" fault address is set to the status of wait()\n"
		"-k: Causes logwrapper to log to the kernel log instead of\n"
		" the Android system log\n");
		}

		int main(int argc, char* argv[]) {
		int seg_fault_on_exit = 0;
		int log_target = LOG_ALOG;
		bool abbreviated = false;
		int ch;
		int status = 0xAAAA;
		int rc;

		if (argc < 2) {
		while ((ch = getopt(argc, argv, "adk")) != -1) {
		switch (ch) {
		case 'a':
		abbreviated = true;
		break;
		case 'd':
		seg_fault_on_exit = 1;
		break;
		case 'k':
		log_target = LOG_KLOG;
		klog_set_level(6);
		break;
		case '?':
		default:
		usage();
		}

		if (strncmp(argv[1], "-d", 2) == 0) {
		seg_fault_on_exit = 1;
		argc--;
		argv++;
		}
		argc -= optind;
		argv += optind;

		if (argc < 2) {
		if (argc < 1) {
		usage();
		}

		rc = android_fork_execvp(argc - 1, &argv[1], &status, true, true);
		rc = android_fork_execvp_ext(argc, &argv[0], &status, true,
		log_target, abbreviated);
		if (!rc) {
		if (WIFEXITED(status))
		rc = WEXITSTATUS(status);