Log enhancements - add slow logger

src/main/groovy/com/morpheusdata/scvmm/ScvmmApiService.groovy

@@ -6,6 +6,7 @@ import com.morpheusdata.core.util.ComputeUtility
 import com.morpheusdata.model.Cloud
 import com.morpheusdata.model.ComputeServer
 import com.morpheusdata.model.KeyPair
+import com.morpheusdata.scvmm.logging.ExecutionTracker
 import com.morpheusdata.scvmm.logging.LogInterface
 import com.morpheusdata.scvmm.logging.LogWrapper
 import groovy.json.JsonOutput
@@ -480,7 +481,9 @@ if(\$cloud) {
     def listClouds(opts) {
         def rtn = [success: false, clouds: []]
         def command = generateCommandString('Get-SCCloud -VMMServer localhost | Select ID, Name')
-        def out = wrapExecuteCommand(command, opts)
+        def out = ExecutionTracker.execute("listClouds", {
+            wrapExecuteCommand(command, opts)
+        }, -1)
         if (out.success) {
             rtn.clouds = out.data
             rtn.success = true
@@ -709,7 +712,9 @@ foreach (\$VHDconf in \$Disks) {
 		}
 		\$report """
         def command = generateCommandString(commandStr)
-        def out = wrapExecuteCommand(command, opts)
+        def out = ExecutionTracker.execute("listClusters", {
+            wrapExecuteCommand(command, opts)
+        }, -1)
         if (out.success) {
             rtn.clusters = out.data
 
@@ -732,7 +737,9 @@ foreach (\$VHDconf in \$Disks) {
         def commandStr = """Get-SCVMHostGroup -VMMServer localhost | Select-Object @{Name="id";Expression={\$_.ID.Guid}}, @{Name="name";Expression={\$_.Name}}, @{Name="path";Expression={\$_.Path}}, @{Name="parent";Expression={\$_.ParentHostGroup.Name}}, @{Name="root";Expression={\$_.IsRoot}}"""
 
         def command = generateCommandString(commandStr)
-        def out = wrapExecuteCommand(command, opts)
+        def out = ExecutionTracker.execute("internalListHostGroups", {
+            wrapExecuteCommand(command, opts)
+        }, -1)
         if (out.success) {
             rtn.hostGroups = out.data
             rtn.success = true
@@ -754,7 +761,9 @@ foreach(\$share in \$shares) {
 }
 \$report"""
 
-        def out = wrapExecuteCommand(generateCommandString(command), opts)
+        def out = ExecutionTracker.execute("listLibraryShares", {
+            wrapExecuteCommand(generateCommandString(command), opts)
+        }, -1)
         if (out.success) {
             rtn.libraryShares = out.data
             rtn.success = true
@@ -776,7 +785,9 @@ foreach (\$cloud in \$clouds) {
 }
 \$report"""
             def command = generateCommandString(commandStr)
-            def out = wrapExecuteCommand(command, opts)
+            def out = ExecutionTracker.execute("listHostGroups", {
+                wrapExecuteCommand(command, opts)
+            }, -1)
             log.debug("out: ${out.data}")
             if (out.success) {
                 def clouds = out.data
@@ -2746,8 +2757,10 @@ For (\$i=0; \$i -le 10; \$i++) {
         getScvmmCloudOpts(morpheusContext, cloud, hypervisor) + getScvmmControllerOpts(cloud, hypervisor)
     }
 
-    def wrapExecuteCommand(String command, Map opts = [:]) {
-        def out = executeCommand(command, opts)
+    def wrapExecuteCommand(String command, Map opts = [:], Integer slowLoggerTimeout = 0) {
+        def out = ExecutionTracker.execute(command, {
+            executeCommand(command, opts)
+        }, slowLoggerTimeout)
 
         if (out.data) {
             def payload = out.data

src/main/groovy/com/morpheusdata/scvmm/common/Constants.groovy

@@ -0,0 +1,9 @@
+package com.morpheusdata.scvmm.common
+
+class Constants {
+
+    // Time Constants represented in Milliseconds
+    static final int MILLISECOND = 1
+    static final int SECOND = 1000 * MILLISECOND
+    static final int MINUTE = 60 * SECOND
+}

src/main/groovy/com/morpheusdata/scvmm/logging/ExecutionTracker.groovy

@@ -0,0 +1,60 @@
+package com.morpheusdata.scvmm.logging
+
+import com.morpheusdata.model.TaskResult
+import com.morpheusdata.scvmm.common.Constants
+import com.morpheusdata.scvmm.tracker.TimeTracker
+import groovy.transform.CompileStatic
+
+import java.time.Duration
+
+/**
+ * Error-aware logging utility for SCVMM plugin that tracks execution time
+ * and provides error handling capabilities.
+ */
+@CompileStatic
+class ExecutionTracker {
+    static final Integer SLOW_LOG_MAX_TIME = 10 * Constants.SECOND
+
+    static void printLog(TimeTracker tracker, String activityName, Integer customMaxTimeout) {
+        def timeout = customMaxTimeout != 0 ? customMaxTimeout : SLOW_LOG_MAX_TIME
+        if (customMaxTimeout < 0 || tracker.getOverallTime(activityName) > timeout) {
+            LogWrapper.instance.info("Activity: { ${activityName} } took " +
+                    "${tracker.getOverallTime(activityName) / Constants.SECOND}s to complete")
+        } else {
+            LogWrapper.instance.debug("Activity: { ${activityName} } execution completed in " +
+                    "${tracker.getOverallTime(activityName) / Constants.SECOND}s")
+        }
+    }
+
+    static <T> T execute(String command, Closure<T> action, Integer slowLoggerTimeout) {
+        LogWrapper.instance.debug("Executing ${command}")
+        TimeTracker tracker = new TimeTracker(command)
+        T result
+
+        try {
+            result = action.call()
+
+            // Check if result has error/success properties safely with CompileStatic
+            if (result != null) {
+                // Use metaClass for property checking in CompileStatic mode
+                def metaResult = (TaskResult) result
+
+                // Check for success property that is false
+                if (!metaResult?.success || metaResult?.error != null) {
+                    String errorMsg = metaResult?.error ? metaResult?.error?.toString() : "Unknown error"
+                    LogWrapper.instance.error("Error in ${command}: ${errorMsg}")
+                    return result
+                }
+            }
+
+            return result
+        } catch (Exception e) {
+            // Log the exception
+            LogWrapper.instance.error("Exception in ${command}: ${e.message}", e)
+            // Rethrow the exception
+            throw e
+        } finally {
+            printLog(tracker.end(command), command, slowLoggerTimeout)
+        }
+    }
+}

src/main/groovy/com/morpheusdata/scvmm/tracker/TimeTracker.groovy

@@ -0,0 +1,84 @@
+package com.morpheusdata.scvmm.tracker
+
+import com.morpheusdata.scvmm.common.Constants
+import groovy.transform.CompileStatic
+
+/**
+ * Custom class to track time for activities and workflows.
+ */
+@CompileStatic
+class TimeTracker {
+    // Map to hold start and end times for both activities and workflows
+    private final Map<String, Long> timeMap
+
+    /**
+     * Constructor for TimeTracker.
+     */
+    TimeTracker() {
+        timeMap = [:]
+    }
+
+    /**
+     * Constructor for TimeTracker.
+     *
+     * @param activityName The name of the activity to track
+     */
+    TimeTracker(String activityName) {
+        timeMap = [:]
+        start(activityName)
+    }
+
+    /**
+     * Start tracking time for a given activity under a workflow.
+     *
+     * @param activity The name of the activity to track
+     * @return The TimeTracker object
+     */
+    TimeTracker start(String activity) {
+        timeMap[activity] = System.currentTimeMillis() // Start time for the activity
+        return this
+    }
+
+    /**
+     * End tracking time for a given activity under a workflow.
+     *
+     * @param activity The name of the activity to track
+     * @return The TimeTracker object
+     */
+    TimeTracker end(String activity) {
+        if (timeMap.containsKey(activity)) {
+            timeMap[activity] = System.currentTimeMillis() - timeMap[activity]
+        }
+        return this
+    }
+
+    /**
+     * Get the overall time taken for a given activity.
+     *
+     * @param activity The name of the activity to track
+     * @return The overall time taken for the activity
+     */
+    Long getOverallTime(String activity) {
+        return timeMap[activity]
+    }
+
+    /**
+     * Get the overall time taken for all activities.
+     *
+     * @return The overall time taken for all activities
+     */
+    @Override
+    String toString() {
+        return timeMap.collect { key, value -> "${key}=${value / Constants.SECOND}s" }.join(", ")
+    }
+
+    /**
+     * Get the elapsed time for a given activity.
+     *
+     * @param activity The name of the activity to track
+     * @return The elapsed time for the activity
+     */
+    Long getElapsedTime(String activity) {
+        return timeMap[activity] / Constants.SECOND as Long
+    }
+}