Improve logging for non-git commands499-log-non-git-commands

Several of our commands only touch the internal API, and go nowhere
near Gitaly. Improve logging for each of these in a single MR. In
general, we want to be able to tell what happened in the execution of
each command, and to track failures down to a specific line of code.

Changelog: added

4 files changed, 37 insertions, 9 deletions

diff --git a/internal/command/personalaccesstoken/personalaccesstoken.go b/internal/command/personalaccesstoken/personalaccesstoken.go
index 6f3d03e..1942ade 100644
--- a/internal/command/personalaccesstoken/personalaccesstoken.go
+++ b/internal/command/personalaccesstoken/personalaccesstoken.go
@@ -8,6 +8,8 @@ import (
 	"strings"
 	"time"
 
+	"gitlab.com/gitlab-org/labkit/log"
+
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
@@ -38,6 +40,10 @@ func (c *Command) Execute(ctx context.Context) error {
 		return err
 	}
 
+	log.WithContextFields(ctx, log.Fields{
+		"token_args": c.TokenArgs,
+	}).Info("personalaccesstoken: execute: requesting token")
+
 	response, err := c.getPersonalAccessToken(ctx)
 	if err != nil {
 		return err
diff --git a/internal/command/shared/customaction/customaction.go b/internal/command/shared/customaction/customaction.go
index 73d2ce4..191ec42 100644
--- a/internal/command/shared/customaction/customaction.go
+++ b/internal/command/shared/customaction/customaction.go
@@ -4,19 +4,17 @@ import (
 	"bytes"
 	"context"
 	"errors"
-
-	"gitlab.com/gitlab-org/gitlab-shell/client"
-
 	"io"
 	"net/http"
 
+	"gitlab.com/gitlab-org/labkit/log"
+
+	"gitlab.com/gitlab-org/gitlab-shell/client"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet/accessverifier"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/pktline"
-
-	"gitlab.com/gitlab-org/labkit/log"
 )
 
 type Request struct {
@@ -59,12 +57,12 @@ func (c *Command) processApiEndpoints(ctx context.Context, response *accessverif
 	request.Data.UserId = response.Who
 
 	for _, endpoint := range data.ApiEndpoints {
-		fields := log.Fields{
+		ctxlog := log.WithContextFields(ctx, log.Fields{
 			"primary_repo": data.PrimaryRepo,
 			"endpoint":     endpoint,
-		}
+		})
 
-		log.WithContextFields(ctx, fields).Info("Performing custom action")
+		ctxlog.Info("customaction: processApiEndpoints: Performing custom action")
 
 		response, err := c.performRequest(ctx, client, endpoint, request)
 		if err != nil {
@@ -90,6 +88,10 @@ func (c *Command) processApiEndpoints(ctx context.Context, response *accessverif
 		} else {
 			output = c.readFromStdinNoEOF()
 		}
+		ctxlog.WithFields(log.Fields{
+			"eof_sent":    c.EOFSent,
+			"stdin_bytes": len(output),
+		}).Debug("customaction: processApiEndpoints: stdin buffered")
 
 		request.Output = output
 	}
diff --git a/internal/command/twofactorrecover/twofactorrecover.go b/internal/command/twofactorrecover/twofactorrecover.go
index f5a700a..91eca3a 100644
--- a/internal/command/twofactorrecover/twofactorrecover.go
+++ b/internal/command/twofactorrecover/twofactorrecover.go
@@ -6,6 +6,8 @@ import (
 	"io"
 	"strings"
 
+	"gitlab.com/gitlab-org/labkit/log"
+
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
@@ -21,9 +23,14 @@ type Command struct {
 }
 
 func (c *Command) Execute(ctx context.Context) error {
+	ctxlog := log.ContextLogger(ctx)
+	ctxlog.Debug("twofactorrecover: execute: Waiting for user input")
+
 	if c.canContinue() {
+		ctxlog.Debug("twofactorrecover: execute: User chose to continue")
 		c.displayRecoveryCodes(ctx)
 	} else {
+		ctxlog.Debug("twofactorrecover: execute: User chose not to continue")
 		fmt.Fprintln(c.ReadWriter.Out, "\nNew recovery codes have *not* been generated. Existing codes will remain valid.")
 	}
 
@@ -43,9 +50,12 @@ func (c *Command) canContinue() bool {
 }
 
 func (c *Command) displayRecoveryCodes(ctx context.Context) {
+	ctxlog := log.ContextLogger(ctx)
+
 	codes, err := c.getRecoveryCodes(ctx)
 
 	if err == nil {
+		ctxlog.Debug("twofactorrecover: displayRecoveryCodes: recovery codes successfully generated")
 		messageWithCodes :=
 			"\nYour two-factor authentication recovery codes are:\n\n" +
 				strings.Join(codes, "\n") +
@@ -54,6 +64,7 @@ func (c *Command) displayRecoveryCodes(ctx context.Context) {
 				"a new device so you do not lose access to your account again.\n"
 		fmt.Fprint(c.ReadWriter.Out, messageWithCodes)
 	} else {
+		ctxlog.WithError(err).Error("twofactorrecover: displayRecoveryCodes: failed to generate recovery codes")
 		fmt.Fprintf(c.ReadWriter.Out, "\nAn error occurred while trying to generate new recovery codes.\n%v\n", err)
 	}
 }
diff --git a/internal/command/twofactorverify/twofactorverify.go b/internal/command/twofactorverify/twofactorverify.go
index b1c5508..fe17339 100644
--- a/internal/command/twofactorverify/twofactorverify.go
+++ b/internal/command/twofactorverify/twofactorverify.go
@@ -5,6 +5,8 @@ import (
 	"fmt"
 	"io"
 
+	"gitlab.com/gitlab-org/labkit/log"
+
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
@@ -18,11 +20,18 @@ type Command struct {
 }
 
 func (c *Command) Execute(ctx context.Context) error {
-	err := c.verifyOTP(ctx, c.getOTP())
+	ctxlog := log.ContextLogger(ctx)
+	ctxlog.Info("twofactorverify: execute: waiting for user input")
+	otp := c.getOTP()
+
+	ctxlog.Info("twofactorverify: execute: verifying entered OTP")
+	err := c.verifyOTP(ctx, otp)
 	if err != nil {
+		ctxlog.WithError(err).Error("twofactorverify: execute: OTP verification failed")
 		return err
 	}
 
+	ctxlog.WithError(err).Info("twofactorverify: execute: OTP verified")
 	return nil
 }