upload: add debug logging

If the directory telemetry.LocalDir/debug exists write a per-process
log of upload actions there.

Fixes:  golang/go#63709

Change-Id: Ia42400fa7ec40848897e76d39e424de1c9fe8d40
Reviewed-on: https://go-review.googlesource.com/c/telemetry/+/558640
Run-TryBot: Peter Weinberger <pjw@google.com>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Robert Findley <rfindley@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>

internal/upload/dates_test.go

@@ -363,7 +363,11 @@ func readCountFileInfo(t *testing.T, localDir string) *countFileInfo {
 }
 
 func doTest(t *testing.T, u *Uploader, doing *Test, known *countFileInfo) int {
-	os.MkdirAll(u.LocalDir, 0777)
+	dbg := filepath.Join(u.LocalDir, "debug")
+	os.MkdirAll(dbg, 0777)
+	if err := LogIfDebug(dbg); err != nil {
+		t.Errorf("debug logging: %v", err)
+	}
 	if len(doing.uploads) > 0 {
 		os.MkdirAll(u.UploadDir, 0777)
 	}
@@ -402,7 +406,7 @@ func doTest(t *testing.T, u *Uploader, doing *Test, known *countFileInfo) int {
 	u.Run()
 
 	// check results
-	var cfiles, rfiles, lfiles, ufiles int
+	var cfiles, rfiles, lfiles, ufiles, logcnt int
 	fis, err := os.ReadDir(u.LocalDir)
 	if err != nil {
 		t.Errorf("%v reading localdir %s", err, u.LocalDir)
@@ -417,10 +421,20 @@ func doTest(t *testing.T, u *Uploader, doing *Test, known *countFileInfo) int {
 			lfiles++
 		case strings.HasSuffix(f.Name(), ".json"):
 			rfiles++
+		case f.Name() == "debug":
+			dbgname := filepath.Join(u.LocalDir, "debug")
+			logs, err := os.ReadDir(dbgname)
+			if err != nil {
+				break
+			}
+			logcnt += len(logs)
 		default:
 			t.Errorf("for %s, unexpected local file %s", doing.name, f.Name())
 		}
 	}
+	if logcnt != 1 {
+		t.Errorf("expected 1 log file, got %d", logcnt)
+	}
 	fis, err = os.ReadDir(u.UploadDir)
 	if err != nil {
 		t.Errorf("%v reading uploaddir %s", err, u.UploadDir)
@@ -439,6 +453,14 @@ func doTest(t *testing.T, u *Uploader, doing *Test, known *countFileInfo) int {
 	if doing.wantUploadeds != ufiles {
 		t.Errorf("%s: got %d uploaded files, wanted %d", doing.name, ufiles, doing.wantUploadeds)
 	}
+	// close all loggers, so Windows can clean up the test
+	for _, lw := range seenlogwriters {
+		if fd, ok := lw.(*os.File); ok {
+			fd.Close()
+		}
+	}
+	// and let the next test start in a clean state
+	seenlogwriters = []io.Writer{}
 	return ufiles - len(doing.uploads)
 }
 

internal/upload/run.go

@@ -5,8 +5,14 @@
 package upload
 
 import (
+	"fmt"
 	"io"
 	"log"
+	"os"
+	"path"
+	"path/filepath"
+	"runtime/debug"
+	"strings"
 	"time"
 
 	"golang.org/x/telemetry"
@@ -19,11 +25,66 @@ func init() {
 	logger = log.New(io.Discard, "", 0)
 }
 
+// keep track of what SetLogOutput has seen
+var seenlogwriters []io.Writer
+
 // SetLogOutput sets the default logger's output destination.
 func SetLogOutput(logging io.Writer) {
-	if logging != nil {
-		logger.SetOutput(logging)
+	if logging == nil {
+		return
+	}
+	logger.SetOutput(logging) // the common case
+	seenlogwriters = append(seenlogwriters, logging)
+	if len(seenlogwriters) > 1 {
+		// The client asked for logging, and there is also a debug dir
+		logger.SetOutput(io.MultiWriter(seenlogwriters...))
+	}
+}
+
+// LogIfDebug arranges to write a log file in the directory
+// dirname, if it exists. If dirname is the empty string,
+// the function tries the directory it.Localdir/debug.
+func LogIfDebug(dirname string) error {
+	dname := filepath.Join(it.LocalDir, "debug")
+	if dirname != "" {
+		dname = dirname
+	}
+	fd, err := os.Stat(dname)
+	if err == os.ErrExist || !fd.IsDir() {
+		// debug doesn't exist or isn't a directory
+		return nil
+	}
+	if err != nil {
+		return err
+	}
+	info, ok := debug.ReadBuildInfo()
+	if !ok {
+		return fmt.Errorf("no build info")
+	}
+	year, month, day := time.Now().UTC().Date()
+	goVers := info.GoVersion
+	// E.g.,  goVers:"go1.22-20240109-RC01 cl/597041403 +dcbe772469 X:loopvar"
+	words := strings.Fields(goVers)
+	goVers = words[0]
+	progPkgPath := info.Path
+	if progPkgPath == "" {
+		progPkgPath = strings.TrimSuffix(filepath.Base(os.Args[0]), ".exe")
+	}
+	prog := path.Base(progPkgPath)
+	progVers := info.Main.Version
+	fname := filepath.Join(dname, fmt.Sprintf("%s-%s-%s-%4d%02d%02d-%d.log",
+		prog, progVers, goVers, year, month, day, os.Getpid()))
+	fname = strings.ReplaceAll(fname, " ", "")
+	if _, err := os.Stat(fname); err == nil {
+		// This process previously called upload.Run
+		return nil
+	}
+	logfd, err := os.Create(fname)
+	if err != nil {
+		return err
 	}
+	SetLogOutput(logfd)
+	return nil
 }
 
 // Uploader carries parameters needed for upload.

upload/upload.go

@@ -17,6 +17,8 @@ func Run(c *Control) {
 	if c != nil && c.Logging != nil {
 		upload.SetLogOutput(c.Logging)
 	}
+	// ignore error: failed logging should not block uploads
+	upload.LogIfDebug("")
 
 	defer func() {
 		if err := recover(); err != nil {