Added logging functionality to linuxemu
authorZach Zimmerman <zpzimmerman@gmail.com>
Fri, 25 Aug 2017 18:46:47 +0000 (11:46 -0700)
committerBarret Rhoden <brho@cs.berkeley.edu>
Tue, 29 Aug 2017 18:14:52 +0000 (14:14 -0400)
Added logging constructor/destructor functions
Added syscall errorchecking
Added linuxemu print statement
Added global logfile for linuxemu
Modified linuxemu to use the new print format
The vmcall register print in linuxemu() now uses
the correct syscall ABI (r10 instead of rcx)
Changed dune_sys_read, write, and gettimeofday
to match the new syscall paradigm

Change-Id: I7d9ce9ee9d04088e7455da1378ef03ce90fb9d0e
Signed-off-by: Zach Zimmerman <zpzimmerman@gmail.com>
Signed-off-by: Barret Rhoden <brho@cs.berkeley.edu>
tests/dune/dune.c
user/vmm/include/vmm/linuxemu.h
user/vmm/linuxemu.c

index 785b414..38dc0c5 100644 (file)
@@ -29,6 +29,7 @@
 #include <sys/uio.h>
 #include <err.h>
 #include <vmm/linuxemu.h>
 #include <sys/uio.h>
 #include <err.h>
 #include <vmm/linuxemu.h>
+
 struct vmm_gpcore_init gpci;
 bool linuxemu(struct guest_thread *gth, struct vm_trapframe *tf);
 
 struct vmm_gpcore_init gpci;
 bool linuxemu(struct guest_thread *gth, struct vm_trapframe *tf);
 
@@ -44,7 +45,7 @@ static struct virtual_machine vm = {.halt_exit = true,};
 static unsigned long long memsize = GiB;
 static uintptr_t memstart = MinMemory;
 
 static unsigned long long memsize = GiB;
 static uintptr_t memstart = MinMemory;
 
