Dump stack trace on emulator test failure

Emulator test failures are sometimes hard to debug, especially when the
test is stuck somewhere and times out. Let's have the emulator dump
stack trace when an assertion fails or a test times out.

The produced stack trace is in this format:
  #0  build/host/kb_8042/kb_8042.exe() [0x412421]
      /home/victoryang/trunk/src/platform/ec/test/kb_8042.c:104
  #1  build/host/kb_8042/kb_8042.exe() [0x4124a9]
      /home/victoryang/trunk/src/platform/ec/test/kb_8042.c:129
  #2  build/host/kb_8042/kb_8042.exe(run_test+0x3a) [0x412e2c]
      /home/victoryang/trunk/src/platform/ec/test/kb_8042.c:262
  #3  build/host/kb_8042/kb_8042.exe(_run_test+0x11) [0x4061de]
      /home/victoryang/trunk/src/platform/ec/core/host/task.c:90
  #4  build/host/kb_8042/kb_8042.exe(_task_start_impl+0x79) [0x406b72]
      /home/victoryang/trunk/src/platform/ec/core/host/task.c:408
  #5  /lib64/libpthread.so.0(+0x70b1) [0x7f6dc2fa10b1]
      ??:0
  #6  /lib64/libc.so.6(clone+0x6d) [0x7f6dc2cd8efd]
      ??:0
The file name and line number in the trace is generated by addr2line.

BUG=chrome-os-partner:19235 chromium:331548
TEST=Put in a infinite loop in a test, and see stack trace when it times
out.
TEST=Add a failing assertion, and see stack trace when it fails.
BRANCH=None

Change-Id: I4494ffd1ebc98081ce40e860a146202084aa2a1e
Signed-off-by: Vic (Chun-Ju) Yang <victoryang@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/181730

6 files changed, 116 insertions, 7 deletions

diff --git a/Makefile.toolchain b/Makefile.toolchain
index 4897469a4c..f29059a605 100644
--- a/Makefile.toolchain
+++ b/Makefile.toolchain
@@ -55,5 +55,5 @@ BUILD_CFLAGS= $(LIBFTDI_CFLAGS) $(CPPFLAGS) -O3 $(CFLAGS_DEBUG) $(CFLAGS_WARN)
 HOST_CFLAGS=$(CPPFLAGS) -O3 $(CFLAGS_DEBUG) $(CFLAGS_WARN)
 LDFLAGS=-nostdlib -X
 BUILD_LDFLAGS=$(LIBFTDI_LDLIBS)
-HOST_TEST_LDFLAGS=-T core/host/host_exe.lds -lrt -pthread \
+HOST_TEST_LDFLAGS=-T core/host/host_exe.lds -lrt -pthread -rdynamic\
 		  $(if $(TEST_COVERAGE),-fprofile-arcs,)
