add debugg logs (#104)

add debugg logs


Signed-off-by: Pablo Chacin <[email protected]>

analyze.go

@@ -1,14 +1,26 @@
 package k6exec
 
 import (
+	"log/slog"
 	"os"
 	"strings"
 
 	"github.com/grafana/k6deps"
 )
 
 func analyze(args []string, opts *Options) (k6deps.Dependencies, error) {
-	return k6deps.Analyze(newDepsOptions(args, opts))
+	depsOpts := newDepsOptions(args, opts)
+
+	// we call Analyze before logging because it will return the name of the manifest, in any
+	deps, err := k6deps.Analyze(depsOpts)
+
+	slog.Debug("analyzing sources", depsOptsAttrs(depsOpts)...)
+
+	if err == nil && len(deps) > 0 {
+		slog.Debug("found dependencies", "deps", deps.String())
+	}
+
+	return deps, err
 }
 
 func newDepsOptions(args []string, opts *Options) *k6deps.Options {
@@ -58,3 +70,26 @@ func scriptArg(args []string) (string, bool) {
 
 	return last, true
 }
+
+func depsOptsAttrs(opts *k6deps.Options) []any {
+	attrs := []any{}
+
+	if opts.Manifest.Name != "" {
+		attrs = append(attrs, "Manifest", opts.Manifest.Name)
+	}
+
+	if opts.Archive.Name != "" {
+		attrs = append(attrs, "Archive", opts.Archive.Name)
+	}
+
+	// ignore script if archive is present
+	if opts.Archive.Name == "" && opts.Script.Name != "" {
+		attrs = append(attrs, "Script", opts.Script.Name)
+	}
+
+	if opts.Env.Name != "" {
+		attrs = append(attrs, "Env", opts.Env.Name)
+	}
+
+	return attrs
+}

cmd/state.go

@@ -142,6 +142,7 @@ func (s *state) runE(_ *cobra.Command, _ []string) error {
 		}
 	}()
 
+	slog.Debug("running", "k6 binary", s.cmd.Path, "args", s.cmd.Args[1:])
 	err = s.cmd.Run()
 
 	return err

cmd/state_internal_test.go

@@ -14,8 +14,9 @@ import (
 	"github.com/stretchr/testify/require"
 )
 
-func Test_interal_state(t *testing.T) { //nolint:tparallel
-	t.Parallel()
+func Test_interal_state(t *testing.T) {
+	t.Setenv("K6_BUILD_SERVICE_URL", "")
+	t.Setenv("K6_CLOUD_TOKEN", "")
 
 	env, err := testutils.NewTestEnv(testutils.TestEnvConfig{
 		WorkDir: t.TempDir(),

command.go

@@ -2,6 +2,7 @@ package k6exec
 
 import (
 	"context"
+	"log/slog"
 	"os/exec"
 )
 
@@ -17,11 +18,16 @@ func Command(ctx context.Context, args []string, opts *Options) (*exec.Cmd, func
 		return nil, nil, err
 	}
 
+	slog.Info("fetching k6 binary")
+
 	exe, err := provision(ctx, deps, opts)
 	if err != nil {
 		return nil, nil, err
 	}
 
+	// FIXME: can we leak sensitive information in arguments here? (pablochacin)
+	slog.Debug("running k6", "path", exe, "args", args)
+
 	cmd := exec.CommandContext(ctx, exe, args...) //nolint:gosec
 
 	// TODO: once k6provider implements the cleanup of binary return the proper cleanup function (pablochacin)

go.mod

@@ -6,6 +6,7 @@ require (
 	github.com/grafana/clireadme v0.1.0
 	github.com/grafana/k6build v0.5.4
 	github.com/grafana/k6deps v0.2.1
+	github.com/grafana/k6provider v0.1.9
 	github.com/samber/slog-logrus/v2 v2.5.2
 	github.com/sirupsen/logrus v1.9.3
 	github.com/spf13/cobra v1.8.1
@@ -30,7 +31,6 @@ require (
 	github.com/evanw/esbuild v0.24.2 // indirect
 	github.com/grafana/k6foundry v0.3.1 // indirect
 	github.com/grafana/k6pack v0.2.4 // indirect
-	github.com/grafana/k6provider v0.1.7
 	github.com/inconshreveable/mousetrap v1.1.0 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/samber/lo v1.47.0 // indirect

go.sum

@@ -22,8 +22,8 @@ github.com/grafana/k6foundry v0.3.1 h1:nv4BqlJfNXrVMk7ps7mlGiPgegR73ogTvisn1y0bY
 github.com/grafana/k6foundry v0.3.1/go.mod h1:4Hw0ll6ZsKN8f3cgp7I4N6EkhXafZ6CBC6fDJWkW7/Q=
 github.com/grafana/k6pack v0.2.4 h1:JzbaO/NnLBaM2Shbn59WynaGAYL+jMvnjsoj/VTr3es=
 github.com/grafana/k6pack v0.2.4/go.mod h1:JTG8lQRU4U4WNKkznSL6zYokviiFVIp1I9W7z7NmrLA=
-github.com/grafana/k6provider v0.1.7 h1:vBHzm80u7vAa2xIocxtq/rK4fy1d0kaVR9arrGNc1n0=
-github.com/grafana/k6provider v0.1.7/go.mod h1:Uvqmgg/16Dc4vm70EwRxx2teA9NMZtSPm1v9qnobtbY=
+github.com/grafana/k6provider v0.1.9 h1:N9yoauRIb4JtDPBB+z3mrIdFHvo5h7S6UA9pfKdjVZg=
+github.com/grafana/k6provider v0.1.9/go.mod h1:voN3IOPdqODBp7RGGawYeHNHTxdwYHb6LW/9dYtBtHw=
 github.com/inconshreveable/mousetrap v1.1.0 h1:wN+x4NVGpMsO7ErUn/mUI3vEoE6Jt13X2s0bqwp9tc8=
 github.com/inconshreveable/mousetrap v1.1.0/go.mod h1:vpF70FUmC8bwa3OWnCshd2FqLfsEA9PFc4w1p2J65bw=
 github.com/klauspost/compress v1.17.9 h1:6KIumPrER1LHsvBVuDa0r5xaG0Es51mhhB9BQB2qeMA=

provision.go

@@ -2,6 +2,8 @@ package k6exec
 
 import (
 	"context"
+	"log/slog"
+	"strings"
 
 	"github.com/grafana/k6deps"
 	"github.com/grafana/k6provider"
@@ -20,10 +22,22 @@ func provision(ctx context.Context, deps k6deps.Dependencies, opts *Options) (st
 		return "", err
 	}
 
+	slog.Debug("fetching binary", "build service URL: ", opts.BuildServiceURL)
+
 	binary, err := provider.GetBinary(ctx, deps)
 	if err != nil {
 		return "", err
 	}
 
+	// Cut the query string from the download URL to reduce noise in the logs
+	downloadURL, _, _ := strings.Cut(binary.DownloadURL, "?")
+	slog.Debug("binary fetched",
+		"Path: ", binary.Path,
+		"dependencies", deps.String(),
+		"checksum", binary.Checksum,
+		"cached", binary.Cached,
+		"download URL", downloadURL,
+	)
+
 	return binary.Path, nil
 }