chore: rework logging

cmd/completion/complete.go

@@ -9,25 +9,25 @@ import (
 	"github.com/wot-oss/tmc/internal/repos"
 )
 
-func CompleteRepoNames(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) {
+func CompleteRepoNames(_ *cobra.Command, _ []string, _ string) ([]string, cobra.ShellCompDirective) {
 	config, err := repos.ReadConfig()
 	if err != nil {
 		return nil, cobra.ShellCompDirectiveError
 	}
 
 	var rNames []string
-	for k, _ := range config {
+	for k := range config {
 		rNames = append(rNames, k)
 	}
 
 	return rNames, cobra.ShellCompDirectiveNoFileComp
 }
 
-func CompleteRepoTypes(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) {
+func CompleteRepoTypes(_ *cobra.Command, _ []string, _ string) ([]string, cobra.ShellCompDirective) {
 	return repos.SupportedTypes, cobra.ShellCompDirectiveNoFileComp
 }
 
-func NoCompletionNoFile(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) {
+func NoCompletionNoFile(_ *cobra.Command, _ []string, _ string) ([]string, cobra.ShellCompDirective) {
 	return nil, cobra.ShellCompDirectiveNoFileComp
 }
 
@@ -65,7 +65,7 @@ func getRepo(cmd *cobra.Command) (*repos.Union, error) {
 	}
 	return u, nil
 }
-func CompleteTMNames(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) {
+func CompleteTMNames(cmd *cobra.Command, _ []string, toComplete string) ([]string, cobra.ShellCompDirective) {
 	rs, err := getRepo(cmd)
 	if err != nil {
 		return nil, cobra.ShellCompDirectiveError
@@ -75,7 +75,7 @@ func CompleteTMNames(cmd *cobra.Command, args []string, toComplete string) ([]st
 	return cs, cobra.ShellCompDirectiveNoFileComp | cobra.ShellCompDirectiveNoSpace
 }
 
-func CompleteTMNamesOrIds(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) {
+func CompleteTMNamesOrIds(cmd *cobra.Command, _ []string, toComplete string) ([]string, cobra.ShellCompDirective) {
 	rs, err := getRepo(cmd)
 	if err != nil {
 		return nil, cobra.ShellCompDirectiveError
@@ -85,7 +85,7 @@ func CompleteTMNamesOrIds(cmd *cobra.Command, args []string, toComplete string)
 
 }
 
-func CompleteAttachmentNames(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) {
+func CompleteAttachmentNames(cmd *cobra.Command, _ []string, toComplete string) ([]string, cobra.ShellCompDirective) {
 	rs, err := getRepo(cmd)
 	if err != nil {
 		return nil, cobra.ShellCompDirectiveError

cmd/digest.go

@@ -1,6 +1,7 @@
 package cmd
 
 import (
+	"context"
 	"os"
 
 	"github.com/spf13/cobra"

cmd/index.go

@@ -2,8 +2,6 @@ package cmd
 
 import (
 	"context"
-	"fmt"
-	"log/slog"
 	"os"
 
 	"github.com/spf13/cobra"
@@ -24,11 +22,8 @@ func init() {
 	AddRepoDisambiguatorFlags(indexCmd)
 }
 
-func executeRefreshIndex(cmd *cobra.Command, args []string) {
-	var log = slog.Default()
-
+func executeRefreshIndex(cmd *cobra.Command, _ []string) {
 	spec := RepoSpecFromFlags(cmd)
-	log.Debug(fmt.Sprintf("Refreshing index for repository %s", spec))
 
 	err := cli.Index(context.Background(), spec)
 	if err != nil {

cmd/repo/repo.go

@@ -28,7 +28,7 @@ func init() {
 	repoCmd.AddCommand(repoListCmd)
 }
 
-func repoList(cmd *cobra.Command, args []string) {
+func repoList(_ *cobra.Command, _ []string) {
 	err := cli.RepoList()
 	if err != nil {
 		os.Exit(1)

cmd/repo/repo_add.go

@@ -1,6 +1,7 @@
 package repo
 
 import (
+	"context"
 	"fmt"
 	"os"
 	"strings"
@@ -40,7 +41,7 @@ the config may be a simple string, like directory path or a URL, or a json file.
 
 		descr, _ := cmd.Flags().GetString("description")
 
-		err = cli.RepoAdd(name, typ, confStr, confFile, descr)
+		err = cli.RepoAdd(context.Background(), name, typ, confStr, confFile, descr)
 		if err != nil {
 			_ = cmd.Usage()
 			os.Exit(1)

cmd/repo/repo_set_auth.go

@@ -1,6 +1,7 @@
 package repo
 
 import (
+	"context"
 	"os"
 
 	"github.com/spf13/cobra"
@@ -16,7 +17,7 @@ var repoSetAuthCmd = &cobra.Command{
 	Example: "set-auth http-repo bearer qfdhjf83cblkju",
 	Args:    cobra.ExactArgs(3),
 	Run: func(cmd *cobra.Command, args []string) {
-		err := cli.RepoSetAuth(args[0], args[1], args[2])
+		err := cli.RepoSetAuth(context.Background(), args[0], args[1], args[2])
 		if err != nil {
 			_ = cmd.Usage()
 			os.Exit(1)

cmd/repo/repo_set_config.go

@@ -1,6 +1,7 @@
 package repo
 
 import (
+	"context"
 	"fmt"
 	"os"
 
@@ -38,7 +39,7 @@ the config may be a simple string, like a URL, or a json file.
 
 		descr, _ := cmd.Flags().GetString("description")
 
-		err = cli.RepoSetConfig(name, typ, confStr, confFile, descr)
+		err = cli.RepoSetConfig(context.Background(), name, typ, confStr, confFile, descr)
 		if err != nil {
 			_ = cmd.Usage()
 			os.Exit(1)

cmd/root.go

@@ -49,7 +49,7 @@ func init() {
 	_ = viper.BindPFlag(config.KeyConfigPath, RootCmd.PersistentFlags().Lookup("config"))
 }
 
-func preRunAll(cmd *cobra.Command, args []string) {
+func preRunAll(cmd *cobra.Command, _ []string) {
 	config.ReadInConfig()
 	// set default loglevel depending on subcommand
 	logDefault := cmd != nil && slices.Contains(logEnabledDefaultCmd, cmd.CalledAs())

cmd/validate.go

@@ -1,6 +1,7 @@
 package cmd
 
 import (
+	"context"
 	"os"
 
 	"github.com/spf13/cobra"
@@ -13,7 +14,7 @@ var validateCmd = &cobra.Command{
 	Long:  `Validate a ThingModel to ensure it is ready to be imported into TM catalog`,
 	Args:  cobra.ExactArgs(1),
 	Run: func(cmd *cobra.Command, args []string) {
-		err := cli.ValidateFile(args[0])
+		err := cli.ValidateFile(context.Background(), args[0])
 		if err != nil {
 			os.Exit(1)
 		}

docs/adr/adr003-logging-strategy.md

@@ -0,0 +1,50 @@
+# Logging Strategy
+
+## Status
+
+accepted
+
+## Context
+
+We have not defined a logging strategy and, as a consequence, our code only contains sporadic log statements. The
+produced logs give little help in way of tracking app's behaviour or finding bugs.
+
+When used to serve the REST API, the application needs to produce some king of access/request logs to enable app
+usage analysis and find possible performance bottlenecks.
+
+## Decision
+
+We have two use-cases: CLI and API server, which differ in the requirements to logging.
+
+CLI doesn't need much in terms of logging, only to make sure that any errors are propagated to the user. The logs in
+this case are only useful if they contain some additional data helpful for understanding the reasons for errors, but
+which was deemed too noisy for including in stdout printouts.
+
+In the API server case, it is necessary to distinguish between log statements from different requests. We will generate
+a request id for each request, extend the default logger with fields containing information about request, and pass that
+logger in the request's context down the stack.
+
+### Logging Guidelines
+
+What follows, should be seen as guidelines, rather than hard and fast rules. Feel free to deviate from them if the
+situation warrants.
+
+- Err on the side of not logging, unless you can explain the value-add of a logging statement. It's better to extend
+  logging later when a specific need is determined than pollute logs with noise.
+- Indicate which component is logging. Use any string as a component identifier that helps to pinpoint the location
+  where the log is produced. This is a cheap poor man's replacement for collecting stacktrace information which is good
+  enough most of the time.
+- Log at INFO every http request's start and end
+- Log errors at those points where information may get lost, e.g. if the \[original] error is not propagated up the
+  stack, or if the message printed to stdout does not contain all error details. All errors returned via http will be
+  logged automatically.
+- Log expected normal errors at DEBUG, e.g. user attempted to import a TM conflicting with existing one
+- Log unexpected errors at WARN (e.g. remote tmc repo returned 5**) or ERROR (e.g. index file could not be locked)
+- When logging errors, log any parameters that may have caused the error
+- Log auth events with authorization=true flag
+
+## Consequences
+
+The logs should get more informative and helpful in tracing errors, while remaining relatively concise.
+There will be a number of functions that include `context.Context` in their signature just for access to the logger, as
+opposed to being able to get canceled by the context.

internal/app/cli/copy.go

@@ -65,7 +65,7 @@ func Copy(ctx context.Context, repo model.RepoSpec, toRepo model.RepoSpec, searc
 				}
 			} else {
 				if cErr != nil {
-					cErr = fmt.Errorf("error copying TM %s: %w", version.TMID, cErr)
+					cErr = fmt.Errorf("couldn't copy TM %s: %w", version.TMID, cErr)
 					totalRes = append(totalRes, operationResult{opResultErr, version.TMID, fmt.Sprintf("%v", cErr)})
 					if err == nil {
 						err = cErr
@@ -142,22 +142,24 @@ func copyAttachments(ctx context.Context, spec model.RepoSpec, toRepo repos.Repo
 		resName := fmt.Sprintf("%s/%s", relDir, att.Name)
 		bytes, aErr = commands.AttachmentFetch(ctx, spec, ref, att.Name, false)
 		if aErr != nil {
-			if err == nil {
-				err = aErr
-			}
+			aErr = fmt.Errorf("could not fetch attachment %s to %v: %w", att.Name, ref, aErr)
 			results = append(results, operationResult{
 				typ:        opResultErr,
 				resourceId: resName,
-				text:       fmt.Errorf("could not fetch attachment %s to %v: %w", att.Name, ref, err).Error(),
+				text:       aErr.Error(),
 			})
+			if err == nil {
+				err = aErr
+			}
 			continue
 		}
 		wErr := toRepo.ImportAttachment(ctx, ref, att, bytes, force)
 		if wErr != nil {
+			wErr = fmt.Errorf("could not import attachment %s to %v: %w", att.Name, ref, wErr)
 			results = append(results, operationResult{
 				typ:        opResultErr,
 				resourceId: resName,
-				text:       fmt.Errorf("could not import attachment %s to %v: %w", att.Name, ref, wErr).Error(),
+				text:       wErr.Error(),
 			})
 			doIgnore := ignoreExisting && errors.Is(wErr, repos.ErrAttachmentExists)
 			if err == nil && !doIgnore {
@@ -180,8 +182,8 @@ func copyThingModel(ctx context.Context, version model.FoundVersion, target repo
 		err = errs[0]
 	}
 	if err != nil {
-		Stderrf("Error fetching %s: %v", version.TMID, err)
 		e := fmt.Errorf("cannot fetch %s from repo %s: %w", version.TMID, version.FoundIn, err)
+		Stderrf("Error fetching %s: %v", version.TMID, err)
 		return repos.ImportResultFromError(e)
 	}
 

internal/app/cli/export.go

@@ -110,26 +110,28 @@ func exportAttachments(ctx context.Context, spec model.RepoSpec, outputPath stri
 		finalOutput := filepath.Join(attDir, att.Name)
 		bytes, aErr = commands.AttachmentFetch(ctx, spec, ref, att.Name, false)
 		if aErr != nil {
-			if err == nil {
-				err = aErr
-			}
+			aErr = fmt.Errorf("could not fetch attachment %s to %v: %w", att.Name, ref, aErr)
 			results = append(results, operationResult{
 				typ:        opResultErr,
 				resourceId: resName,
-				text:       fmt.Errorf("could not fetch attachment %s to %v: %w", att.Name, ref, err).Error(),
+				text:       aErr.Error(),
 			})
+			if err == nil {
+				err = aErr
+			}
 			continue
 		}
 		wErr := os.WriteFile(finalOutput, bytes, 0660)
 		if wErr != nil {
-			if err == nil {
-				err = wErr
-			}
+			wErr = fmt.Errorf("could not write attachment %s to %v: %w", att.Name, ref, wErr)
 			results = append(results, operationResult{
 				typ:        opResultErr,
 				resourceId: resName,
-				text:       fmt.Errorf("could not write attachment %s to %v: %w", att.Name, ref, err).Error(),
+				text:       wErr.Error(),
 			})
+			if err == nil {
+				err = wErr
+			}
 			continue
 		}
 		results = append(results, operationResult{

internal/app/cli/import.go

@@ -113,8 +113,9 @@ func (p *ImportExecutor) importDirectory(ctx context.Context, absDirname string,
 func (p *ImportExecutor) importFile(ctx context.Context, filename string, repo repos.Repo, opts repos.ImportOptions) (repos.ImportResult, error) {
 	_, raw, err := utils.ReadRequiredFile(filename)
 	if err != nil {
-		Stderrf("Couldn't read file %s: %v", filename, err)
-		return repos.ImportResultFromError(fmt.Errorf("error importing file %s: %w", filename, err))
+		err := fmt.Errorf("error reading file %s for import: %w", filename, err)
+		Stderrf("%v", err.Error())
+		return repos.ImportResultFromError(err)
 	}
 	res, err := commands.NewImportCommand(p.now).ImportFile(ctx, raw, repo, opts)
 	if err != nil {
@@ -127,6 +128,7 @@ func (p *ImportExecutor) importFile(ctx context.Context, filename string, repo r
 			return res, err
 		}
 		err := fmt.Errorf("error importing file %s: %w", filename, err)
+		Stderrf("%v", err.Error())
 		return repos.ImportResultFromError(err)
 	}
 	switch res.Type {
@@ -141,7 +143,9 @@ func (p *ImportExecutor) importFile(ctx context.Context, filename string, repo r
 	case repos.ImportResultOK:
 		res.Message = fmt.Sprintf("file %s imported as %s", filename, res.TmID)
 	default:
-		return repos.ImportResultFromError(fmt.Errorf("unexpected ImportResult type %v when importing file %s", res.Type, filename))
+		err := fmt.Errorf("unexpected ImportResult type %v when importing file %s", res.Type, filename)
+		Stderrf("%v", err.Error())
+		return repos.ImportResultFromError(err)
 	}
 	return res, err
 }

internal/app/cli/repo.go

@@ -1,6 +1,7 @@
 package cli
 
 import (
+	"context"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -42,14 +43,14 @@ func RepoList() error {
 	return nil
 }
 
-func RepoAdd(name, typ, confStr, confFile, descr string) error {
-	return repoSaveConfig(name, typ, confStr, confFile, descr, repos.Add)
+func RepoAdd(ctx context.Context, name, typ, confStr, confFile, descr string) error {
+	return repoSaveConfig(ctx, name, typ, confStr, confFile, descr, repos.Add)
 }
-func RepoSetConfig(name, typ, confStr, confFile string, descr string) error {
-	return repoSaveConfig(name, typ, confStr, confFile, descr, repos.SetConfig)
+func RepoSetConfig(ctx context.Context, name, typ, confStr, confFile string, descr string) error {
+	return repoSaveConfig(ctx, name, typ, confStr, confFile, descr, repos.SetConfig)
 }
 
-func repoSaveConfig(name, typ, confStr, confFile, descr string, saver func(name string, typ string, confStr string, confFile []byte, descr string) error) error {
+func repoSaveConfig(ctx context.Context, name, typ, confStr, confFile, descr string, saver func(name string, typ string, confStr string, confFile []byte, descr string) error) error {
 	if !repos.ValidRepoNameRegex.MatchString(name) {
 		Stderrf("invalid name: %v", name)
 		return ErrInvalidArgs
@@ -155,7 +156,7 @@ func RepoRename(oldName, newName string) (err error) {
 	return
 }
 
-func RepoSetAuth(name, kind, data string) error {
+func RepoSetAuth(ctx context.Context, name, kind, data string) error {
 	conf, err := repos.ReadConfig()
 	if err != nil {
 		Stderrf("error setting auth: %v", err)