[debug] Print exec time (#1461)

## Summary

Enable this by setting `DEVBOX_PRINT_EXEC_TIME=1`

## How was it tested?

```
export DEVBOX_PRINT_EXEC_TIME=1
devbox run echo 1
```

Author: mikeland73

internal/boxcli/midcobra/debug.go

@@ -5,7 +5,6 @@ package midcobra
 
 import (
 	"errors"
-	"os"
 	"os/exec"
 	"strconv"
 
@@ -15,7 +14,6 @@ import (
 
 	"go.jetpack.io/devbox/internal/boxcli/usererr"
 	"go.jetpack.io/devbox/internal/debug"
-	"go.jetpack.io/devbox/internal/envir"
 	"go.jetpack.io/devbox/internal/telemetry"
 	"go.jetpack.io/devbox/internal/ux"
 )
@@ -41,14 +39,11 @@ func (d *DebugMiddleware) preRun(cmd *cobra.Command, args []string) {
 		return
 	}
 
-	strVal := ""
 	if d.flag.Changed {
-		strVal = d.flag.Value.String()
-	} else {
-		strVal = os.Getenv(envir.DevboxDebug)
-	}
-	if enabled, _ := strconv.ParseBool(strVal); enabled {
-		debug.Enable()
+		strVal := d.flag.Value.String()
+		if enabled, _ := strconv.ParseBool(strVal); enabled {
+			debug.Enable()
+		}
 	}
 }
 

internal/boxcli/root.go

@@ -121,7 +121,11 @@ func Main() {
 		return
 	}
 
-	os.Exit(Execute(ctx, os.Args[1:]))
+	code := Execute(ctx, os.Args[1:])
+	// Run out here instead of as a middleware so we can capture any time we spend
+	// in middlewares as well.
+	debug.PrintExecutionTime()
+	os.Exit(code)
 }
 
 func listAllCommands(cmd *cobra.Command, indent string) {

internal/debug/debug.go

@@ -7,18 +7,20 @@ import (
 	"fmt"
 	"io"
 	"log"
+	"os"
 	"runtime"
+	"strconv"
 
 	"github.com/getsentry/sentry-go"
 	"github.com/pkg/errors"
-
-	"go.jetpack.io/devbox/internal/envir"
 )
 
+const DevboxDebug = "DEVBOX_DEBUG"
+
 var enabled bool
 
 func init() {
-	enabled = envir.IsDevboxDebugEnabled()
+	enabled, _ = strconv.ParseBool(os.Getenv(DevboxDebug))
 }
 
 func IsEnabled() bool { return enabled }

internal/debug/time.go

@@ -0,0 +1,27 @@
+// Copyright 2023 Jetpack Technologies Inc and contributors. All rights reserved.
+// Use of this source code is governed by the license in the LICENSE file.
+
+package debug
+
+import (
+	"fmt"
+	"os"
+	"strconv"
+	"strings"
+	"time"
+)
+
+const devboxPrintExecTime = "DEVBOX_PRINT_EXEC_TIME"
+
+var start = time.Now()
+
+func PrintExecutionTime() {
+	if enabled, _ := strconv.ParseBool(os.Getenv(devboxPrintExecTime)); !enabled {
+		return
+	}
+	fmt.Fprintf(
+		os.Stderr,
+		"\"%s\" took %s\n", strings.Join(os.Args, " "),
+		time.Since(start),
+	)
+}

internal/envir/env.go

@@ -5,7 +5,6 @@ package envir
 
 const (
 	DevboxCache         = "DEVBOX_CACHE"
-	DevboxDebug         = "DEVBOX_DEBUG"
 	DevboxFeaturePrefix = "DEVBOX_FEATURE_"
 	DevboxGateway       = "DEVBOX_GATEWAY"
 	// DevboxLatestVersion is the latest version available of the devbox CLI binary.

internal/envir/util.go

@@ -23,11 +23,6 @@ func DoNotTrack() bool {
 	return doNotTrack
 }
 
-func IsDevboxDebugEnabled() bool {
-	enabled, _ := strconv.ParseBool(os.Getenv(DevboxDebug))
-	return enabled
-}
-
 func IsInBrowser() bool { // TODO: a better name
 	inBrowser, _ := strconv.ParseBool(os.Getenv("START_WEB_TERMINAL"))
 	return inBrowser

testscripts/testrunner/setupenv.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/rogpeppe/go-internal/testscript"
 
+	"go.jetpack.io/devbox/internal/debug"
 	"go.jetpack.io/devbox/internal/envir"
 	"go.jetpack.io/devbox/internal/xdg"
 )
@@ -22,7 +23,7 @@ func setupTestEnv(t *testing.T, envs *testscript.Env) error {
 		return err
 	}
 
-	envs.Setenv(envir.DevboxDebug, os.Getenv(envir.DevboxDebug))
+	envs.Setenv(debug.DevboxDebug, os.Getenv(debug.DevboxDebug))
 	return nil
 }