From 6cfdbf88f12b6b9c1bfd234a71534c41a7ef0310 Mon Sep 17 00:00:00 2001
From: Rom Walton <romw@romwnet.org>
Date: Wed, 22 Jan 2014 14:34:20 -0500
Subject: [PATCH] VBOX: Introducing the replay and trace logs for vboxwrapper.

The replay log stores the commands that were executed in a near shell script state.  Ideally we should be able to use this to pass bugs back upstream to VirtualBox.

The trace log shows the date, time, thread id, command, return value, and output of the above commands.
---
 samples/vboxwrapper/vbox.cpp | 78 ++++++++++++++++++++++++++----------
 samples/vboxwrapper/vbox.h   | 14 ++++++-
 2 files changed, 69 insertions(+), 23 deletions(-)

diff --git a/samples/vboxwrapper/vbox.cpp b/samples/vboxwrapper/vbox.cpp
index 984cffc748..85a41d412c 100644
--- a/samples/vboxwrapper/vbox.cpp
+++ b/samples/vboxwrapper/vbox.cpp
@@ -276,7 +276,7 @@ void VBOX_VM::poll(bool log_state) {
     command  = "showvminfo \"" + vm_name + "\" ";
     command += "--machinereadable ";
 
-    if (vbm_popen(command, output, "VM state", false, false) == 0) {
+    if (vbm_popen(command, output, "VM state", false, false, 45, false) == 0) {
         vmstate_start = output.find("VMState=\"");
         if (vmstate_start != string::npos) {
             vmstate_start += 9;
@@ -2291,6 +2291,7 @@ int VBOX_VM::launch_vboxsvc() {
                     );
                 }
 
+                vbm_trace(command, std::string(""), retval);
             }
         }
     }
