From 7cd076d4f88eda65ad6bf976776f331c2ce960c4 Mon Sep 17 00:00:00 2001 From: "Sascha L. Teichmann" Date: Wed, 27 Sep 2023 11:30:24 +0200 Subject: [PATCH] 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 | 77 ++++++++++++++----------------- cmd/csaf_downloader/downloader.go | 53 +++++++++++---------- cmd/csaf_downloader/forwarder.go | 7 ++- docs/csaf_downloader.md | 5 +- internal/options/log.go | 33 +++++++++++++ internal/options/log_test.go | 49 ++++++++++++++++++++ util/client.go | 20 ++++++-- 7 files changed, 166 insertions(+), 78 deletions(-) create mode 100644 internal/options/log.go create mode 100644 internal/options/log_test.go diff --git a/cmd/csaf_downloader/config.go b/cmd/csaf_downloader/config.go index 8c304b83..0ecdf18d 100644 --- a/cmd/csaf_downloader/config.go +++ b/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) diff --git a/cmd/csaf_downloader/downloader.go b/cmd/csaf_downloader/downloader.go index 1803d9e2..fce53c5b 100644 --- a/cmd/csaf_downloader/downloader.go +++ b/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 { diff --git a/cmd/csaf_downloader/forwarder.go b/cmd/csaf_downloader/forwarder.go index da7ef7e9..3d683b21 100644 --- a/cmd/csaf_downloader/forwarder.go +++ b/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 diff --git a/docs/csaf_downloader.md b/docs/csaf_downloader.md index 122f5b15..7c0c29fa 100644 --- a/docs/csaf_downloader.md +++ b/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 diff --git a/internal/options/log.go b/internal/options/log.go new file mode 100644 index 00000000..c8e828dc --- /dev/null +++ b/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) +// Software-Engineering: 2023 Intevation GmbH + +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 +} diff --git a/internal/options/log_test.go b/internal/options/log_test.go new file mode 100644 index 00000000..6c938651 --- /dev/null +++ b/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) +// Software-Engineering: 2023 Intevation GmbH + +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`) + } +} diff --git a/util/client.go b/util/client.go index 2f54032e..239f8ecf 100644 --- a/util/client.go +++ b/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) }