- VBOX: If VirtualBox reports an error snag both the hypervisor system

log as well as the VM execution log.  Maybe the hypervisor log
        will tell us what is up with the virtual floppy device.
    - VBOX: Don't retry commands that are expected to fail in normal use
        cases.  It slows down getting the VM up and running.
    - VBOX: After starting the VM, use a timed loop waiting for the initial
        VM state change instead of just waiting for 5 seconds.  Older
        machines can take longer than 5 seconds to switch from poweroff
        to starting.  If we hit the main poll loop in that state the wrapper
        thinks we have crashed.
    - VBOX: Strip carriage returns from all the vboxmanage output on
        Windows.
        
    samples/vboxwrapper/
        vbox.cpp, .h
        vboxwrapper.cpp

svn path=/trunk/boinc/; revision=24967

checkin_notes

@@ -26,3 +26,21 @@ David  2 Jan 2012
             index.php
         user/
             sandbox.php
+
+Rom    2 Jan 2012
+    - VBOX: If VirtualBox reports an error snag both the hypervisor system
+        log as well as the VM execution log.  Maybe the hypervisor log
+        will tell us what is up with the virtual floppy device.
+    - VBOX: Don't retry commands that are expected to fail in normal use
+        cases.  It slows down getting the VM up and running.
+    - VBOX: After starting the VM, use a timed loop waiting for the initial
+        VM state change instead of just waiting for 5 seconds.  Older
+        machines can take longer than 5 seconds to switch from poweroff
+        to starting.  If we hit the main poll loop in that state the wrapper
+        thinks we have crashed.
+    - VBOX: Strip carriage returns from all the vboxmanage output on
+        Windows.
+        
+    samples/vboxwrapper/
+        vbox.cpp, .h
+        vboxwrapper.cpp

samples/vboxwrapper/vbox.cpp