@@ -2303,9 +2304,11 @@ int VBOX_VM::launch_vboxsvc() {
 int VBOX_VM::launch_vboxvm() {
     char buf[256];
     char error_msg[256];
-    int retval = ERR_EXEC;
+    char cmdline[1024];
     char* argv[5];
     int argc;
+    std::string output;
+    int retval = ERR_EXEC;
 
     // Construct the command line parameters
     //
@@ -2324,8 +2327,15 @@ int VBOX_VM::launch_vboxvm() {
     argv[4] = NULL;
     argc = 4;
 
+    strcpy(cmdline, "");
+    for (int i=0; i<argc; i++) {
+        strcat(cmdline, argv[i]);
+        if (i<argc-1) {
+            strcat(cmdline, " ");
+        }
+    }
+
 #ifdef _WIN32
-    char cmdline[1024];
     STARTUPINFO si;
     PROCESS_INFORMATION pi;
     SECURITY_ATTRIBUTES sa;
@@ -2335,7 +2345,6 @@ int VBOX_VM::launch_vboxvm() {
     DWORD dwCount = 0;
     unsigned long ulExitCode = 0;
     unsigned long ulExitTimeout = 0;
-    std::string output;
 
     memset(&si, 0, sizeof(si));
     memset(&pi, 0, sizeof(pi));
@@ -2367,14 +2376,6 @@ int VBOX_VM::launch_vboxvm() {
     si.hStdError = hWritePipe;
     si.hStdInput = NULL;
 
-    strcpy(cmdline, "");
-    for (int i=0; i<argc; i++) {
-        strcat(cmdline, argv[i]);
-        if (i<argc-1) {
-            strcat(cmdline, " ");
-        }
-    }
-
     // Execute command
     if (!CreateProcess(
         NULL, 
@@ -2456,12 +2457,13 @@ CLEANUP:
 #else
     int pid = fork();
     if (-1 == pid) {
+        output = strerror(errno);
         fprintf(
             stderr,
             "%s Status Report: Launching virtualbox.exe/vboxheadless.exe failed!.\n"
             "           Error: %s",
             vboxwrapper_msg_prefix(buf, sizeof(buf)),
-            strerror(errno)
+            output.c_str()
         );
         retval = ERR_FORK;
     } else if (0 == pid) {
@@ -2474,6 +2476,8 @@ CLEANUP:
     }
 #endif
 
+    vbm_trace(std::string(cmdline), output, retval);
+
     return retval;
 }
 
@@ -2493,15 +2497,18 @@ void VBOX_VM::sanitize_output(std::string& output) {
 
 // If there are errors we can recover from, process them here.
 //
-int VBOX_VM::vbm_popen(string& arguments, string& output, const char* item, bool log_error, bool retry_failures, unsigned int timeout) {
+int VBOX_VM::vbm_popen(string& command, string& output, const char* item, bool log_error, bool retry_failures, unsigned int timeout, bool log_trace) {
     int retval = 0;
     int retry_count = 0;
     double sleep_interval = 1.0;
     char buf[256];
     string retry_notes;
 
+    // Initialize command line
+    command = "VBoxManage -q " + command;
+
     do {
-        retval = vbm_popen_raw(arguments, output, timeout);
+        retval = vbm_popen_raw(command, output, timeout);
         if (retval) {
 
             // VirtualBox designed the concept of sessions to prevent multiple applications using
@@ -2559,23 +2566,26 @@ int VBOX_VM::vbm_popen(string& arguments, string& output, const char* item, bool
 
         fprintf(
             stderr,
-            "%s Error in %s for VM: %d\nArguments:\n%s\nOutput:\n%s\n",
+            "%s Error in %s for VM: %d\nCommand:\n%s\nOutput:\n%s\n",
             vboxwrapper_msg_prefix(buf, sizeof(buf)),
             item,
             retval,
-            arguments.c_str(),
+            command.c_str(),
             output.c_str()
         );
     }
 
+    if (log_trace) {
+        vbm_trace(command, output, retval);
+    }
+
     return retval;
 }
 
 // Execute the vbox manage application and copy the output to the buffer.
 //
-int VBOX_VM::vbm_popen_raw(string& arguments, string& output, unsigned int timeout) {
+int VBOX_VM::vbm_popen_raw(string& command, string& output, unsigned int timeout) {
     char buf[256];
-    string command;
     size_t errcode_start;
     size_t errcode_end;
     string errcode;
@@ -2584,9 +2594,6 @@ int VBOX_VM::vbm_popen_raw(string& arguments, string& output, unsigned int timeo
     // Launch vboxsvc in case it was shutdown for being idle
     launch_vboxsvc();
 
-    // Initialize command line
-    command = "VBoxManage -q " + arguments;
-
     // Reset output buffer
     output.clear();
 
@@ -2755,3 +2762,30 @@ CLEANUP:
 
     return retval;
 }
+
+void VBOX_VM::vbm_replay(std::string& command) {
+    FILE* f = fopen(REPLAYLOG_FILENAME, "a");
+    if (f) {
+        fprintf(f, "%s\n", command.c_str());
+        fclose(f);
+    }
+}
+
+void VBOX_VM::vbm_trace(std::string& command, std::string& output, int retval) {
+    vbm_replay(command);
+
+    char buf[256];
+    FILE* f = fopen(TRACELOG_FILENAME, "a");
+    if (f) {
+        fprintf(
+            f,
+            "%s\nCommand: %s\nExit Code: %d\nOutput:\n%s\n",
+            vboxwrapper_msg_prefix(buf, sizeof(buf)),
+            command.c_str(),
+            retval,
+            output.c_str()
+        );
+        fclose(f);
+    }
+}
+
diff --git a/samples/vboxwrapper/vbox.h b/samples/vboxwrapper/vbox.h
index 65d607af9d..621bb2a563 100644
--- a/samples/vboxwrapper/vbox.h
+++ b/samples/vboxwrapper/vbox.h
@@ -34,6 +34,11 @@
 //
 #define VBOXWRAPPER_ERR_RECOVERABLE     -1000
 
+// Vboxwrapper diagnostics
+//
+#define REPLAYLOG_FILENAME "vbox_replay.txt"
+#define TRACELOG_FILENAME "vbox_trace.txt"
+
 
 // raw floppy drive device
 class FloppyIO;
@@ -186,14 +191,21 @@ struct VBOX_VM {
 
     int launch_vboxsvc();
     int launch_vboxvm();
+
     void sanitize_output(std::string& output);
 
     int vbm_popen(
-        std::string& command, std::string& output, const char* item, bool log_error = true, bool retry_failures = true, unsigned int timeout = 45
+        std::string& command, std::string& output, const char* item, bool log_error = true, bool retry_failures = true, unsigned int timeout = 45, bool log_trace = true
     );
     int vbm_popen_raw(
         std::string& command, std::string& output, unsigned int timeout
     );
+    void vbm_replay(
+        std::string& command
+    );
+    void vbm_trace(
+        std::string& command, std::string& ouput, int retval
+    );
 };
 
 #endif