[vscode-extension] Logging events in logfile (#1745)

## Summary
Added capability to log sequence of events and potential errors in
"Re-open in devbox shell environment" functionality of the extension.
This involved adding a log file in `.devbox/extension.log` file which
both the vscode extension process and devbox binary will output their
logs into.

The reason to add this capability is "Re-open in devbox shell"
functionality relies on multiple sub-processes running a sequence of
events correctly. So if one breaks along the way, often times, the error
message for it will be lost. This PR makes sure that in such cases, the
user has a way of capturing the error messages that may have been lost.

## How was it tested?
1. in devbox, run: `devbox run build` this creates a binary in
`dist/devbox` copy the absolute path to that binary
2. in an editor, edit the file `/usr/local/bin/devbox` in line 414 to be
similar to below:
```bash
#local -r bin="${INSTALL_DIR}/${version}_${platform}/${TOOL_NAME}"
# absolute path to devbox binary in dist/
local -r bin="/Users/mohsenansari/code/jetpack/go.jetpack.io/devbox/dist/devbox"
```
3. Back in devbox repo in Terminal `cd vscode-extension` then run `vsce
package` (if you don't have vsce install do it via `npm i -g vsce`
4. Open vscode and uninstall the already installed devbox extension.
Then reload vscode.
5. In Terminal, run `code --install-extension devbox-0.1.3.vsix`
6. In VSCode go to settings(UI) and search for devbox. Enable debug mode
by ticking its checkbox.
7. cmd + shift + p and search for "Devbox: Re-open in Devbox shell
environment"
8. Confirm an `extension.log` file is created in `.devbox/` directory
and contains the logs for reopen in devbox feature.

Author: mohsenari

internal/boxcli/integrate.go

@@ -6,19 +6,23 @@ package boxcli
 import (
 	"bytes"
 	"encoding/json"
+	"fmt"
+	"log"
+	"os"
 	"os/exec"
 	"slices"
 	"strings"
+	"time"
 
 	"github.com/spf13/cobra"
 	"github.com/zealic/go2node"
-	"go.jetpack.io/devbox/internal/debug"
 	"go.jetpack.io/devbox/internal/devbox"
 	"go.jetpack.io/devbox/internal/devbox/devopt"
 )
 
 type integrateCmdFlags struct {
-	config configFlags
+	config    configFlags
+	debugmode bool
 }
 
 func integrateCmd() *cobra.Command {
@@ -43,9 +47,10 @@ func integrateVSCodeCmd() *cobra.Command {
 		Hidden: true,
 		Short:  "Integrate devbox environment with VSCode.",
 		RunE: func(cmd *cobra.Command, args []string) error {
-			return runIntegrateVSCodeCmd(cmd)
+			return runIntegrateVSCodeCmd(cmd, flags)
 		},
 	}
+	command.Flags().BoolVar(&flags.debugmode, "debugmode", false, "enable debug outputs to a file.")
 	flags.config.register(command)
 
 	return command
@@ -55,21 +60,27 @@ type parentMessage struct {
 	ConfigDir string `json:"configDir"`
 }
 
-func runIntegrateVSCodeCmd(cmd *cobra.Command) error {
+func runIntegrateVSCodeCmd(cmd *cobra.Command, flags integrateCmdFlags) error {
+	dbug := debugMode{
+		enabled: flags.debugmode,
+	}
 	// Setup process communication with node as parent
+	dbug.logToFile("Devbox process initiated. Setting up communication channel with VSCode process")
 	channel, err := go2node.RunAsNodeChild()
 	if err != nil {
+		dbug.logToFile(err.Error())
 		return err
 	}
-
 	// Get config dir as a message from parent process
 	msg, err := channel.Read()
 	if err != nil {
+		dbug.logToFile(err.Error())
 		return err
 	}
 	// Parse node process' message
 	var message parentMessage
 	if err = json.Unmarshal(msg.Message, &message); err != nil {
+		dbug.logToFile(err.Error())
 		return err
 	}
 
@@ -79,11 +90,14 @@ func runIntegrateVSCodeCmd(cmd *cobra.Command) error {
 		Stderr: cmd.ErrOrStderr(),
 	})
 	if err != nil {
+		dbug.logToFile(err.Error())
 		return err
 	}
 	// Get env variables of a devbox shell
+	dbug.logToFile("Computing devbox environment")
 	envVars, err := box.EnvVars(cmd.Context())
 	if err != nil {
+		dbug.logToFile(err.Error())
 		return err
 	}
 	envVars = slices.DeleteFunc(envVars, func(s string) bool {
@@ -96,10 +110,12 @@ func runIntegrateVSCodeCmd(cmd *cobra.Command) error {
 	})
 
 	// Send message to parent process to terminate
+	dbug.logToFile("Signaling VSCode to close")
 	err = channel.Write(&go2node.NodeMessage{
 		Message: []byte(`{"status": "finished"}`),
 	})
 	if err != nil {
+		dbug.logToFile(err.Error())
 		return err
 	}
 	// Open vscode with devbox shell environment
@@ -108,10 +124,34 @@ func runIntegrateVSCodeCmd(cmd *cobra.Command) error {
 	var outb, errb bytes.Buffer
 	cmnd.Stdout = &outb
 	cmnd.Stderr = &errb
+	dbug.logToFile("Re-opening VSCode in computed devbox environment")
 	err = cmnd.Run()
 	if err != nil {
-		debug.Log("out: %s \n err: %s", outb.String(), errb.String())
+		dbug.logToFile(fmt.Sprintf("stdout: %s \n stderr: %s", outb.String(), errb.String()))
+		dbug.logToFile(err.Error())
 		return err
 	}
 	return nil
 }
+
+type debugMode struct {
+	enabled bool
+}
+
+func (d *debugMode) logToFile(msg string) {
+	// only write to file when --debugmode=true flag is passed
+	if d.enabled {
+		file, err := os.OpenFile(".devbox/extension.log", os.O_APPEND|os.O_WRONLY, 0o666)
+		if err != nil {
+			log.Fatal(err)
+		}
+		timestamp := time.Now().UTC().Format(time.RFC1123)
+		_, err = file.WriteString("[" + timestamp + "] " + msg + "\n")
+		if err != nil {
+			log.Fatal(err)
+		}
+		if err = file.Close(); err != nil {
+			log.Fatal(err)
+		}
+	}
+}

vscode-extension/package.json

@@ -128,6 +128,11 @@
           "type": "boolean",
           "default": true,
           "description": "Automatically run devbox shell when terminal is opened."
+        },
+        "devbox.enableDebugMode": {
+          "type": "boolean",
+          "default": false,
+          "description": "Enables debug mode for this extension which creates an extension.log in .devbox/ directory. Currently only works for 'Devbox: Reopen in Devbox shell environment' command."
         }
       }
     }

vscode-extension/src/devbox.ts

@@ -1,4 +1,5 @@
 import { window, workspace, commands, ProgressLocation, Uri, ConfigurationTarget, env } from 'vscode';
+import { writeFile, open } from 'fs/promises';
 import { spawn, spawnSync } from 'node:child_process';
 
 
@@ -32,25 +33,30 @@ export async function devboxReopen() {
         if (workspace.workspaceFolders) {
           const workingDir = workspace.workspaceFolders[0].uri;
           const dotdevbox = Uri.joinPath(workingDir, '/.devbox');
+          await logToFile(dotdevbox, 'Installing devbox packages');
           progress.report({ message: 'Installing devbox packages...', increment: 25 });
           await setupDotDevbox(workingDir, dotdevbox);
-
+          
           // setup required vscode settings
+          await logToFile(dotdevbox, 'Updating VSCode configurations');
           progress.report({ message: 'Updating configurations...', increment: 50 });
           updateVSCodeConf();
 
           // Calling CLI to compute devbox env
+          await logToFile(dotdevbox, 'Calling "devbox integrate" to setup environment');
           progress.report({ message: 'Calling Devbox to setup environment...', increment: 80 });
           // To use a custom compiled devbox when testing, change this to an absolute path.
           const devbox = 'devbox';
           // run devbox integrate and then close this window
-          let child = spawn(devbox, ['integrate', 'vscode'], {
+          const debugModeFlag = workspace.getConfiguration("devbox").get("enableDebugMode");
+          let child = spawn(devbox, ['integrate', 'vscode', '--debugmode='+debugModeFlag], {
             cwd: workingDir.path,
             stdio: [0, 1, 2, 'ipc']
           });
           // if CLI closes before sending "finished" message
           child.on('close', (code: number) => {
             console.log("child process closed with exit code:", code);
+            logToFile(dotdevbox, 'child process closed with exit code: ' + code);
             window.showErrorMessage("Failed to setup devbox environment.");
             reject();
           });
@@ -65,6 +71,7 @@ export async function devboxReopen() {
             }
             else {
               console.log(msg);
+              logToFile(dotdevbox, 'Failed to setup devbox environment.' + String(msg));
               window.showErrorMessage("Failed to setup devbox environment.");
               reject();
             }
@@ -127,4 +134,21 @@ function updateVSCodeConf() {
       ConfigurationTarget.Workspace
     );
   }
-}
+}
+
+async function logToFile(dotDevboxPath: Uri, message: string) {
+  // only print to log file if debug mode config is set to true
+  if (workspace.getConfiguration("devbox").get("enableDebugMode")){
+    try {   
+      const logFilePath = Uri.joinPath(dotDevboxPath, 'extension.log');
+      const timestamp = new Date().toUTCString();
+      const fileHandler = await open(logFilePath.fsPath, 'a');
+      const logData = new Uint8Array(Buffer.from(`[${timestamp}] ${message}\n`));
+      await writeFile(fileHandler, logData, {flag: 'a'} );
+      await fileHandler.close();
+    } catch (error) {
+      console.log("failed to write to extension.log file");
+      console.error(error);
+    }
+  }
+}