@@ -83,6 +83,7 @@ VBOX_VM::~VBOX_VM() {
 
 int VBOX_VM::run() {
     int retval;
+    double timeout;
 
     retval = initialize();
     if (retval) return retval;
@@ -106,8 +107,16 @@ int VBOX_VM::run() {
     retval = start();
     if (retval) return retval;
 
-    // Give time enough for external processes to begin the VM boot process
+    // Wait for up to 5 minutes for the VM to switch states.  An older system
+    // under load can take a while.  Since the poll function can wait for up
+    // to a minute to execute a command we need to make this time based instead
+    // of interation based.
+    timeout = dtime() + 300;
+    do {
+        poll(false);
+        if (online) break;
         boinc_sleep(1.0);
+    } while (timeout <= dtime());
 
     return 0;
 }
@@ -122,14 +131,14 @@ void VBOX_VM::cleanup() {
 
 // 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) {
+int VBOX_VM::vbm_popen(string& arguments, string& output, const char* item, bool log_error, bool retry_failures) {
     int retval = 0;
     char buf[256];
     int retry_count = 0;
     string retry_notes;
 
     do {
-        retval = vbm_popen_raw(arguments, output, item);
+        retval = vbm_popen_raw(arguments, output);
         if (retval) {
 
             // VirtualBox designed the concept of sessions to prevent multiple applications using
@@ -157,12 +166,24 @@ int VBOX_VM::vbm_popen(string& arguments, string& output, const char* item, bool
             // Timeout?
             if (retry_count >= 6) break;
 
+            // Retry?
+            if (!retry_failures) break;
+
             retry_count++;
             boinc_sleep(5.0);
         }
     }
     while (retval);
 
+#ifdef _WIN32
+    // Remove \r from the log spew
+    for (string::iterator iter = output.begin(); iter != output.end(); ++iter) {
+        if (*iter == '\r') {
+            output.erase(iter);
+        }
+    }
+#endif
+
     // Add all relivent notes to the output string and log errors
     //
     if (retval && log_error) {
@@ -186,7 +207,7 @@ int VBOX_VM::vbm_popen(string& arguments, string& output, const char* item, bool
 
 // Execute the vbox manage application and copy the output to the buffer.
 //
-int VBOX_VM::vbm_popen_raw(string& arguments, string& output, const char* item) {
+int VBOX_VM::vbm_popen_raw(string& arguments, string& output) {
     char buf[256];
     string command;
     int retval = 0;
@@ -240,7 +261,17 @@ int VBOX_VM::vbm_popen_raw(string& arguments, string& output, const char* item)
     si.hStdInput = NULL;
 
     // Execute command
-    if (!CreateProcess(NULL, (LPTSTR)command.c_str(), NULL, NULL, TRUE, CREATE_NO_WINDOW, NULL, NULL, &si, &pi)) {
+    if (!CreateProcess(
+        NULL, 
+        (LPTSTR)command.c_str(),
+        NULL,
+        NULL,
+        TRUE,
+        CREATE_NO_WINDOW, NULL,
+        NULL,
+        &si,
+        &pi
+    )) {
         fprintf(
             stderr,
             "%s CreateProcess failed! (%d).\n",
@@ -350,7 +381,7 @@ bool VBOX_VM::is_registered() {
     command  = "showvminfo \"" + vm_name + "\" ";
     command += "--machinereadable ";
 
-    if (vbm_popen(command, output, "registration", false) == 0) {
+    if (vbm_popen(command, output, "registration", false, false) == 0) {
         if (output.find("VBOX_E_OBJECT_NOT_FOUND") == string::npos) {
             // Error message not found in text
             return true;
@@ -368,7 +399,7 @@ bool VBOX_VM::is_hdd_registered() {
 
     command = "showhdinfo \"" + virtual_machine_root_dir + "/" + image_filename + "\" ";
 
-    if (vbm_popen(command, output, "hdd registration", false) == 0) {
+    if (vbm_popen(command, output, "hdd registration", false, false) == 0) {
         if ((output.find("VBOX_E_FILE_ERROR") == string::npos) && (output.find("VBOX_E_OBJECT_NOT_FOUND") == string::npos)) {
             // Error message not found in text
             return true;
@@ -377,7 +408,7 @@ bool VBOX_VM::is_hdd_registered() {
     return false;
 }
 
-void VBOX_VM::poll() {
+void VBOX_VM::poll(bool log_state) {
     char buf[256];
     string command;
     string output;
@@ -388,7 +419,7 @@ void VBOX_VM::poll() {
     command  = "showvminfo \"" + vm_name + "\" ";
     command += "--machinereadable ";
 
-    if (vbm_popen(command, output, "VM state", false) == 0) {
+    if (vbm_popen(command, output, "VM state", false, false) == 0) {
         vmstate_start = output.find("VMState=\"");
         if (vmstate_start != string::npos) {
             vmstate_start += 9;
@@ -423,6 +454,7 @@ void VBOX_VM::poll() {
                 crashed = true;
             } else {
                 online = false;
+                if (log_state) {
                     fprintf(
                         stderr,
                         "%s Virtual machine is no longer is a running state. It is in '%s'.\n",
@@ -432,6 +464,7 @@ void VBOX_VM::poll() {
                 }
             }
         }
+    }
 }
 
 int VBOX_VM::get_install_directory(string& virtualbox_install_directory ) {
@@ -1246,6 +1279,36 @@ int VBOX_VM::get_network_bytes_sent(double& sent) {
     return 0;
 }
 
+int VBOX_VM::get_system_log(string& log) {
+    string virtualbox_user_home;
+    string virtualbox_system_log;
+    int retval = 0;
+
+    // Where is VirtualBox storing its configuration files?
+    virtualbox_user_home = getenv("VBOX_USER_HOME");
+    if (virtualbox_user_home.empty()) {
+        // If the override environment variable isn't specified then
+        // it is based of the current users HOME directory.
+#ifdef _WIN32
+        virtualbox_user_home = getenv("USERPROFILE");
+#else
+        virtualbox_user_home = getenv("HOME");
+#endif
+        virtualbox_user_home += "/.VirtualBox";
+    }
+
+    // Locate and read log file
+    virtualbox_system_log = virtualbox_user_home + "/VBoxSVC.log";
+    if (boinc_file_exists(virtualbox_system_log.c_str())) {
+        // Keep only the last 16k if it is larger than that.
+        retval = read_file_string(virtualbox_system_log.c_str(), log, 16384, true);
+    } else {
+        retval = ERR_NOT_FOUND;
+    }
+
+    return retval;
+}
+
 int VBOX_VM::get_vm_log(string& log) {
     string command;
     string output;
@@ -1257,16 +1320,13 @@ int VBOX_VM::get_vm_log(string& log) {
     retval = vbm_popen(command, output, "get vm log");
     if (retval) return retval;
 
-#ifdef _WIN32
-    // Remove \r from the log spew
-    for (string::iterator iter = output.begin(); iter != output.end(); ++iter) {
-        if (*iter == '\r') {
-            output.erase(iter);
-        }
-    }
-#endif
-
+    // Keep only the last 16k if it is larger than that.
+    size_t size = output.size();
+    if (size > 16384) {
+        log = output.substr(size - 16384, size);
+    } else {
         log = output;
+    }
 
     return 0;
 }

samples/vboxwrapper/vbox.h

@@ -77,7 +77,7 @@ struct VBOX_VM {
     int pause();
     int resume();
     void cleanup();
-    void poll();
+    void poll(bool log_state = true);
     bool is_running();
     bool is_paused();
 
@@ -94,6 +94,7 @@ struct VBOX_VM {
     int get_process_id(int& process_id);
     int get_network_bytes_sent(double& sent);
     int get_network_bytes_received(double& received);
+    int get_system_log(std::string& log);
     int get_vm_log(std::string& log);
     int read_floppy(std::string& data);
     int write_floppy(std::string& data);
@@ -103,10 +104,10 @@ struct VBOX_VM {
     static int get_install_directory(std::string& dir);
     static int get_slot_directory(std::string& dir);
     static int vbm_popen(
-        std::string& command, std::string& output, const char* item, bool log_error = true
+        std::string& command, std::string& output, const char* item, bool log_error = true, bool retry_failures = true
     );
     static int vbm_popen_raw(
-        std::string& command, std::string& output, const char* item
+        std::string& command, std::string& output
     );
 };
 

samples/vboxwrapper/vboxwrapper.cpp

@@ -220,6 +220,7 @@ int main(int argc, char** argv) {
     int vm_pid=0;
     int vm_max_cpus=0;
     std::string vm_log;
+    std::string system_log;
     char buf[256];
 
     memset(&boinc_options, 0, sizeof(boinc_options));
@@ -384,6 +385,7 @@ int main(int argc, char** argv) {
         }
         if (!vm.online) {
             if (vm.crashed || (elapsed_time < vm.job_duration)) {
+                vm.get_system_log(system_log);
                 vm.get_vm_log(vm_log);
             }
             vm.cleanup();
@@ -440,11 +442,15 @@ int main(int argc, char** argv) {
                         stderr,
                         "%s NOTE: This could be like a blue-screen event in Windows, the rest of the information in this file\n"
                         "%s   is diagnostic information generated by the hypervisor.\n"
+                        "%s Hypervisor System Log:\n\n"
+                        "%s\n"
                         "%s VM Execution Log:\n\n"
                         "%s\n",
                         boinc_msg_prefix(buf, sizeof(buf)),
                         boinc_msg_prefix(buf, sizeof(buf)),
                         boinc_msg_prefix(buf, sizeof(buf)),
+                        system_log.c_str(),
+                        boinc_msg_prefix(buf, sizeof(buf)),
                         vm_log.c_str()
                     );
                 }