feat: add more logging around echo tar (coder#10731)

mtojek · web-flow · commit 0e5eecd7da8e · 2023-11-16T16:52:04.000+01:00
diff --git a/coderd/coderdtest/coderdtest.go b/coderd/coderdtest/coderdtest.go
@@ -709,7 +709,7 @@ func createAnotherUserRetry(t testing.TB, client *codersdk.Client, organizationI
 // with testing.
 func CreateTemplateVersion(t testing.TB, client *codersdk.Client, organizationID uuid.UUID, res *echo.Responses, mutators ...func(*codersdk.CreateTemplateVersionRequest)) codersdk.TemplateVersion {
 	t.Helper()
-	data, err := echo.Tar(res)
+	data, err := echo.TarWithOptions(context.Background(), client.Logger(), res)
 	require.NoError(t, err)
 	file, err := client.Upload(context.Background(), codersdk.ContentTypeTar, bytes.NewReader(data))
 	require.NoError(t, err)
diff --git a/coderd/prometheusmetrics/insights/metricscollector_test.go b/coderd/prometheusmetrics/insights/metricscollector_test.go
@@ -15,6 +15,7 @@ import (
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
+	"cdr.dev/slog"
 	"cdr.dev/slog/sloggers/slogtest"
 	"github.com/coder/coder/v2/agent/agenttest"
 	"github.com/coder/coder/v2/coderd/coderdtest"
@@ -41,6 +42,7 @@ func TestCollectInsights(t *testing.T) {
 		Pubsub:                    ps,
 	}
 	client := coderdtest.New(t, options)
+	client.SetLogger(logger.Named("client").Leveled(slog.LevelDebug))
 
 	// Given
 	// Initialize metrics collector
diff --git a/provisioner/echo/serve.go b/provisioner/echo/serve.go
@@ -13,6 +13,8 @@ import (
 	"golang.org/x/xerrors"
 	protobuf "google.golang.org/protobuf/proto"
 
+	"cdr.dev/slog"
+
 	"github.com/coder/coder/v2/provisionersdk"
 	"github.com/coder/coder/v2/provisionersdk/proto"
 )
@@ -211,6 +213,15 @@ type Responses struct {
 
 // Tar returns a tar archive of responses to provisioner operations.
 func Tar(responses *Responses) ([]byte, error) {
+	logger := slog.Make()
+	return TarWithOptions(context.Background(), logger, responses)
+}
+
+// TarWithOptions returns a tar archive of responses to provisioner operations,
+// but it gives more insight into the archiving process.
+func TarWithOptions(ctx context.Context, logger slog.Logger, responses *Responses) ([]byte, error) {
+	logger = logger.Named("echo_tar")
+
 	if responses == nil {
 		responses = &Responses{
 			ParseComplete, ApplyComplete, PlanComplete,
@@ -242,6 +253,7 @@ func Tar(responses *Responses) ([]byte, error) {
 		if err != nil {
 			return err
 		}
+		logger.Debug(ctx, "write proto", slog.F("name", name), slog.F("message", string(data)))
 
 		err = writer.WriteHeader(&tar.Header{
 			Name: name,
@@ -252,10 +264,11 @@ func Tar(responses *Responses) ([]byte, error) {
 			return err
 		}
 
-		_, err = writer.Write(data)
+		n, err := writer.Write(data)
 		if err != nil {
 			return err
 		}
+		logger.Debug(context.Background(), "proto written", slog.F("name", name), slog.F("bytes_written", n))
 
 		return nil
 	}
diff --git a/provisionersdk/session.go b/provisionersdk/session.go
@@ -5,6 +5,7 @@ import (
 	"bytes"
 	"context"
 	"fmt"
+	"hash/crc32"
 	"io"
 	"os"
 	"path/filepath"
@@ -216,6 +217,11 @@ func (s *Session) extractArchive() error {
 			}
 			return xerrors.Errorf("read template source archive: %w", err)
 		}
+		s.Logger.Debug(context.Background(), "read archive entry",
+			slog.F("name", header.Name),
+			slog.F("mod_time", header.ModTime),
+			slog.F("size", header.Size))
+
 		// Security: don't untar absolute or relative paths, as this can allow a malicious tar to overwrite
 		// files outside the workdir.
 		if !filepath.IsLocal(header.Name) {
@@ -253,8 +259,11 @@ func (s *Session) extractArchive() error {
 			if err != nil {
 				return xerrors.Errorf("create file %q (mode %s): %w", headerPath, mode, err)
 			}
+
+			hash := crc32.NewIEEE()
+			hashReader := io.TeeReader(reader, hash)
 			// Max file size of 10MiB.
-			size, err := io.CopyN(file, reader, 10<<20)
+			size, err := io.CopyN(file, hashReader, 10<<20)
 			if xerrors.Is(err, io.EOF) {
 				err = nil
 			}
@@ -270,7 +279,7 @@ func (s *Session) extractArchive() error {
 				slog.F("size_bytes", size),
 				slog.F("path", headerPath),
 				slog.F("mode", mode),
-			)
+				slog.F("checksum", fmt.Sprintf("%x", hash.Sum(nil))))
 		}
 	}
 	return nil