-static int debug;
+static int dune_debug;
 
 static void hlt(void)
 {
 
 static void hlt(void)
 {
@@ -163,7 +164,7 @@ void *populate_stack(uintptr_t *stack, int argc, char *argv[],
                        return 0;
                for (int i = 0; i < argc; i++) {
                        memcpy(new_argbuf + offset, argv[i], arg_lens[i]);
                        return 0;
                for (int i = 0; i < argc; i++) {
                        memcpy(new_argbuf + offset, argv[i], arg_lens[i]);
-                       if (debug) {
+                       if (dune_debug) {
                                fprintf(stderr, "data: memcpy(%p, %p, %ld)\n",
                                        new_argbuf + offset, argv[i], arg_lens[i]);
                                fprintf(stderr, "arg: set arg %d, @%p, to %p\n", i,
                                fprintf(stderr, "data: memcpy(%p, %p, %ld)\n",
                                        new_argbuf + offset, argv[i], arg_lens[i]);
                                fprintf(stderr, "arg: set arg %d, @%p, to %p\n", i,
@@ -185,7 +186,7 @@ void *populate_stack(uintptr_t *stack, int argc, char *argv[],
        bufsize += (auxc + 1) * sizeof(struct elf_aux);
        bufsize += (envc + 1) * sizeof(char**);
        bufsize += (argc + 1) * sizeof(char**);
        bufsize += (auxc + 1) * sizeof(struct elf_aux);
        bufsize += (envc + 1) * sizeof(char**);
        bufsize += (argc + 1) * sizeof(char**);
-       if (debug)
+       if (dune_debug)
                fprintf(stderr, "Bufsize for pointers and argc is %d\n", bufsize);
 
        /* Add in the size of the env and arg strings. */
                fprintf(stderr, "Bufsize for pointers and argc is %d\n", bufsize);
 
        /* Add in the size of the env and arg strings. */
@@ -194,13 +195,13 @@ void *populate_stack(uintptr_t *stack, int argc, char *argv[],
 
        bufsize += get_lens(argc, argv, arg_lens);
        bufsize += get_lens(envc, envp, env_lens);
 
        bufsize += get_lens(argc, argv, arg_lens);
        bufsize += get_lens(envc, envp, env_lens);
-       if (debug)
+       if (dune_debug)
                fprintf(stderr, "Bufsize for pointers, argc, and strings is %d\n",
                        bufsize);
 
        /* Adjust bufsize so that our buffer will ultimately be 16 byte aligned. */
        bufsize = (bufsize + 15) & ~0xf;
                fprintf(stderr, "Bufsize for pointers, argc, and strings is %d\n",
                        bufsize);
 
        /* Adjust bufsize so that our buffer will ultimately be 16 byte aligned. */
        bufsize = (bufsize + 15) & ~0xf;
-       if (debug)
+       if (dune_debug)
                fprintf(stderr,
                        "Bufsize for pointers, argc, and strings is rounded is %d\n",
                        bufsize);
                fprintf(stderr,
                        "Bufsize for pointers, argc, and strings is rounded is %d\n",
                        bufsize);
@@ -212,7 +213,7 @@ void *populate_stack(uintptr_t *stack, int argc, char *argv[],
        struct elf_aux *new_auxv = (struct elf_aux*)(new_envp + envc + 1);
        char *new_argbuf = (char*)(new_auxv + auxc + 1);
 
        struct elf_aux *new_auxv = (struct elf_aux*)(new_envp + envc + 1);
        char *new_argbuf = (char*)(new_auxv + auxc + 1);
 
-       if (debug) {
+       if (dune_debug) {
                fprintf(stderr, "There are %d args, %d env, and %d aux\n", new_argc,
                        envc, auxc);
                fprintf(stderr, "Locations: argc: %p, argv: %p, envp: %p, auxv: %p\n",
                fprintf(stderr, "There are %d args, %d env, and %d aux\n", new_argc,
                        envc, auxc);
                fprintf(stderr, "Locations: argc: %p, argv: %p, envp: %p, auxv: %p\n",
@@ -229,7 +230,7 @@ void *populate_stack(uintptr_t *stack, int argc, char *argv[],
        offset = remap(argc, argv, new_argv, new_argbuf, arg_lens);
        if (offset == -1)
                return 0;
        offset = remap(argc, argv, new_argv, new_argbuf, arg_lens);
        if (offset == -1)
                return 0;
-       if (debug) {
+       if (dune_debug) {
                fprintf(stderr, "Locations: argbuf: %p, envbuf: %p, ", new_argbuf,
                        new_argbuf + offset);
 
                fprintf(stderr, "Locations: argbuf: %p, envbuf: %p, ", new_argbuf,
                        new_argbuf + offset);
 
@@ -243,7 +244,7 @@ void *populate_stack(uintptr_t *stack, int argc, char *argv[],
 
        memcpy(new_auxv, auxv, auxc * sizeof(struct elf_aux));
        memcpy(new_auxv + auxc, &null_aux, sizeof(struct elf_aux));
 
        memcpy(new_auxv, auxv, auxc * sizeof(struct elf_aux));
        memcpy(new_auxv + auxc, &null_aux, sizeof(struct elf_aux));
-       if (debug) {
+       if (dune_debug) {
                fprintf(stderr, "auxbuf: %p\n", new_auxv);
                hexdump(stdout, new_auxv, auxc * sizeof(struct elf_aux));
        }
                fprintf(stderr, "auxbuf: %p\n", new_auxv);
                hexdump(stdout, new_auxv, auxc * sizeof(struct elf_aux));
        }
@@ -293,7 +294,7 @@ getextra(int *auxc, char *_s)
        char *auxpairs[32];
 
        *auxc = gettokens(s, auxpairs, 32, ",");
        char *auxpairs[32];
 
        *auxc = gettokens(s, auxpairs, 32, ",");
-       if (debug)
+       if (dune_debug)
                fprintf(stderr, "Found %d extra aux pairs\n", *auxc);
        if (*auxc < 1)
                return NULL;
                fprintf(stderr, "Found %d extra aux pairs\n", *auxc);
        if (*auxc < 1)
                return NULL;
@@ -316,7 +317,7 @@ getextra(int *auxc, char *_s)
                v = strtoul(aux[1], 0, 0);
                auxv[i].v[0] = t;
                auxv[i].v[1] = v;
                v = strtoul(aux[1], 0, 0);
                auxv[i].v[0] = t;
                auxv[i].v[1] = v;
-               if (debug)
+               if (dune_debug)
                        fprintf(stderr, "Adding aux pair 0x%x:0x%x\n", auxv[i].v[0],
                                auxv[i].v[1]);
        }
                        fprintf(stderr, "Adding aux pair 0x%x:0x%x\n", auxv[i].v[0],
                                auxv[i].v[1]);
        }
@@ -334,7 +335,7 @@ buildaux(struct elf_aux *base, int basec, struct elf_aux *extra, int extrac)
        if (!ret)
                return NULL;
 
        if (!ret)
                return NULL;
 
-       if (debug)
+       if (dune_debug)
                fprintf(stderr, "buildaux: consolidating %d aux and %d extra\n",
                        basec, extrac);
        /* TOOD: check for dups. */
                fprintf(stderr, "buildaux: consolidating %d aux and %d extra\n",
                        basec, extrac);
        /* TOOD: check for dups. */
@@ -372,12 +373,12 @@ int main(int argc, char **argv)
                switch (c) {
                case 'a':
                        extra = getextra(&extrac, optarg);
                switch (c) {
                case 'a':
                        extra = getextra(&extrac, optarg);
-                       if (debug)
+                       if (dune_debug)
                                fprintf(stderr, "Added %d aux items\n", extrac);
                        break;
                case 'd':
                        fprintf(stderr, "SET DEBUG\n");
                                fprintf(stderr, "Added %d aux items\n", extrac);
                        break;
                case 'd':
                        fprintf(stderr, "SET DEBUG\n");
-                       debug++;
+                       dune_debug++;
                        break;
                case 'v':
                        vmmflags = strtoull(optarg, 0, 0);
                        break;
                case 'v':
                        vmmflags = strtoull(optarg, 0, 0);
@@ -409,6 +410,7 @@ int main(int argc, char **argv)
                usage();
        }
 
                usage();
        }
 
+       init_lemu_logging(dune_debug);
        init_syscall_table();
 
        if ((uintptr_t)(memstart + memsize) >= (uintptr_t)BRK_START) {
        init_syscall_table();
 
        if ((uintptr_t)(memstart + memsize) >= (uintptr_t)BRK_START) {
@@ -420,7 +422,7 @@ int main(int argc, char **argv)
 
        mmap_memory(&vm, memstart, memsize);
 
 
        mmap_memory(&vm, memstart, memsize);
 
-       if (debug)
+       if (dune_debug)
                fprintf(stderr, "mmap guest physical memory at %p for 0x%lx bytes\n",
                        memstart, memsize);
 
                fprintf(stderr, "mmap guest physical memory at %p for 0x%lx bytes\n",
                        memstart, memsize);
 
@@ -449,10 +451,10 @@ int main(int argc, char **argv)
                fprintf(stderr, "Running dune test\n");
                entry = (uintptr_t) dune_test;
        }
                fprintf(stderr, "Running dune test\n");
                entry = (uintptr_t) dune_test;
        }
-       if (debug)
+       if (dune_debug)
                fprintf(stderr, "Test: Populate stack at %p\n", tos);
        tos = populate_stack(tos, ac, av, envc, environ, auxc, auxv);
                fprintf(stderr, "Test: Populate stack at %p\n", tos);
        tos = populate_stack(tos, ac, av, envc, environ, auxc, auxv);
-       if (debug)
+       if (dune_debug)
                fprintf(stderr, "populated stack at %p; argc %d, envc %d, auxc %d\n",
                        tos, ac, envc, auxc);
 
                fprintf(stderr, "populated stack at %p; argc %d, envc %d, auxc %d\n",
                        tos, ac, envc, auxc);
 
@@ -468,7 +470,7 @@ int main(int argc, char **argv)
        /* we can't use the default stack since we set one up
         * ourselves. */
        vm_tf->tf_rsp = (uint64_t)tos;
        /* we can't use the default stack since we set one up
         * ourselves. */
        vm_tf->tf_rsp = (uint64_t)tos;
-       if (debug)
+       if (dune_debug)
                fprintf(stderr, "stack is %p\n", tos);
 
        vthread_create(&vm, 0, (void *)entry, tos);
                fprintf(stderr, "stack is %p\n", tos);
 
        vthread_create(&vm, 0, (void *)entry, tos);
index 79b7062..f314c04 100644 (file)
@@ -12,5 +12,8 @@ struct dune_sys_table_entry {
 struct dune_sys_table_entry dune_syscall_table[dune_max_syscall];
 
 void init_syscall_table(void);
 struct dune_sys_table_entry dune_syscall_table[dune_max_syscall];
 
 void init_syscall_table(void);
+void init_lemu_logging(int logging_level);
+void destroy_lemu_logging(void);
+
 bool dune_sys_write(struct vm_trapframe *tf);
 bool dune_sys_read(struct vm_trapframe *tf);
 bool dune_sys_write(struct vm_trapframe *tf);
 bool dune_sys_read(struct vm_trapframe *tf);
index e6ac53c..af93afb 100644 (file)
 #include <vmm/linuxemu.h>
 #include <dlfcn.h>
 
 #include <vmm/linuxemu.h>
 #include <dlfcn.h>
 
-bool dune_sys_read(struct vm_trapframe *tf)
+
+static int lemu_debug;
+static uth_mutex_t *lemu_logging_lock;
+static FILE *lemu_global_logfile;
+
+void init_lemu_logging(int log_level)
 {
 {
-       int retval = read(tf->tf_rdi, (void *)tf->tf_rsi, (size_t)tf->tf_rdx);
+       const char *logfile_name = "lemu.log";
+       FILE *x = fopen(logfile_name, "w");
 
 
-       if (retval == -1)
-               tf->tf_rax = -errno;
+       lemu_debug = log_level;
+       lemu_logging_lock = uth_mutex_alloc();
+
+       if (x != NULL)
+               lemu_global_logfile = x;
        else
        else
-               tf->tf_rax = retval;
+               lemu_global_logfile = stderr;
+}
 
 
-       return true;
+void destroy_lemu_logging(void)
+{
+       if (lemu_logging_lock != NULL)
+               uth_mutex_free(lemu_logging_lock);
+
+       if (lemu_global_logfile != stderr)
+               fclose(lemu_global_logfile);
 }
 
 }
 
-bool dune_sys_write(struct vm_trapframe *tf)
+
+void lemuprint(const uint32_t tid, const char *syscallname,
+               const bool isError, const char *fmt, ...)
 {
 {
-       int retval = write(tf->tf_rdi, (void *)tf->tf_rsi, (size_t)tf->tf_rdx);
+       va_list valist;
+       const char *prefix = "[TID %d] %s: ";
+       bool double_logging = false;
 
 
-       if (retval == -1)
-               tf->tf_rax = -errno;
-       else
+
+       // Do not use global variable as a check to acquire lock.
+       // make sure it is not changed during our acquire/release.
+       int debug = lemu_debug;
+
+       // If we are not going to log anything anyway, just bail out.
+       if (!(debug > 0 || isError))
+               return;
+
+       va_start(valist, fmt);
+
+       uth_mutex_lock(lemu_logging_lock);
+
+       // Print to stderr if debug level is sufficient
+       if (debug > 1) {
+               fprintf(stderr, prefix, tid, syscallname);
+               vfprintf(stderr, fmt, valist);
+               // Checks if we will double log to stderr
+               if (lemu_global_logfile == stderr)
+                       double_logging = true;
+       }
+
+       // Log to the global logfile, if we defaulted the global logging to
+       // stderr then we don't want to log 2 times to stderr.
+       if (lemu_global_logfile != NULL && !double_logging) {
+               fprintf(lemu_global_logfile, prefix, tid, syscallname);
+               vfprintf(lemu_global_logfile, fmt, valist);
+       }
+
+       uth_mutex_unlock(lemu_logging_lock);
+
+       va_end(valist);
+}
+
+
+bool dune_sys_read(struct vm_trapframe *tf)
+{
+       ssize_t retval = read(tf->tf_rdi, (void*) tf->tf_rsi, (size_t) tf->tf_rdx);
+       int err = errno;
+
+       if (retval == -1) {
+               lemuprint(tf->tf_guest_pcoreid, syscalls[tf->tf_rax], true,
+                         "ERROR %zd\n", err);
+               tf->tf_rax = -err;
+       } else {
+               lemuprint(tf->tf_guest_pcoreid, syscalls[tf->tf_rax], false,
+                         "SUCCESS %zd\n", retval);
                tf->tf_rax = retval;
                tf->tf_rax = retval;
+       }
+       return true;
+}
+
 
 
+bool dune_sys_write(struct vm_trapframe *tf)
+{
+       ssize_t retval = write((int) tf->tf_rdi, (const void *) tf->tf_rsi,
+                              (size_t) tf->tf_rdx);
+       int err = errno;
+
+       if (retval == -1) {
+               lemuprint(tf->tf_guest_pcoreid, syscalls[tf->tf_rax], true,
+                         "ERROR %zd\n", err);
+               tf->tf_rax = -err;
+       } else {
+               lemuprint(tf->tf_guest_pcoreid, syscalls[tf->tf_rax], false,
+                         "SUCCESS %zd\n", retval);
+               tf->tf_rax = retval;
+       }
        return true;
 }
 
        return true;
 }
 
@@ -49,13 +132,19 @@ bool dune_sys_gettid(struct vm_trapframe *tf)
 
 bool dune_sys_gettimeofday(struct vm_trapframe *tf)
 {
 
 bool dune_sys_gettimeofday(struct vm_trapframe *tf)
 {
-       int retval = gettimeofday((struct timeval*)tf->tf_rdi,
-                                 (struct timezone*)tf->tf_rsi);
-       if (retval == -1)
-               tf->tf_rax = -errno;
-       else
+       int retval = gettimeofday((struct timeval*) tf->tf_rdi,
+                                 (struct timezone*) tf->tf_rsi);
+       int err = errno;
+
+       if (retval == -1) {
+               lemuprint(tf->tf_guest_pcoreid, syscalls[tf->tf_rax], true,
+                         "ERROR %d\n", err);
+               tf->tf_rax = -err;
+       } else {
+               lemuprint(tf->tf_guest_pcoreid, syscalls[tf->tf_rax], false,
+                         "SUCCESS %d\n", retval);
                tf->tf_rax = retval;
                tf->tf_rax = retval;
-
+       }
        return true;
 }
 
        return true;
 }
 
@@ -96,13 +185,6 @@ linuxemu(struct guest_thread *gth, struct vm_trapframe *tf)
 {
        bool ret = false;
 
 {
        bool ret = false;
 
-       fprintf(stderr, "vmcall(%s(%d), %p, %p, %p, %p, %p, %p);\n",
-               tf->tf_rax < 311 ? syscalls[tf->tf_rax] : "",
-               tf->tf_rax, tf->tf_rdi, tf->tf_rsi, tf->tf_rdx,
-               tf->tf_rcx, tf->tf_r8, tf->tf_r9);
-
-       tf->tf_rip += 3;
-
        if (tf->tf_rax >= dune_max_syscall) {
                fprintf(stderr, "System call %d is out of range\n", tf->tf_rax);
                return false;
        if (tf->tf_rax >= dune_max_syscall) {
                fprintf(stderr, "System call %d is out of range\n", tf->tf_rax);
                return false;
@@ -110,9 +192,17 @@ linuxemu(struct guest_thread *gth, struct vm_trapframe *tf)
 
 
        if (dune_syscall_table[tf->tf_rax].call == NULL) {
 
 
        if (dune_syscall_table[tf->tf_rax].call == NULL) {
-               fprintf(stderr, "System call %d is not implemented\n", tf->tf_rax);
+               fprintf(stderr, "System call #%d (%s) is not implemented\n",
+                       tf->tf_rax, dune_syscall_table[tf->tf_rax].name);
                return false;
        }
 
                return false;
        }
 
+       lemuprint(tf->tf_guest_pcoreid, dune_syscall_table[tf->tf_rax].name,
+                 false, "vmcall(%d, %p, %p, %p, %p, %p, %p);\n", tf->tf_rax,
+                 tf->tf_rdi, tf->tf_rsi, tf->tf_rdx, tf->tf_r10, tf->tf_r8,
+                 tf->tf_r9);
+
+       tf->tf_rip += 3;
+
        return (dune_syscall_table[tf->tf_rax].call)(tf);
 }
        return (dune_syscall_table[tf->tf_rax].call)(tf);
 }