diff --git a/core/host/main.c b/core/host/main.c
index 2e01267626..2d3622c269 100644
--- a/core/host/main.c
+++ b/core/host/main.c
@@ -30,6 +30,8 @@ int main(int argc, char **argv)
 {
 	__prog_name = argv[0];
 
+	task_register_tracedump();
+
 	register_test_end_hook();
 
 	flash_pre_init();
diff --git a/core/host/panic.c b/core/host/panic.c
index 468d024552..260329cc39 100644
--- a/core/host/panic.c
+++ b/core/host/panic.c
@@ -8,6 +8,7 @@
 
 #include "common.h"
 #include "panic.h"
+#include "test_util.h"
 #include "util.h"
 
 void panic_assert_fail(const char *msg, const char *func, const char *fname,
@@ -15,7 +16,7 @@ void panic_assert_fail(const char *msg, const char *func, const char *fname,
 {
 	fprintf(stderr, "ASSERTION FAIL: %s:%d:%s - %s\n",
 		fname, linenum, func, msg);
-	fflush(stderr);
+	task_dump_trace();
 
 	puts("Fail!"); /* Inform test runner */
 	fflush(stdout);
diff --git a/core/host/task.c b/core/host/task.c
index bb4b073997..156aeeed62 100644
--- a/core/host/task.c
+++ b/core/host/task.c
@@ -5,20 +5,43 @@
 
 /* Task scheduling / events module for Chrome EC operating system */
 
+#include <execinfo.h>
+#include <malloc.h>
 #include <pthread.h>
 #include <semaphore.h>
 #include <signal.h>
 #include <stdint.h>
 #include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
 
 #include "atomic.h"
 #include "common.h"
 #include "console.h"
+#include "host_test.h"
 #include "task.h"
 #include "task_id.h"
 #include "test_util.h"
 #include "timer.h"
 
+#define SIGNAL_INTERRUPT SIGUSR1
+
+#define SIGNAL_TRACE_DUMP SIGTERM
+#define MAX_TRACE 30
+/*
+ * When trace dump is requested from signal handler, skip:
+ *   _task_dump_trace_impl
+ *   _task_dump_trace_dispath
+ *   A function in libc
+ */
+#define SIGNAL_TRACE_OFFSET 3
+/*
+ * When trace dump is requested from task_dump_trace(), skip:
+ *   task_dump_trace
+ *   _task_dump_trace_impl
+ */
+#define DIRECT_TRACE_OFFSET 2
+
 struct emu_task_t {
 	pthread_t thread;
 	pthread_cond_t resume;
@@ -37,6 +60,7 @@ static pthread_cond_t scheduler_cond;
 static pthread_mutex_t run_lock;
 static task_id_t running_task_id;
 static int task_started;
+static pthread_t main_thread;
 
 static sem_t interrupt_sem;
 static pthread_mutex_t interrupt_lock;
@@ -105,7 +129,7 @@ void interrupt_enable(void)
 	interrupt_disabled = 0;
 }
 
-void _task_execute_isr(int sig)
+static void _task_execute_isr(int sig)
 {
 	in_interrupt = 1;
 	pending_isr();
@@ -113,10 +137,75 @@ void _task_execute_isr(int sig)
 	in_interrupt = 0;
 }
 
-void task_register_interrupt(void)
+static void __attribute__((noinline)) _task_dump_trace_impl(int offset)
+{
+	void *trace[MAX_TRACE];
+	size_t sz;
+	char **messages;
+	char buf[256];
+	FILE *file;
+	int i, nb;
+
+	sz = backtrace(trace, MAX_TRACE);
+	messages = backtrace_symbols(trace + offset, sz - offset);
+
+	for (i = 0; i < sz - offset; ++i) {
+		fprintf(stderr, "#%-2d %s\n", i, messages[i]);
+		sprintf(buf, "addr2line %p -e %s",
+			trace[i + offset], __get_prog_name());
+		file = popen(buf, "r");
+		if (file) {
+			nb = fread(buf, 1, sizeof(buf) - 1, file);
+			buf[nb] = '\0';
+			fprintf(stderr, "    %s", buf);
+			pclose(file);
+		}
+	}
+	fflush(stderr);
+	free(messages);
+}
+
+void __attribute__((noinline)) task_dump_trace(void)
+{
+	_task_dump_trace_impl(DIRECT_TRACE_OFFSET);
+}
+
+static void __attribute__((noinline)) _task_dump_trace_dispatch(int sig)
+{
+	int need_dispatch = 1;
+
+	if (pthread_self() != main_thread) {
+		need_dispatch = 0;
+	} else if (!task_start_called()) {
+		fprintf(stderr, "Stack trace of main thread:\n");
+		need_dispatch = 0;
+	} else if (in_interrupt_context()) {
+		fprintf(stderr, "Stack trace of ISR:\n");
+	} else {
+		fprintf(stderr, "Stack trace of task %d (%s):\n",
+				running_task_id, task_names[running_task_id]);
+	}
+
+	if (need_dispatch) {
+		pthread_kill(tasks[running_task_id].thread, SIGNAL_TRACE_DUMP);
+	} else {
+		_task_dump_trace_impl(SIGNAL_TRACE_OFFSET);
+		udelay(100 * MSEC); /* Leave time for stderr to flush */
+		exit(1);
+	}
+}
+
+void task_register_tracedump(void)
+{
+	/* Trace dumper MUST be registered from main thread */
+	main_thread = pthread_self();
+	signal(SIGNAL_TRACE_DUMP, _task_dump_trace_dispatch);
+}
+
+static void task_register_interrupt(void)
 {
 	sem_init(&interrupt_sem, 0, 0);
-	signal(SIGUSR1, _task_execute_isr);
+	signal(SIGNAL_INTERRUPT, _task_execute_isr);
 }
 
 void task_trigger_test_interrupt(void (*isr)(void))
@@ -127,7 +216,7 @@ void task_trigger_test_interrupt(void (*isr)(void))
 
 	/* Suspend current task and excute ISR */
 	pending_isr = isr;
-	pthread_kill(tasks[running_task_id].thread, SIGUSR1);
+	pthread_kill(tasks[running_task_id].thread, SIGNAL_INTERRUPT);
 
 	/* Wait for ISR to complete */
 	sem_wait(&interrupt_sem);
diff --git a/include/test_util.h b/include/test_util.h
index 182ad9d233..754230489f 100644
--- a/include/test_util.h
+++ b/include/test_util.h
@@ -27,6 +27,7 @@
 	do { \
 		if (!(n)) { \
 			ccprintf("%d: ASSERTION failed: %s\n", __LINE__, #n); \
+			task_dump_trace(); \
 			return EC_ERROR_UNKNOWN; \
 		} \
 	} while (0)
@@ -38,6 +39,7 @@
 		if (__ABS(n) >= t) { \
 			ccprintf("%d: ASSERT_ABS_LESS failed: abs(%d) is " \
 				 "not less than %d\n", __LINE__, n, t); \
+			task_dump_trace(); \
 			return EC_ERROR_UNKNOWN; \
 		} \
 	} while (0)
@@ -50,6 +52,7 @@
 				ccprintf("%d: ASSERT_ARRAY_EQ failed at " \
 					 "index=%d: %d != %d\n", __LINE__, \
 					 __i, (int)(s)[__i], (int)(d)[__i]); \
+				task_dump_trace(); \
 				return EC_ERROR_UNKNOWN; \
 			} \
 	} while (0)
@@ -127,8 +130,19 @@ void interrupt_generator_udelay(unsigned us);
 
 #ifdef EMU_BUILD
 void wait_for_task_started(void);
+
+/*
+ * Register trace dump handler for emulator. Trace dump is printed to stderr
+ * when SIGUSR2 is received.
+ */
+void task_register_tracedump(void);
+
+/* Dump current stack trace */
+void task_dump_trace(void);
 #else
 static inline void wait_for_task_started(void) { }
+static inline void task_register_tracedump(void) { }
+static inline void task_dump_trace(void) { }
 #endif
 
 uint32_t prng(uint32_t seed);
diff --git a/util/run_host_test b/util/run_host_test
index ba59454527..a12c44053f 100755
--- a/util/run_host_test
+++ b/util/run_host_test
@@ -6,6 +6,7 @@
 
 from cStringIO import StringIO
 import pexpect
+import signal
 import sys
 import time
 
@@ -39,7 +40,9 @@ def RunOnce(test_name, log, timeout_secs):
     child.close()
     raise
   finally:
-    child.kill(15)
+    if child.isalive():
+      child.kill(signal.SIGTERM)
+    child.read()
 
 log = StringIO()
 tee_log = Tee(log)