Downloader: Remove verbose flag (#464)

* Remove verbose flag from downloader.

* Do structured http logging in forwarder, too.

* Use structured logging to separate http traffic of downloader from forwarder.

cmd/csaf_downloader/config.go

@@ -12,6 +12,7 @@ import (
 	"crypto/tls"
 	"fmt"
 	"io"
+	"log"
 	"log/slog"
 	"net/http"
 	"os"
@@ -30,7 +31,7 @@ const (
 	defaultForwardQueue   = 5
 	defaultValidationMode = validationStrict
 	defaultLogFile        = "downloader.log"
-	defaultLogLevel       = logLevelInfo
+	defaultLogLevel       = slog.LevelInfo
 )
 
 type validationMode string
@@ -40,15 +41,6 @@ const (
 	validationUnsafe = validationMode("unsafe")
 )
 
-type logLevel string
-
-const (
-	logLevelDebug = logLevel("debug")
-	logLevelInfo  = logLevel("info")
-	logLevelWarn  = logLevel("warn")
-	logLevelError = logLevel("error")
-)
-
 type config struct {
 	Directory            string            `short:"d" long:"directory" description:"DIRectory to store the downloaded files in" value-name:"DIR" toml:"directory"`
 	Insecure             bool              `long:"insecure" description:"Do not check TLS certificates from provider" toml:"insecure"`
@@ -57,7 +49,6 @@ type config struct {
 	ClientKey            *string           `long:"client-key" description:"TLS client private key file (PEM encoded data)" value-name:"KEY-FILE" toml:"client_key"`
 	ClientPassphrase     *string           `long:"client-passphrase" description:"Optional passphrase for the client cert (limited, experimental, see doc)" value-name:"PASSPHRASE" toml:"client_passphrase"`
 	Version              bool              `long:"version" description:"Display version of the binary" toml:"-"`
-	Verbose              bool              `long:"verbose" short:"v" description:"Verbose output" toml:"verbose"`
 	NoStore              bool              `long:"nostore" short:"n" description:"Do not store files" toml:"no_store"`
 	Rate                 *float64          `long:"rate" short:"r" description:"The average upper limit of https operations per second (defaults to unlimited)" toml:"rate"`
 	Worker               int               `long:"worker" short:"w" description:"NUMber of concurrent downloads" value-name:"NUM" toml:"worker"`
@@ -78,9 +69,9 @@ type config struct {
 	ForwardQueue    int         `long:"forwardqueue" description:"Maximal queue LENGTH before forwarder" value-name:"LENGTH" toml:"forward_queue"`
 	ForwardInsecure bool        `long:"forwardinsecure" description:"Do not check TLS certificates from forward endpoint" toml:"forward_insecure"`
 
-	LogFile string `long:"logfile" description:"FILE to log downloading to" value-name:"FILE" toml:"log_file"`
+	LogFile *string `long:"logfile" description:"FILE to log downloading to" value-name:"FILE" toml:"log_file"`
 	//lint:ignore SA5008 We are using choice or than once: debug, info, warn, error
-	LogLevel logLevel `long:"loglevel" description:"LEVEL of logging details" value-name:"LEVEL" choice:"debug" choice:"info" choice:"warn" choice:"error" toml:"log_level"`
+	LogLevel *options.LogLevel `long:"loglevel" description:"LEVEL of logging details" value-name:"LEVEL" choice:"debug" choice:"info" choice:"warn" choice:"error" toml:"log_level"`
 
 	Config string `short:"c" long:"config" description:"Path to config TOML file" value-name:"TOML-FILE" toml:"-"`
 
@@ -97,6 +88,10 @@ var configPaths = []string{
 
 // parseArgsConfig parses the command line and if need a config file.
 func parseArgsConfig() ([]string, *config, error) {
+	var (
+		logFile  = defaultLogFile
+		logLevel = &options.LogLevel{Level: defaultLogLevel}
+	)
 	p := options.Parser[config]{
 		DefaultConfigLocations: configPaths,
 		ConfigLocation:         func(cfg *config) string { return cfg.Config },
@@ -107,8 +102,8 @@ func parseArgsConfig() ([]string, *config, error) {
 			cfg.RemoteValidatorPresets = []string{defaultPreset}
 			cfg.ValidationMode = defaultValidationMode
 			cfg.ForwardQueue = defaultForwardQueue
-			cfg.LogFile = defaultLogFile
-			cfg.LogLevel = defaultLogLevel
+			cfg.LogFile = &logFile
+			cfg.LogLevel = logLevel
 		},
 		// Re-establish default values if not set.
 		EnsureDefaults: func(cfg *config) {
@@ -123,30 +118,35 @@ func parseArgsConfig() ([]string, *config, error) {
 			default:
 				cfg.ValidationMode = validationStrict
 			}
+			if cfg.LogFile == nil {
+				cfg.LogFile = &logFile
+			}
+			if cfg.LogLevel == nil {
+				cfg.LogLevel = logLevel
+			}
 		},
 	}
 	return p.Parse()
 }
 
-// UnmarshalText implements [encoding/text.TextUnmarshaler].
+// UnmarshalText implements [encoding.TextUnmarshaler].
 func (vm *validationMode) UnmarshalText(text []byte) error {
 	switch m := validationMode(text); m {
 	case validationStrict, validationUnsafe:
 		*vm = m
 	default:
-		return fmt.Errorf(`invalid value %q (expected "strict" or "unsafe"`, m)
+		return fmt.Errorf(`invalid value %q (expected "strict" or "unsafe)"`, m)
 	}
 	return nil
 }
 
-// UnmarshalText implements [encoding/text.TextUnmarshaler].
-func (ll *logLevel) UnmarshalText(text []byte) error {
-	switch l := logLevel(text); l {
-	case logLevelDebug, logLevelInfo, logLevelWarn, logLevelError:
-		*ll = l
-	default:
-		return fmt.Errorf(`invalid value %q (expected "debug", "info", "warn", "error")`, l)
+// UnmarshalFlag implements [flags.UnmarshalFlag].
+func (vm *validationMode) UnmarshalFlag(value string) error {
+	var v validationMode
+	if err := v.UnmarshalText([]byte(value)); err != nil {
+		return err
 	}
+	*vm = v
 	return nil
 }
 
@@ -155,20 +155,9 @@ func (cfg *config) ignoreURL(u string) bool {
 	return cfg.ignorePattern.Matches(u)
 }
 
-// slogLevel converts logLevel to [slog.Level].
-func (ll logLevel) slogLevel() slog.Level {
-	switch ll {
-	case logLevelDebug:
-		return slog.LevelDebug
-	case logLevelInfo:
-		return slog.LevelInfo
-	case logLevelWarn:
-		return slog.LevelWarn
-	case logLevelError:
-		return slog.LevelError
-	default:
-		return slog.LevelInfo
-	}
+// verbose is considered a log level equal or less debug.
+func (cfg *config) verbose() bool {
+	return cfg.LogLevel.Level <= slog.LevelDebug
 }
 
 // prepareDirectory ensures that the working directory
@@ -209,26 +198,28 @@ func dropSubSeconds(_ []string, a slog.Attr) slog.Attr {
 // prepareLogging sets up the structured logging.
 func (cfg *config) prepareLogging() error {
 	var w io.Writer
-	if cfg.LogFile == "" {
+	if cfg.LogFile == nil || *cfg.LogFile == "" {
+		log.Println("using STDERR for logging")
 		w = os.Stderr
 	} else {
 		var fname string
 		// We put the log inside the download folder
 		// if it is not absolute.
-		if filepath.IsAbs(cfg.LogFile) {
-			fname = cfg.LogFile
+		if filepath.IsAbs(*cfg.LogFile) {
+			fname = *cfg.LogFile
 		} else {
-			fname = filepath.Join(cfg.Directory, cfg.LogFile)
+			fname = filepath.Join(cfg.Directory, *cfg.LogFile)
 		}
 		f, err := os.OpenFile(fname, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
 		if err != nil {
 			return err
 		}
+		log.Printf("using %q for logging\n", *cfg.LogFile)
 		w = f
 	}
 	ho := slog.HandlerOptions{
 		//AddSource: true,
-		Level:       cfg.LogLevel.slogLevel(),
+		Level:       cfg.LogLevel.Level,
 		ReplaceAttr: dropSubSeconds,
 	}
 	handler := slog.NewJSONHandler(w, &ho)

cmd/csaf_downloader/downloader.go

@@ -108,7 +108,7 @@ func (d *downloader) httpClient() util.Client {
 
 	hClient := http.Client{}
 
-	if d.cfg.LogLevel.slogLevel() <= slog.LevelDebug {
+	if d.cfg.verbose() {
 		hClient.CheckRedirect = logRedirect
 	}
 
@@ -136,8 +136,11 @@ func (d *downloader) httpClient() util.Client {
 	}
 
 	// Add optional URL logging.
-	if d.cfg.Verbose {
-		client = &util.LoggingClient{Client: client}
+	if d.cfg.verbose() {
+		client = &util.LoggingClient{
+			Client: client,
+			Log:    httpLog("downloader"),
+		}
 	}
 
 	// Add optional rate limiting.
@@ -151,6 +154,16 @@ func (d *downloader) httpClient() util.Client {
 	return client
 }
 
+// httpLog does structured logging in a [util.LoggingClient].
+func httpLog(who string) func(string, string) {
+	return func(method, url string) {
+		slog.Debug("http",
+			"who", who,
+			"method", method,
+			"url", url)
+	}
+}
+
 func (d *downloader) download(ctx context.Context, domain string) error {
 	client := d.httpClient()
 
@@ -158,9 +171,9 @@ func (d *downloader) download(ctx context.Context, domain string) error {
 
 	lpmd := loader.Load(domain)
 
-	if d.cfg.Verbose {
+	if d.cfg.verbose() {
 		for i := range lpmd.Messages {
-			slog.Info("Loading provider-metadata.json",
+			slog.Debug("Loading provider-metadata.json",
 				"domain", domain,
 				"message", lpmd.Messages[i].Message)
 		}
@@ -347,7 +360,7 @@ func (d *downloader) logValidationIssues(url string, errors []string, err error)
 		return
 	}
 	if len(errors) > 0 {
-		if d.cfg.Verbose {
+		if d.cfg.verbose() {
 			slog.Error("CSAF file has validation errors",
 				"url", url,
 				"error", strings.Join(errors, ", "))
@@ -404,9 +417,7 @@ nextAdvisory:
 		}
 
 		if d.cfg.ignoreURL(file.URL()) {
-			if d.cfg.Verbose {
-				slog.Warn("Ignoring URL", "url", file.URL())
-			}
+			slog.Debug("Ignoring URL", "url", file.URL())
 			continue
 		}
 
@@ -454,22 +465,18 @@ nextAdvisory:
 
 		// Only hash when we have a remote counter part we can compare it with.
 		if remoteSHA256, s256Data, err = loadHash(client, file.SHA256URL()); err != nil {
-			if d.cfg.Verbose {
-				slog.Warn("Cannot fetch SHA256",
-					"url", file.SHA256URL(),
-					"error", err)
-			}
+			slog.Warn("Cannot fetch SHA256",
+				"url", file.SHA256URL(),
+				"error", err)
 		} else {
 			s256 = sha256.New()
 			writers = append(writers, s256)
 		}
 
 		if remoteSHA512, s512Data, err = loadHash(client, file.SHA512URL()); err != nil {
-			if d.cfg.Verbose {
-				slog.Warn("Cannot fetch SHA512",
-					"url", file.SHA512URL(),
-					"error", err)
-			}
+			slog.Warn("Cannot fetch SHA512",
+				"url", file.SHA512URL(),
+				"error", err)
 		} else {
 			s512 = sha512.New()
 			writers = append(writers, s512)
@@ -522,11 +529,9 @@ nextAdvisory:
 			var sign *crypto.PGPSignature
 			sign, signData, err = loadSignature(client, file.SignURL())
 			if err != nil {
-				if d.cfg.Verbose {
-					slog.Warn("Downloading signature failed",
-						"url", file.SignURL(),
-						"error", err)
-				}
+				slog.Warn("Downloading signature failed",
+					"url", file.SignURL(),
+					"error", err)
 			}
 			if sign != nil {
 				if err := d.checkSignature(data.Bytes(), sign); err != nil {

cmd/csaf_downloader/forwarder.go

@@ -116,8 +116,11 @@ func (f *forwarder) httpClient() util.Client {
 	}
 
 	// Add optional URL logging.
-	if f.cfg.Verbose {
-		client = &util.LoggingClient{Client: client}
+	if f.cfg.verbose() {
+		client = &util.LoggingClient{
+			Client: client,
+			Log:    httpLog("forwarder"),
+		}
 	}
 
 	f.client = client

docs/csaf_downloader.md

@@ -14,10 +14,8 @@ Application Options:
       --client-key=KEY-FILE                      TLS client private key file (PEM encoded data)
       --client-passphrase=PASSPHRASE             Optional passphrase for the client cert (limited, experimental, see doc)
       --version                                  Display version of the binary
-  -v, --verbose                                  Verbose output
   -n, --nostore                                  Do not store files
-  -r, --rate=                                    The average upper limit of https operations per second (defaults to
-                                                 unlimited)
+  -r, --rate=                                    The average upper limit of https operations per second (defaults to unlimited)
   -w, --worker=NUM                               NUMber of concurrent downloads (default: 2)
   -t, --timerange=RANGE                          RANGE of time from which advisories to download
   -f, --folder=FOLDER                            Download into a given subFOLDER
@@ -65,7 +63,6 @@ insecure            = false
 # client_key        # not set by default
 # client_passphrase # not set by default
 ignoresigcheck      = false
-verbose             = false
 # rate              # set to unlimited
 worker              = 2
 # timerange         # not set by default

internal/options/log.go

@@ -0,0 +1,33 @@
+// This file is Free Software under the MIT License
+// without warranty, see README.md and LICENSES/MIT.txt for details.
+//
+// SPDX-License-Identifier: MIT
+//
+// SPDX-FileCopyrightText: 2023 German Federal Office for Information Security (BSI) <https://www.bsi.bund.de>
+// Software-Engineering: 2023 Intevation GmbH <https://intevation.de>
+
+package options
+
+import (
+	"log/slog"
+	"strings"
+)
+
+// LogLevel implements a helper type to be used in configurations.
+type LogLevel struct{ slog.Level }
+
+// MarshalFlag implements [flags.Marshaler].
+func (ll LogLevel) MarshalFlag() (string, error) {
+	t, err := ll.MarshalText()
+	return strings.ToLower(string(t)), err
+}
+
+// UnmarshalFlag implements [flags.Unmarshaler].
+func (ll *LogLevel) UnmarshalFlag(value string) error {
+	var l slog.Level
+	if err := l.UnmarshalText([]byte(value)); err != nil {
+		return err
+	}
+	*ll = LogLevel{Level: l}
+	return nil
+}

internal/options/log_test.go

@@ -0,0 +1,49 @@
+// This file is Free Software under the MIT License
+// without warranty, see README.md and LICENSES/MIT.txt for details.
+//
+// SPDX-License-Identifier: MIT
+//
+// SPDX-FileCopyrightText: 2023 German Federal Office for Information Security (BSI) <https://www.bsi.bund.de>
+// Software-Engineering: 2023 Intevation GmbH <https://intevation.de>
+
+package options
+
+import (
+	"log/slog"
+	"testing"
+)
+
+func TestMarshalFlag(t *testing.T) {
+	ll := LogLevel{Level: slog.LevelInfo}
+	got, err := ll.MarshalFlag()
+	if err != nil {
+		t.Fatal(err)
+	}
+	if got != "info" {
+		t.Fatalf("got %q expected \"info\"", got)
+	}
+}
+
+func TestUnmarshalFlag(t *testing.T) {
+	for _, x := range []struct {
+		input  string
+		expect slog.Level
+	}{
+		{input: "debug", expect: slog.LevelDebug},
+		{input: "info", expect: slog.LevelInfo},
+		{input: "warn", expect: slog.LevelWarn},
+		{input: "error", expect: slog.LevelError},
+	} {
+		var ll LogLevel
+		if err := ll.UnmarshalFlag(x.input); err != nil {
+			t.Fatalf("%q error: %v", x.input, err)
+		}
+		if ll.Level != x.expect {
+			t.Fatalf("%q: got %s expected %s", x.input, ll.Level, x.expect)
+		}
+	}
+	var ll LogLevel
+	if err := ll.UnmarshalFlag("invalid"); err == nil {
+		t.Fatal(`"invalid" should return an error`)
+	}
+}

util/client.go

@@ -31,6 +31,7 @@ type Client interface {
 // LoggingClient is a client that logs called URLs.
 type LoggingClient struct {
 	Client
+	Log func(method, url string)
 }
 
 // LimitingClient is a Client implementing rate throttling.
@@ -97,33 +98,42 @@ func (hc *HeaderClient) PostForm(url string, data url.Values) (*http.Response, e
 		url, "application/x-www-form-urlencoded", strings.NewReader(data.Encode()))
 }
 
+// log logs to a callback if given.
+func (lc *LoggingClient) log(method, url string) {
+	if lc.Log != nil {
+		lc.Log(method, url)
+	} else {
+		log.Printf("[%s]: %s\n", method, url)
+	}
+}
+
 // Do implements the respective method of the Client interface.
 func (lc *LoggingClient) Do(req *http.Request) (*http.Response, error) {
-	log.Printf("[DO]: %s\n", req.URL.String())
+	lc.log("DO", req.URL.String())
 	return lc.Client.Do(req)
 }
 
 // Get implements the respective method of the Client interface.
 func (lc *LoggingClient) Get(url string) (*http.Response, error) {
-	log.Printf("[GET]: %s\n", url)
+	lc.log("GET", url)
 	return lc.Client.Get(url)
 }
 
 // Head implements the respective method of the Client interface.
 func (lc *LoggingClient) Head(url string) (*http.Response, error) {
-	log.Printf("[HEAD]: %s\n", url)
+	lc.log("HEAD", url)
 	return lc.Client.Head(url)
 }
 
 // Post implements the respective method of the Client interface.
 func (lc *LoggingClient) Post(url, contentType string, body io.Reader) (*http.Response, error) {
-	log.Printf("[POST]: %s\n", url)
+	lc.log("POST", url)
 	return lc.Client.Post(url, contentType, body)
 }
 
 // PostForm implements the respective method of the Client interface.
 func (lc *LoggingClient) PostForm(url string, data url.Values) (*http.Response, error) {
-	log.Printf("[POST FORM]: %s\n", url)
+	lc.log("POST FORM", url)
 	return lc.Client.PostForm(url, data)
 }