diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index ec08254e..89237d09 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -27,7 +27,7 @@ jobs: strategy: fail-fast: true matrix: - go: [1.16, 1.17, 1.18] + go: [1.17, 1.18, 1.19] run_long_tests: [no] allow_failure: [false] include: @@ -36,7 +36,7 @@ jobs: # - go: master # run_long_tests: no # allow_failure: true - - go: 1.17 + - go: 1.18 run_long_tests: yes allow_failure: false diff --git a/api/api.go b/api/api.go index 3ba51fb1..c15be6e2 100644 --- a/api/api.go +++ b/api/api.go @@ -3,7 +3,6 @@ package api import ( "fmt" - "log" "net/http" "sort" "strconv" @@ -15,6 +14,7 @@ import ( "github.com/aptly-dev/aptly/query" "github.com/aptly-dev/aptly/task" "github.com/gin-gonic/gin" + "github.com/rs/zerolog/log" ) // Lock order acquisition (canonical): @@ -155,7 +155,7 @@ func maybeRunTaskInBackground(c *gin.Context, name string, resources []string, p // Run this task in background if configured globally or per-request background := truthy(c.DefaultQuery("_async", strconv.FormatBool(context.Config().AsyncAPI))) if background { - log.Println("Executing task asynchronously") + log.Info().Msg("Executing task asynchronously") task, conflictErr := runTaskInBackground(name, resources, proc) if conflictErr != nil { AbortWithJSONError(c, 409, conflictErr) @@ -163,7 +163,7 @@ func maybeRunTaskInBackground(c *gin.Context, name string, resources []string, p } c.JSON(202, task) } else { - log.Println("Executing task synchronously") + log.Info().Msg("Executing task synchronously") out := context.Progress() detail := task.Detail{} retValue, err := proc(out, &detail) diff --git a/api/middleware.go b/api/middleware.go index 69f3f6a5..8d18eedb 100644 --- a/api/middleware.go +++ b/api/middleware.go @@ -9,20 +9,36 @@ import ( "github.com/gin-gonic/gin" "github.com/prometheus/client_golang/prometheus" + "github.com/rs/zerolog/log" ) // Only use base path as label value (e.g.: /api/repos) because of time series cardinality // See https://prometheus.io/docs/practices/naming/#labels func getBasePath(c *gin.Context) string { - return fmt.Sprintf("%s%s", getURLSegment(c.Request.URL.Path, 0), getURLSegment(c.Request.URL.Path, 1)) + segment0, err := getURLSegment(c.Request.URL.Path, 0) + if err != nil { + return "/" + } + segment1, err := getURLSegment(c.Request.URL.Path, 1) + if err != nil { + return *segment0 + } + + return *segment0 + *segment1 } -func getURLSegment(url string, idx int) string { - var urlSegments = strings.Split(url, "/") - +func getURLSegment(url string, idx int) (*string, error) { + urlSegments := strings.Split(url, "/") // Remove segment at index 0 because it's an empty string - var segmentAtIndex = urlSegments[1:cap(urlSegments)][idx] - return fmt.Sprintf("/%s", segmentAtIndex) + urlSegments = urlSegments[1:cap(urlSegments)] + + if len(urlSegments) <= idx { + return nil, fmt.Errorf("index %d out of range, only has %d url segments", idx, len(urlSegments)) + } + + segmentAtIndex := urlSegments[idx] + s := fmt.Sprintf("/%s", segmentAtIndex) + return &s, nil } func instrumentHandlerInFlight(g *prometheus.GaugeVec, pathFunc func(*gin.Context) string) func(*gin.Context) { @@ -62,3 +78,39 @@ func instrumentHandlerDuration(obs prometheus.ObserverVec, pathFunc func(*gin.Co obs.WithLabelValues(strconv.Itoa(c.Writer.Status()), c.Request.Method, pathFunc(c)).Observe(time.Since(now).Seconds()) } } + +// JSONLogger is a gin middleware that takes an instance of Logger and uses it for writing access +// logs that include error messages if there are any. +func JSONLogger() gin.HandlerFunc { + return func(c *gin.Context) { + // Start timer + start := time.Now() + path := c.Request.URL.Path + raw := c.Request.URL.RawQuery + + // Process request + c.Next() + + ts := time.Now() + if raw != "" { + path = path + "?" + raw + } + + errorMessage := strings.TrimSuffix(c.Errors.ByType(gin.ErrorTypePrivate).String(), "\n") + l := log.With().Str("remote", c.ClientIP()).Logger(). + With().Str("method", c.Request.Method).Logger(). + With().Str("path", path).Logger(). + With().Str("protocol", c.Request.Proto).Logger(). + With().Str("code", fmt.Sprint(c.Writer.Status())).Logger(). + With().Str("latency", ts.Sub(start).String()).Logger(). + With().Str("agent", c.Request.UserAgent()).Logger() + + if c.Writer.Status() >= 400 && c.Writer.Status() < 500 { + l.Warn().Msg(errorMessage) + } else if c.Writer.Status() >= 500 { + l.Error().Msg(errorMessage) + } else { + l.Info().Msg(errorMessage) + } + } +} diff --git a/api/middleware_test.go b/api/middleware_test.go new file mode 100644 index 00000000..0681785c --- /dev/null +++ b/api/middleware_test.go @@ -0,0 +1,255 @@ +package api + +import ( + "bytes" + "encoding/json" + "fmt" + "io" + "net/http" + "net/http/httptest" + "os" + "sync/atomic" + + "github.com/aptly-dev/aptly/utils" + "github.com/gin-gonic/gin" + . "gopkg.in/check.v1" +) + +type MiddlewareSuite struct { + router http.Handler + context *gin.Context + logReader *os.File + logWriter *os.File +} + +var _ = Suite(&MiddlewareSuite{}) + +func (s *MiddlewareSuite) SetUpTest(c *C) { + r, w, err := os.Pipe() + c.Assert(err, IsNil) + + utils.SetupJSONLogger("debug", w) + mw := JSONLogger() + + router := gin.New() + router.UseRawPath = true + router.Use(mw) + router.Use(gin.Recovery(), gin.ErrorLogger()) + + root := router.Group("/api") + isReady := &atomic.Value{} + isReady.Store(false) + root.GET("/ready", apiReady(isReady)) + root.GET("/healthy", apiHealthy) + + s.router = router + s.logReader = r + s.logWriter = w +} + +func (s *MiddlewareSuite) TearDownTest(c *C) { + s.router = nil + s.context = nil + s.logReader = nil + s.logWriter = nil +} + +func (s *MiddlewareSuite) HTTPRequest(method string, url string, body io.Reader) { + recorder := httptest.NewRecorder() + s.context, _ = gin.CreateTestContext(recorder) + req, _ := http.NewRequestWithContext(s.context, method, url, body) + s.context.Request = req + req.Header.Add("Content-Type", "application/json") + s.router.ServeHTTP(httptest.NewRecorder(), req) +} + +func (s *MiddlewareSuite) TestJSONMiddleware4xx(c *C) { + outC := make(chan string) + go func() { + var buf bytes.Buffer + io.Copy(&buf, s.logReader) + fmt.Println(buf.String()) + outC <- buf.String() + }() + + s.HTTPRequest(http.MethodGet, "/", nil) + s.logWriter.Close() + capturedOutput := <-outC + + var jsonMap map[string]interface{} + json.Unmarshal([]byte(capturedOutput), &jsonMap) + + if val, ok := jsonMap["level"]; ok { + c.Check(val, Equals, "warn") + } else { + c.Errorf("Log message didn't have a 'level' key, obtained %s", capturedOutput) + } + + if val, ok := jsonMap["method"]; ok { + c.Check(val, Equals, "GET") + } else { + c.Errorf("Log message didn't have a 'method' key, obtained %s", capturedOutput) + } + + if val, ok := jsonMap["path"]; ok { + c.Check(val, Equals, "/") + } else { + c.Errorf("Log message didn't have a 'path' key, obtained %s", capturedOutput) + } + + if val, ok := jsonMap["protocol"]; ok { + c.Check(val, Equals, "HTTP/1.1") + } else { + c.Errorf("Log message didn't have a 'protocol' key, obtained %s", capturedOutput) + } + + if val, ok := jsonMap["code"]; ok { + c.Check(val, Equals, "404") + } else { + c.Errorf("Log message didn't have a 'code' key, obtained %s", capturedOutput) + } + + if _, ok := jsonMap["remote"]; !ok { + c.Errorf("Log message didn't have a 'remote' key, obtained %s", capturedOutput) + } + + if _, ok := jsonMap["latency"]; !ok { + c.Errorf("Log message didn't have a 'latency' key, obtained %s", capturedOutput) + } + + if _, ok := jsonMap["agent"]; !ok { + c.Errorf("Log message didn't have a 'agent' key, obtained %s", capturedOutput) + } + + if _, ok := jsonMap["time"]; !ok { + c.Errorf("Log message didn't have a 'time' key, obtained %s", capturedOutput) + } +} + +func (s *MiddlewareSuite) TestJSONMiddleware2xx(c *C) { + outC := make(chan string) + go func() { + var buf bytes.Buffer + io.Copy(&buf, s.logReader) + fmt.Println(buf.String()) + outC <- buf.String() + }() + + s.HTTPRequest(http.MethodGet, "/api/healthy", nil) + s.logWriter.Close() + capturedOutput := <-outC + + var jsonMap map[string]interface{} + json.Unmarshal([]byte(capturedOutput), &jsonMap) + + if val, ok := jsonMap["level"]; ok { + c.Check(val, Equals, "info") + } else { + c.Errorf("Log message didn't have a 'level' key, obtained %s", capturedOutput) + } +} + +func (s *MiddlewareSuite) TestJSONMiddleware5xx(c *C) { + outC := make(chan string) + go func() { + var buf bytes.Buffer + io.Copy(&buf, s.logReader) + fmt.Println(buf.String()) + outC <- buf.String() + }() + + s.HTTPRequest(http.MethodGet, "/api/ready", nil) + s.logWriter.Close() + capturedOutput := <-outC + + var jsonMap map[string]interface{} + json.Unmarshal([]byte(capturedOutput), &jsonMap) + + if val, ok := jsonMap["level"]; ok { + c.Check(val, Equals, "error") + } else { + c.Errorf("Log message didn't have a 'level' key, obtained %s", capturedOutput) + } +} + +func (s *MiddlewareSuite) TestJSONMiddlewareRaw(c *C) { + outC := make(chan string) + go func() { + var buf bytes.Buffer + io.Copy(&buf, s.logReader) + fmt.Println(buf.String()) + outC <- buf.String() + }() + + s.HTTPRequest(http.MethodGet, "/api/healthy?test=raw", nil) + s.logWriter.Close() + capturedOutput := <-outC + + var jsonMap map[string]interface{} + json.Unmarshal([]byte(capturedOutput), &jsonMap) + + fmt.Println(capturedOutput) + + if val, ok := jsonMap["level"]; ok { + c.Check(val, Equals, "info") + } else { + c.Errorf("Log message didn't have a 'level' key, obtained %s", capturedOutput) + } +} + +func (s *MiddlewareSuite) TestGetBasePath(c *C) { + s.HTTPRequest(http.MethodGet, "", nil) + path := getBasePath(s.context) + c.Check(path, Equals, "/") + + s.HTTPRequest(http.MethodGet, "/", nil) + path = getBasePath(s.context) + c.Check(path, Equals, "/") + + s.HTTPRequest(http.MethodGet, "/api", nil) + path = getBasePath(s.context) + c.Check(path, Equals, "/api") + + s.HTTPRequest(http.MethodGet, "/api/repos/testRepo", nil) + path = getBasePath(s.context) + c.Check(path, Equals, "/api/repos") +} + +func (s *MiddlewareSuite) TestGetURLSegment(c *C) { + url := "/" + segment, err := getURLSegment(url, 0) + if err != nil { + c.Error(err) + } + c.Check(*segment, Equals, "/") + + _, err = getURLSegment(url, 1) + if err == nil { + c.Error("Invalid return value") + } + + url = "/api" + segment, err = getURLSegment(url, 0) + if err != nil { + c.Error(err) + } + c.Check(*segment, Equals, "/api") + + _, err = getURLSegment(url, 1) + if err == nil { + c.Error("Invalid return value") + } + + url = "/api/repos/testRepo" + segment, err = getURLSegment(url, 0) + if err != nil { + c.Error(err) + } + c.Check(*segment, Equals, "/api") + + segment, err = getURLSegment(url, 1) + if err != nil { + c.Error(err) + } + c.Check(*segment, Equals, "/repos") +} diff --git a/api/mirror.go b/api/mirror.go index 29f045ed..41bcbe34 100644 --- a/api/mirror.go +++ b/api/mirror.go @@ -2,7 +2,6 @@ package api import ( "fmt" - "log" "net/http" "sort" "strings" @@ -14,6 +13,7 @@ import ( "github.com/aptly-dev/aptly/query" "github.com/aptly-dev/aptly/task" "github.com/gin-gonic/gin" + "github.com/rs/zerolog/log" ) func getVerifier(ignoreSignatures bool, keyRings []string) (pgp.Verifier, error) { @@ -309,7 +309,7 @@ func apiMirrorsUpdate(c *gin.Context) { b.Architectures = remote.Architectures b.Components = remote.Components - log.Printf("%s: Starting mirror update\n", b.Name) + log.Info().Msgf("%s: Starting mirror update\n", b.Name) if c.Bind(&b) != nil { return @@ -458,7 +458,7 @@ func apiMirrorsUpdate(c *gin.Context) { } }() - log.Printf("%s: Spawning background processes...\n", b.Name) + log.Info().Msgf("%s: Spawning background processes...\n", b.Name) var wg sync.WaitGroup for i := 0; i < context.Config().DownloadConcurrency; i++ { wg.Add(1) @@ -505,9 +505,9 @@ func apiMirrorsUpdate(c *gin.Context) { } // Wait for all download goroutines to finish - log.Printf("%s: Waiting for background processes to finish...\n", b.Name) + log.Info().Msgf("%s: Waiting for background processes to finish...\n", b.Name) wg.Wait() - log.Printf("%s: Background processes finished\n", b.Name) + log.Info().Msgf("%s: Background processes finished\n", b.Name) close(taskFinished) for idx := range queue { @@ -539,18 +539,18 @@ func apiMirrorsUpdate(c *gin.Context) { } if len(errors) > 0 { - log.Printf("%s: Unable to update because of previous errors\n", b.Name) + log.Info().Msgf("%s: Unable to update because of previous errors\n", b.Name) return &task.ProcessReturnValue{Code: http.StatusInternalServerError, Value: nil}, fmt.Errorf("unable to update: download errors:\n %s", strings.Join(errors, "\n ")) } - log.Printf("%s: Finalizing download\n", b.Name) + log.Info().Msgf("%s: Finalizing download\n", b.Name) remote.FinalizeDownload(collectionFactory, out) err = collectionFactory.RemoteRepoCollection().Update(remote) if err != nil { return &task.ProcessReturnValue{Code: http.StatusInternalServerError, Value: nil}, fmt.Errorf("unable to update: %s", err) } - log.Printf("%s: Mirror updated successfully!\n", b.Name) + log.Info().Msgf("%s: Mirror updated successfully!\n", b.Name) return &task.ProcessReturnValue{Code: http.StatusNoContent, Value: nil}, nil }) } diff --git a/api/router.go b/api/router.go index 4c577c20..c443445f 100644 --- a/api/router.go +++ b/api/router.go @@ -2,11 +2,14 @@ package api import ( "net/http" + "os" "sync/atomic" ctx "github.com/aptly-dev/aptly/context" + "github.com/aptly-dev/aptly/utils" "github.com/gin-gonic/gin" "github.com/prometheus/client_golang/prometheus/promhttp" + "github.com/rs/zerolog/log" ) var context *ctx.AptlyContext @@ -19,11 +22,23 @@ func apiMetricsGet() gin.HandlerFunc { // Router returns prebuilt with routes http.Handler func Router(c *ctx.AptlyContext) http.Handler { + router := gin.New() context = c - router := gin.Default() router.UseRawPath = true - router.Use(gin.ErrorLogger()) + + if c.Config().LogFormat == "json" { + c.StructuredLogging(true) + utils.SetupJSONLogger(c.Config().LogLevel, os.Stdout) + gin.DefaultWriter = utils.LogWriter{Logger: log.Logger} + router.Use(JSONLogger()) + } else { + c.StructuredLogging(false) + utils.SetupDefaultLogger(c.Config().LogLevel) + router.Use(gin.Logger()) + } + + router.Use(gin.Recovery(), gin.ErrorLogger()) if c.Config().EnableMetricsEndpoint { MetricsCollectorRegistrar.Register(router) diff --git a/console/progress.go b/console/progress.go index 3671fc3a..6f3ba53b 100644 --- a/console/progress.go +++ b/console/progress.go @@ -7,6 +7,7 @@ import ( "github.com/aptly-dev/aptly/aptly" "github.com/cheggaaa/pb" + "github.com/rs/zerolog/log" "github.com/wsxiaoys/terminal/color" ) @@ -34,6 +35,7 @@ type Progress struct { queue chan printTask bar *pb.ProgressBar barShown bool + worker ProgressWorker } // Check interface @@ -42,16 +44,19 @@ var ( ) // NewProgress creates new progress instance -func NewProgress() *Progress { - return &Progress{ +func NewProgress(structuredLogging bool) *Progress { + p := &Progress{ stopped: make(chan bool), queue: make(chan printTask, 100), } + + p.worker = progressWorkerFactroy(structuredLogging, p) + return p } // Start makes progress start its work func (p *Progress) Start() { - go p.worker() + go p.worker.run() } // Shutdown shuts down progress display @@ -173,42 +178,94 @@ func (p *Progress) ColoredPrintf(msg string, a ...interface{}) { } } -func (p *Progress) worker() { +type ProgressWorker interface { + run() +} + +func progressWorkerFactroy(structuredLogging bool, progress *Progress) ProgressWorker { + if structuredLogging { + worker := loggerProgressWorker{progress: progress} + return &worker + } + + worker := standardProgressWorker{progress: progress} + return &worker +} + +type standardProgressWorker struct { + progress *Progress +} + +func (w *standardProgressWorker) run() { hasBar := false for { - task := <-p.queue + task := <-w.progress.queue switch task.code { case codeBarEnabled: hasBar = true case codeBarDisabled: hasBar = false case codePrint: - if p.barShown { + if w.progress.barShown { fmt.Print("\r\033[2K") - p.barShown = false + w.progress.barShown = false } fmt.Print(task.message) case codePrintStdErr: - if p.barShown { + if w.progress.barShown { fmt.Print("\r\033[2K") - p.barShown = false + w.progress.barShown = false } fmt.Fprint(os.Stderr, task.message) case codeProgress: if hasBar { fmt.Print("\r" + task.message) - p.barShown = true + w.progress.barShown = true } case codeHideProgress: - if p.barShown { + if w.progress.barShown { fmt.Print("\r\033[2K") - p.barShown = false + w.progress.barShown = false } case codeFlush: task.reply <- true case codeStop: - p.stopped <- true + w.progress.stopped <- true + return + } + } +} + +type loggerProgressWorker struct { + progress *Progress +} + +func (w *loggerProgressWorker) run() { + hasBar := false + + for { + task := <-w.progress.queue + switch task.code { + case codeBarEnabled: + hasBar = true + case codeBarDisabled: + hasBar = false + case codePrint, codePrintStdErr: + log.Info().Msg(strings.TrimSuffix(task.message, "\n")) + case codeProgress: + if hasBar { + log.Info().Msg(strings.TrimSuffix(task.message, "\n")) + w.progress.barShown = true + } + case codeHideProgress: + if w.progress.barShown { + w.progress.barShown = false + } + case codeFlush: + task.reply <- true + case codeStop: + w.progress.stopped <- true return } } diff --git a/console/progress_test.go b/console/progress_test.go new file mode 100644 index 00000000..2b412eca --- /dev/null +++ b/console/progress_test.go @@ -0,0 +1,24 @@ +package console + +import ( + "fmt" + "testing" + + . "gopkg.in/check.v1" +) + +func Test(t *testing.T) { + TestingT(t) +} + +type ProgressSuite struct {} + +var _ = Suite(&ProgressSuite{}) + +func (s *ProgressSuite) TestNewProgress(c *C) { + p := NewProgress(false) + c.Check(fmt.Sprintf("%T", p.worker), Equals, fmt.Sprintf("%T", &standardProgressWorker{})) + + p = NewProgress(true) + c.Check(fmt.Sprintf("%T", p.worker), Equals, fmt.Sprintf("%T", &loggerProgressWorker{})) +} diff --git a/context/context.go b/context/context.go index d80528a5..a4fef877 100644 --- a/context/context.go +++ b/context/context.go @@ -48,6 +48,7 @@ type AptlyContext struct { publishedStorages map[string]aptly.PublishedStorage dependencyOptions int architecturesList []string + structuredLogging bool // Debug features fileCPUProfile *os.File fileMemProfile *os.File @@ -195,7 +196,7 @@ func (context *AptlyContext) Progress() aptly.Progress { func (context *AptlyContext) _progress() aptly.Progress { if context.progress == nil { - context.progress = console.NewProgress() + context.progress = console.NewProgress(context.structuredLogging) context.progress.Start() } @@ -540,6 +541,11 @@ func (context *AptlyContext) GoContextHandleSignals() { }() } +// StructuredLogging allows to set the structuredLogging flag +func (context *AptlyContext) StructuredLogging(structuredLogging bool) { + context.structuredLogging = structuredLogging +} + // Shutdown shuts context down func (context *AptlyContext) Shutdown() { context.Lock() diff --git a/deb/changes_test.go b/deb/changes_test.go index 64b962b7..b7dc4d95 100644 --- a/deb/changes_test.go +++ b/deb/changes_test.go @@ -45,7 +45,7 @@ func (s *ChangesSuite) SetUpTest(c *C) { s.checksumStorage = files.NewMockChecksumStorage() s.packagePool = files.NewPackagePool(s.Dir, false) - s.progress = console.NewProgress() + s.progress = console.NewProgress(false) s.progress.Start() } diff --git a/deb/remote_test.go b/deb/remote_test.go index 82f6fff8..91e3b224 100644 --- a/deb/remote_test.go +++ b/deb/remote_test.go @@ -91,7 +91,7 @@ func (s *RemoteRepoSuite) SetUpTest(c *C) { s.repo, _ = NewRemoteRepo("yandex", "http://mirror.yandex.ru/debian", "squeeze", []string{"main"}, []string{}, false, false, false) s.flat, _ = NewRemoteRepo("exp42", "http://repos.express42.com/virool/precise/", "./", []string{}, []string{}, false, false, false) s.downloader = http.NewFakeDownloader().ExpectResponse("http://mirror.yandex.ru/debian/dists/squeeze/Release", exampleReleaseFile) - s.progress = console.NewProgress() + s.progress = console.NewProgress(false) s.db, _ = goleveldb.NewOpenDB(c.MkDir()) s.collectionFactory = NewCollectionFactory(s.db) s.packagePool = files.NewPackagePool(c.MkDir(), false) diff --git a/go.mod b/go.mod index c02f6875..17c1f868 100644 --- a/go.mod +++ b/go.mod @@ -18,8 +18,7 @@ require ( github.com/kjk/lzma v0.0.0-20161016003348-3fd93898850d github.com/klauspost/compress v1.13.6 github.com/klauspost/pgzip v1.2.5 - github.com/mattn/go-colorable v0.1.2 // indirect - github.com/mattn/go-isatty v0.0.14 // indirect + github.com/mattn/go-colorable v0.1.13 // indirect github.com/mattn/go-runewidth v0.0.2 // indirect github.com/mattn/go-shellwords v1.0.2 github.com/mkrautz/goar v0.0.0-20150919110319-282caa8bd9da @@ -28,17 +27,19 @@ require ( github.com/pborman/uuid v0.0.0-20180122190007-c65b2f87fee3 github.com/pkg/errors v0.9.1 github.com/prometheus/client_golang v1.12.1 + github.com/rs/zerolog v1.28.0 github.com/smartystreets/gunit v1.0.4 // indirect github.com/smira/commander v0.0.0-20140515201010-f408b00e68d5 github.com/smira/flag v0.0.0-20170926215700-695ea5e84e76 github.com/smira/go-aws-auth v0.0.0-20180731211914-8b73995fd8d1 github.com/smira/go-ftp-protocol v0.0.0-20140829150050-066b75c2b70d github.com/smira/go-xz v0.0.0-20220607140411-c2a07d4bedda + github.com/stretchr/testify v1.8.0 // indirect github.com/syndtr/goleveldb v1.0.1-0.20190923125748-758128399b1d github.com/ugorji/go/codec v1.2.7 github.com/wsxiaoys/terminal v0.0.0-20160513160801-0940f3fc43a0 golang.org/x/crypto v0.0.0-20220331220935-ae2d96664a29 - golang.org/x/sys v0.0.0-20220405052023-b1e9470b6e64 + golang.org/x/sys v0.3.0 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1 golang.org/x/time v0.0.0-20211116232009-f0f3c7e86c11 google.golang.org/protobuf v1.28.0 // indirect diff --git a/go.sum b/go.sum index fe590900..5126213e 100644 --- a/go.sum +++ b/go.sum @@ -78,6 +78,7 @@ github.com/chzyer/readline v0.0.0-20180603132655-2972be24d48e/go.mod h1:nSuG5e5P github.com/chzyer/test v0.0.0-20180213035817-a1ea475d72b1/go.mod h1:Q3SI9o4m/ZMnBNeIyt5eFwwo7qiLfzFZmjNmxjkiQlU= github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDkc90ppPyw= github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGXZJjfX53e64911xZQV5JYwmTeXPW+k8Sc= +github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= @@ -117,6 +118,7 @@ github.com/go-playground/validator/v10 v10.10.1 h1:uA0+amWMiglNZKZ9FJRKUAe9U3RX9 github.com/go-playground/validator/v10 v10.10.1/go.mod h1:i+3WkQ1FvaUjjxh1kSvIA4dMGDBiPU55YFDl0WbKdWU= github.com/go-sql-driver/mysql v1.5.0/go.mod h1:DCzpHaOWr8IXmIStZouvnhqoel9Qv2LBy8hT2VhHyBg= github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY= +github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ= github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q= github.com/golang/groupcache v0.0.0-20190702054246-869f871628b6/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc= @@ -218,14 +220,15 @@ github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= github.com/leodido/go-urn v1.2.0/go.mod h1:+8+nEpDfqqsY+g338gtMEUOtuK+4dEMhiQEgxpxOKII= github.com/leodido/go-urn v1.2.1 h1:BqpAaACuzVSgi/VLzGZIobT2z4v53pjosyNd9Yv6n/w= github.com/leodido/go-urn v1.2.1/go.mod h1:zt4jvISO2HfUBqxjfIshjdMTYS56ZS/qv49ictyFfxY= -github.com/mattn/go-colorable v0.1.2 h1:/bC9yWikZXAL9uJdulbSfyVNIR3n3trXl+v8+1sx8mU= -github.com/mattn/go-colorable v0.1.2/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE= +github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4= +github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= +github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= github.com/mattn/go-ieproxy v0.0.1 h1:qiyop7gCflfhwCzGyeT0gro3sF9AIg9HU98JORTkqfI= github.com/mattn/go-ieproxy v0.0.1/go.mod h1:pYabZ6IHcRpFh7vIaLfK7rdcWgFEb3SFJ6/gNWuh88E= -github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU= -github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y= github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94= +github.com/mattn/go-isatty v0.0.16 h1:bq3VjFmv/sOjHtdEhmkEV4x1AJtvUvOJ2PFAZ5+peKQ= +github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= github.com/mattn/go-runewidth v0.0.2 h1:UnlwIPBGaTZfPQ6T1IGzPI0EkYAQmT9fAEJ/poFC63o= github.com/mattn/go-runewidth v0.0.2/go.mod h1:LwmH8dsx7+W8Uxz3IHJYH5QSwggIsqBzpuz5H//U1FU= github.com/mattn/go-shellwords v1.0.2 h1:5FJ7APbaUYdUTxxP/XXltfy/mICrGqugUEClfnj+D3Y= @@ -287,6 +290,9 @@ github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFR github.com/rogpeppe/go-internal v1.6.1/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc= github.com/rogpeppe/go-internal v1.8.0 h1:FCbCCtXNOY3UtUuHUYaghJg4y7Fd14rXifAYUAtL9R8= github.com/rogpeppe/go-internal v1.8.0/go.mod h1:WmiCO8CzOY8rg0OYDC4/i/2WRWAB6poM+XZ2dLUbcbE= +github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= +github.com/rs/zerolog v1.28.0 h1:MirSo27VyNi7RJYP3078AA1+Cyzd2GB66qy3aUHvsWY= +github.com/rs/zerolog v1.28.0/go.mod h1:NILgTygv/Uej1ra5XxGf82ZFSLk58MFGAUS2o6usyD0= github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo= github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE= github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88= @@ -306,13 +312,16 @@ github.com/smira/go-xz v0.0.0-20220607140411-c2a07d4bedda h1:WWMF6Bz2r8/91uUs4ZY github.com/smira/go-xz v0.0.0-20220607140411-c2a07d4bedda/go.mod h1:RdN8UkuBr4amSnXBHKWkn6p1mXqYjHw+Yvxz8gQfU5A= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA= github.com/stretchr/testify v1.6.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= -github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY= github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk= +github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= github.com/syndtr/goleveldb v1.0.1-0.20190923125748-758128399b1d h1:gZZadD8H+fF+n9CmNhYL1Y0dJB+kLOmKd7FbPJLeGHs= github.com/syndtr/goleveldb v1.0.1-0.20190923125748-758128399b1d/go.mod h1:9OrXJhf154huy1nPWmuSrkgjPUtUNhA+Zmy+6AESzuA= github.com/ugorji/go v1.1.7/go.mod h1:kZn38zHttfInRq0xu/PH0az30d+z6vm202qpg1oXVMw= @@ -426,7 +435,6 @@ golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5h golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20181116152217-5ac8a444bdc5/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= -golang.org/x/sys v0.0.0-20190222072716-a9d3bda3a223/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20190312061237-fead79001313/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= @@ -463,9 +471,11 @@ golang.org/x/sys v0.0.0-20210603081109-ebe580a85c40/go.mod h1:oPkhp1MJrh7nUepCBc golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210806184541-e5e7981a1069/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220114195835-da31bd327af9/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.0.0-20220405052023-b1e9470b6e64 h1:D1v9ucDTYBtbz5vNuBbAhIMAGhQhJ6Ym5ah3maMVNX4= -golang.org/x/sys v0.0.0-20220405052023-b1e9470b6e64/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.3.0 h1:w8ZOecv6NaNa/zC8944JTU3vz4u6Lagfk4RPQxv92NQ= +golang.org/x/sys v0.3.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1 h1:v+OssWQX+hTHEmOBgwxdZxK4zHq3yOs8F9J7mk0PY8E= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.0.0-20170915032832-14c0d48ead0c/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= @@ -627,8 +637,9 @@ gopkg.in/yaml.v2 v2.3.0/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.4.0 h1:D8xgwECY7CYvx+Y2n4sBz93Jn9JRvxdiyyo8CTfuKaY= gopkg.in/yaml.v2 v2.4.0/go.mod h1:RDklbk79AGWmwhnvt/jBztapEOGDOx6ZbXqjP6csGnQ= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= -gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo= gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= honnef.co/go/tools v0.0.0-20190106161140-3f1c8253044a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= honnef.co/go/tools v0.0.0-20190418001031-e561f6794a2a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= diff --git a/http/download_test.go b/http/download_test.go index fb4cce2f..0579ab1d 100644 --- a/http/download_test.go +++ b/http/download_test.go @@ -42,7 +42,7 @@ func (s *DownloaderSuiteBase) SetUpTest(c *C) { close(s.ch) }() - s.progress = console.NewProgress() + s.progress = console.NewProgress(false) s.progress.Start() s.d = NewDownloader(0, 1, s.progress) diff --git a/http/grab_test.go b/http/grab_test.go index 1aca9a60..ca61e5ca 100644 --- a/http/grab_test.go +++ b/http/grab_test.go @@ -41,7 +41,7 @@ func (s *GrabDownloaderSuiteBase) SetUpTest(c *C) { close(s.ch) }() - s.progress = console.NewProgress() + s.progress = console.NewProgress(false) s.progress.Start() s.d = NewGrabDownloader(0, 1, s.progress) diff --git a/system/lib.py b/system/lib.py index 9958b43b..faa34401 100644 --- a/system/lib.py +++ b/system/lib.py @@ -145,6 +145,8 @@ class BaseTest(object): "ppaDistributorID": "ubuntu", "ppaCodename": "", "enableMetricsEndpoint": True, + "logLevel": "debug", + "logFormat": "default" } configOverride = {} environmentOverride = {} diff --git a/system/t02_config/ConfigShowTest_gold b/system/t02_config/ConfigShowTest_gold index 57b42b6a..330a2b6e 100644 --- a/system/t02_config/ConfigShowTest_gold +++ b/system/t02_config/ConfigShowTest_gold @@ -25,5 +25,7 @@ "SwiftPublishEndpoints": {}, "AzurePublishEndpoints": {}, "AsyncAPI": false, - "enableMetricsEndpoint": true + "enableMetricsEndpoint": true, + "logLevel": "debug", + "logFormat": "default" } diff --git a/system/t02_config/CreateConfigTest_gold b/system/t02_config/CreateConfigTest_gold index 7d1a23e1..a943b323 100644 --- a/system/t02_config/CreateConfigTest_gold +++ b/system/t02_config/CreateConfigTest_gold @@ -25,5 +25,7 @@ "SwiftPublishEndpoints": {}, "AzurePublishEndpoints": {}, "AsyncAPI": false, - "enableMetricsEndpoint": false + "enableMetricsEndpoint": false, + "logLevel": "debug", + "logFormat": "default" } \ No newline at end of file diff --git a/utils/config.go b/utils/config.go index e2d2d93e..35479b53 100644 --- a/utils/config.go +++ b/utils/config.go @@ -35,6 +35,8 @@ type ConfigStructure struct { // nolint: maligned AzurePublishRoots map[string]AzurePublishRoot `json:"AzurePublishEndpoints"` AsyncAPI bool `json:"AsyncAPI"` EnableMetricsEndpoint bool `json:"enableMetricsEndpoint"` + LogLevel string `json:"logLevel"` + LogFormat string `json:"logFormat"` } // FileSystemPublishRoot describes single filesystem publishing entry point @@ -112,6 +114,8 @@ var Config = ConfigStructure{ AzurePublishRoots: map[string]AzurePublishRoot{}, AsyncAPI: false, EnableMetricsEndpoint: false, + LogLevel: "debug", + LogFormat: "default", } // LoadConfig loads configuration from json file diff --git a/utils/config_test.go b/utils/config_test.go index 4e10fab7..44ef098e 100644 --- a/utils/config_test.go +++ b/utils/config_test.go @@ -47,6 +47,9 @@ func (s *ConfigSuite) TestSaveConfig(c *C) { s.config.AzurePublishRoots = map[string]AzurePublishRoot{"test": { Container: "repo"}} + s.config.LogLevel = "info" + s.config.LogFormat = "json" + err := SaveConfig(configname, &s.config) c.Assert(err, IsNil) @@ -131,7 +134,9 @@ func (s *ConfigSuite) TestSaveConfig(c *C) { " }\n"+ " },\n"+ " \"AsyncAPI\": false,\n"+ - " \"enableMetricsEndpoint\": false\n"+ + " \"enableMetricsEndpoint\": false,\n"+ + " \"logLevel\": \"info\",\n"+ + " \"logFormat\": \"json\"\n"+ "}") } diff --git a/utils/logging.go b/utils/logging.go new file mode 100644 index 00000000..ae6cf034 --- /dev/null +++ b/utils/logging.go @@ -0,0 +1,68 @@ +package utils + +import ( + "io" + "os" + "strings" + "time" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +type LogWriter struct { + Logger zerolog.Logger +} + +func (lw LogWriter) Write(bs []byte) (int, error) { + return lw.Logger.With().Str("level", "info").Logger().Write(bs) +} + +func SetupJSONLogger(levelStr string, w io.Writer) { + // zerolog.SetGlobalLevel(GetLogLevelOrDebug(levelStr)) + + zerolog.MessageFieldName = "message" + zerolog.LevelFieldName = "level" + // zerolog.TimestampFieldName= "time" + + var tsHook timestampHook + log.Logger = zerolog.New(w). + Hook(&tsHook). + Level(GetLogLevelOrDebug(levelStr)) +} + +func SetupDefaultLogger(levelStr string) { + zerolog.MessageFieldName = "message" + zerolog.LevelFieldName = "level" + + log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}). + Level(GetLogLevelOrDebug(levelStr)). + With(). + Timestamp(). + Logger() +} + +func GetLogLevelOrDebug(levelStr string) zerolog.Level { + levelStr = strings.ToLower(levelStr) + if levelStr == "warning" { + levelStr = "warn" + } + + var level zerolog.Level + + err := level.UnmarshalText([]byte(levelStr)) + if err == nil { + return level + } + + log.Warn().Msgf("Unknown log level '%s', defaulting to debug", levelStr) + return zerolog.DebugLevel +} + +type timestampHook struct{} + +func (h *timestampHook) Run(e *zerolog.Event, l zerolog.Level, msg string) { + t := time.Now() + ts := t.Format(time.RFC3339) + e.Str("time", ts) +}