diff --git a/src/api/blob/controller.go b/src/api/blob/controller.go index b688afa80..9ff18ef5d 100644 --- a/src/api/blob/controller.go +++ b/src/api/blob/controller.go @@ -80,14 +80,12 @@ type Controller interface { // NewController creates an instance of the default repository controller func NewController() Controller { return &controller{ - blobMgr: blob.Mgr, - logPrefix: "[controller][blob]", + blobMgr: blob.Mgr, } } type controller struct { - blobMgr blob.Manager - logPrefix string + blobMgr blob.Manager } func (c *controller) AssociateWithArtifact(ctx context.Context, blobDigests []string, artifactDigest string) error { @@ -97,7 +95,7 @@ func (c *controller) AssociateWithArtifact(ctx context.Context, blobDigests []st } if exist { - log.Infof("%s: artifact digest %s already exist, skip to associate blobs with the artifact", c.logPrefix, artifactDigest) + log.G(ctx).Infof("artifact digest %s already exist, skip to associate blobs with the artifact", artifactDigest) return nil } @@ -263,7 +261,7 @@ func (c *controller) Sync(ctx context.Context, references []distribution.Descrip orm.WithTransaction(func(ctx context.Context) error { for _, blob := range updating { if err := c.blobMgr.Update(ctx, blob); err != nil { - log.Warningf("Failed to update blob %s, error: %v", blob.Digest, err) + log.G(ctx).Warningf("Failed to update blob %s, error: %v", blob.Digest, err) return err } } diff --git a/src/api/event/handler/auditlog/auditlog_test.go b/src/api/event/handler/auditlog/auditlog_test.go index c0faae3ce..ff9c25c5c 100644 --- a/src/api/event/handler/auditlog/auditlog_test.go +++ b/src/api/event/handler/auditlog/auditlog_test.go @@ -16,18 +16,17 @@ package auditlog import ( "context" - "github.com/goharbor/harbor/src/api/event/metadata" + "testing" "github.com/goharbor/harbor/src/api/event" + "github.com/goharbor/harbor/src/api/event/metadata" common_dao "github.com/goharbor/harbor/src/common/dao" - "github.com/goharbor/harbor/src/common/utils/log" "github.com/goharbor/harbor/src/pkg/audit/model" "github.com/goharbor/harbor/src/pkg/notifier" ne "github.com/goharbor/harbor/src/pkg/notifier/event" "github.com/goharbor/harbor/src/pkg/q" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/suite" - "testing" ) type MockAuditLogManager struct { @@ -69,7 +68,6 @@ func (suite *AuditLogHandlerTestSuite) SetupSuite() { common_dao.PrepareTestForPostgresSQL() suite.logMgr = &MockAuditLogManager{} suite.auditLogHandler = &Handler{} - log.SetLevel(log.DebugLevel) } func (suite *AuditLogHandlerTestSuite) TestSubscribeTagEvent() { diff --git a/src/api/quota/controller.go b/src/api/quota/controller.go index eaca3a2a2..ac3ec3bec 100644 --- a/src/api/quota/controller.go +++ b/src/api/quota/controller.go @@ -72,14 +72,12 @@ type Controller interface { // NewController creates an instance of the default quota controller func NewController() Controller { return &controller{ - logPrefix: "[controller][quota]", reservedExpiration: defaultReservedExpiration, quotaMgr: quota.Mgr, } } type controller struct { - logPrefix string reservedExpiration time.Duration quotaMgr quota.Manager @@ -163,7 +161,7 @@ func (c *controller) reserveResources(ctx context.Context, reference, referenceI reserved, err := c.getReservedResources(ctx, reference, referenceID) if err != nil { - log.Errorf("failed to get reserved resources for %s %s, error: %v", reference, referenceID, err) + log.G(ctx).Errorf("failed to get reserved resources for %s %s, error: %v", reference, referenceID, err) return err } @@ -175,7 +173,7 @@ func (c *controller) reserveResources(ctx context.Context, reference, referenceI } if err := c.setReservedResources(ctx, reference, referenceID, newReserved); err != nil { - log.Errorf("failed to set reserved resources for %s %s, error: %v", reference, referenceID, err) + log.G(ctx).Errorf("failed to set reserved resources for %s %s, error: %v", reference, referenceID, err) return err } @@ -193,7 +191,7 @@ func (c *controller) unreserveResources(ctx context.Context, reference, referenc reserved, err := c.getReservedResources(ctx, reference, referenceID) if err != nil { - log.Errorf("failed to get reserved resources for %s %s, error: %v", reference, referenceID, err) + log.G(ctx).Errorf("failed to get reserved resources for %s %s, error: %v", reference, referenceID, err) return err } @@ -204,7 +202,7 @@ func (c *controller) unreserveResources(ctx context.Context, reference, referenc } if err := c.setReservedResources(ctx, reference, referenceID, newReserved); err != nil { - log.Errorf("failed to set reserved resources for %s %s, error: %v", reference, referenceID, err) + log.G(ctx).Errorf("failed to set reserved resources for %s %s, error: %v", reference, referenceID, err) return err } @@ -240,7 +238,7 @@ func (c *controller) Refresh(ctx context.Context, reference, referenceID string, newUsed, err := driver.CalculateUsage(ctx, referenceID) if err != nil { - log.Errorf("failed to calculate quota usage for %s %s, error: %v", reference, referenceID, err) + log.G(ctx).Errorf("failed to calculate quota usage for %s %s, error: %v", reference, referenceID, err) return err } @@ -275,7 +273,7 @@ func (c *controller) Request(ctx context.Context, reference, referenceID string, if err := c.unreserveResources(ctx, reference, referenceID, resources); err != nil { // ignore this error because reserved resources will be expired // when no actions on the key of the reserved resources in redis during sometimes - log.Warningf("unreserve resources %s for %s %s failed, error: %v", resources.String(), reference, referenceID, err) + log.G(ctx).Warningf("unreserve resources %s for %s %s failed, error: %v", resources.String(), reference, referenceID, err) } }() diff --git a/src/common/utils/log/context.go b/src/common/utils/log/context.go new file mode 100644 index 000000000..85f7c055d --- /dev/null +++ b/src/common/utils/log/context.go @@ -0,0 +1,45 @@ +// Copyright Project Harbor Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "context" +) + +var ( + // G shortcut to get logger from the context + G = GetLogger + // L the default logger + L = DefaultLogger() +) + +type loggerKey struct{} + +// WithLogger returns a new context with the provided logger. +func WithLogger(ctx context.Context, logger *Logger) context.Context { + return context.WithValue(ctx, loggerKey{}, logger) +} + +// GetLogger retrieves the current logger from the context. +// If no logger is available, the default logger is returned. +func GetLogger(ctx context.Context) *Logger { + logger := ctx.Value(loggerKey{}) + + if logger == nil { + return L + } + + return logger.(*Logger) +} diff --git a/src/common/utils/log/logger.go b/src/common/utils/log/logger.go index 5c8b6b376..2bc2358da 100644 --- a/src/common/utils/log/logger.go +++ b/src/common/utils/log/logger.go @@ -19,6 +19,7 @@ import ( "io" "os" "runtime" + "sort" "strings" "sync" "time" @@ -31,19 +32,22 @@ const srcSeparator = "harbor" + string(os.PathSeparator) + "src" func init() { lvl := os.Getenv("LOG_LEVEL") if len(lvl) == 0 { - logger.SetLevel(InfoLevel) + logger.setLevel(InfoLevel) return } level, err := parseLevel(lvl) if err != nil { - logger.SetLevel(InfoLevel) + logger.setLevel(InfoLevel) return } - logger.SetLevel(level) + logger.setLevel(level) } +// Fields type alias to map[string]interface{} +type Fields = map[string]interface{} + // Logger provides a struct with fields that describe the details of logger. type Logger struct { out io.Writer @@ -51,7 +55,9 @@ type Logger struct { lvl Level callDepth int skipLine bool - mu sync.Mutex + fields map[string]interface{} + fieldsStr string + mu *sync.Mutex // ptr here to share one sync.Mutex for clone method } // New returns a customized Logger @@ -66,11 +72,14 @@ func New(out io.Writer, fmtter Formatter, lvl Level, options ...interface{}) *Lo depth = d } } + return &Logger{ out: out, fmtter: fmtter, lvl: lvl, callDepth: depth, + fields: map[string]interface{}{}, + mu: &sync.Mutex{}, } } @@ -79,45 +88,82 @@ func DefaultLogger() *Logger { return logger } -// SetOutput sets the output of Logger l -func (l *Logger) SetOutput(out io.Writer) { +func (l *Logger) clone() *Logger { + return &Logger{ + out: l.out, + fmtter: l.fmtter, + lvl: l.lvl, + callDepth: l.callDepth, + skipLine: l.skipLine, + fields: l.fields, + fieldsStr: l.fieldsStr, + mu: l.mu, + } +} + +// WithDepth returns cloned logger with new depth +func (l *Logger) WithDepth(depth int) *Logger { + r := l.clone() + r.callDepth = depth + + return r +} + +// WithFields returns cloned logger which fields merged with the new fields +func (l *Logger) WithFields(fields Fields) *Logger { + r := l.clone() + + if len(fields) > 0 { + copyFields := make(map[string]interface{}, len(l.fields)+len(fields)) + for key, value := range l.fields { + copyFields[key] = value + } + for key, value := range fields { + copyFields[key] = value + } + + sortedKeys := make([]string, 0, len(copyFields)) + for key := range copyFields { + sortedKeys = append(sortedKeys, key) + } + sort.Strings(sortedKeys) + + parts := make([]string, 0, len(copyFields)) + for _, key := range sortedKeys { + parts = append(parts, fmt.Sprintf(`%v="%v"`, key, copyFields[key])) + } + + r.fields = copyFields + r.fieldsStr = "[" + strings.Join(parts, " ") + "]" + } + + return r +} + +// setOutput sets the output of Logger l +func (l *Logger) setOutput(out io.Writer) { l.mu.Lock() defer l.mu.Unlock() l.out = out } -// SetFormatter sets the formatter of Logger l -func (l *Logger) SetFormatter(fmtter Formatter) { +// setFormatter sets the formatter of Logger l +func (l *Logger) setFormatter(fmtter Formatter) { l.mu.Lock() defer l.mu.Unlock() l.fmtter = fmtter } -// SetLevel sets the level of Logger l -func (l *Logger) SetLevel(lvl Level) { +// setLevel sets the level of Logger l +func (l *Logger) setLevel(lvl Level) { l.mu.Lock() defer l.mu.Unlock() l.lvl = lvl } -// SetOutput sets the output of default Logger -func SetOutput(out io.Writer) { - logger.SetOutput(out) -} - -// SetFormatter sets the formatter of default Logger -func SetFormatter(fmtter Formatter) { - logger.SetFormatter(fmtter) -} - -// SetLevel sets the level of default Logger -func SetLevel(lvl Level) { - logger.SetLevel(lvl) -} - func (l *Logger) output(record *Record) (err error) { b, err := l.fmtter.Format(record) if err != nil { @@ -215,10 +261,18 @@ func (l *Logger) Fatalf(format string, v ...interface{}) { } func (l *Logger) getLine() string { - if l.skipLine { - return "" + var str string + if !l.skipLine { + str = line(l.callDepth) } - return line(l.callDepth) + + str = str + l.fieldsStr + + if str != "" { + str = str + ":" + } + + return str } // Debug ... @@ -281,5 +335,5 @@ func line(callDepth int) string { if len(l) > 1 { file = l[1] } - return fmt.Sprintf("[%s:%d]:", file, line) + return fmt.Sprintf("[%s:%d]", file, line) } diff --git a/src/common/utils/log/logger_test.go b/src/common/utils/log/logger_test.go index 5dff18a62..50126a9f8 100644 --- a/src/common/utils/log/logger_test.go +++ b/src/common/utils/log/logger_test.go @@ -32,10 +32,10 @@ func contains(t *testing.T, str string, lvl string, line, msg string) bool { func TestSetx(t *testing.T) { logger := New(nil, nil, WarningLevel) - logger.SetOutput(os.Stdout) + logger.setOutput(os.Stdout) fmt := NewTextFormatter() - logger.SetFormatter(fmt) - logger.SetLevel(DebugLevel) + logger.setFormatter(fmt) + logger.setLevel(DebugLevel) if logger.out != os.Stdout { t.Errorf("unexpected outer: %v != %v", logger.out, os.Stdout) @@ -50,6 +50,25 @@ func TestSetx(t *testing.T) { } } +func TestWithFields(t *testing.T) { + buf := enter() + defer exit() + + logger.WithFields(Fields{"action": "create"}).Info(message) + + str := buf.String() + + var ( + expectedLevel = InfoLevel.string() + expectLine = `[action="create"]` + expectMsg = "message" + ) + + if !contains(t, str, expectedLevel, expectLine, expectMsg) { + t.Errorf("unexpected message: %s, expected level: %s, expected line: %s, expected message: %s", str, expectedLevel, expectLine, expectMsg) + } +} + func TestDebug(t *testing.T) { buf := enter() defer exit() @@ -149,7 +168,7 @@ func TestWarningf(t *testing.T) { func TestError(t *testing.T) { var ( expectedLevel = ErrorLevel.string() - expectLine = "logger_test.go:159" + expectLine = "logger_test.go:178" expectMsg = "message" ) @@ -167,7 +186,7 @@ func TestError(t *testing.T) { func TestErrorf(t *testing.T) { var ( expectedLevel = ErrorLevel.string() - expectLine = "logger_test.go:177" + expectLine = "logger_test.go:196" expectMsg = "message" ) @@ -186,11 +205,11 @@ func enter() *bytes.Buffer { b := make([]byte, 0, 32) buf := bytes.NewBuffer(b) - logger.SetOutput(buf) + logger.setOutput(buf) return buf } func exit() { - logger.SetOutput(os.Stdout) + logger.setOutput(os.Stdout) } diff --git a/src/core/middlewares/middlewares.go b/src/core/middlewares/middlewares.go index 8e461200f..c0926e614 100644 --- a/src/core/middlewares/middlewares.go +++ b/src/core/middlewares/middlewares.go @@ -15,9 +15,6 @@ package middlewares import ( - "github.com/goharbor/harbor/src/server/middleware/csrf" - "github.com/goharbor/harbor/src/server/middleware/notification" - "github.com/goharbor/harbor/src/server/middleware/readonly" "net/http" "path" "regexp" @@ -26,7 +23,11 @@ import ( "github.com/astaxie/beego" "github.com/docker/distribution/reference" "github.com/goharbor/harbor/src/server/middleware" + "github.com/goharbor/harbor/src/server/middleware/csrf" + "github.com/goharbor/harbor/src/server/middleware/log" + "github.com/goharbor/harbor/src/server/middleware/notification" "github.com/goharbor/harbor/src/server/middleware/orm" + "github.com/goharbor/harbor/src/server/middleware/readonly" "github.com/goharbor/harbor/src/server/middleware/requestid" "github.com/goharbor/harbor/src/server/middleware/transaction" ) @@ -75,6 +76,7 @@ func MiddleWares() []beego.MiddleWare { return []beego.MiddleWare{ csrf.Middleware(), requestid.Middleware(), + log.Middleware(), readonly.Middleware(readonlySkippers...), orm.Middleware(legacyAPISkipper), // notification must ahead of transaction ensure the DB transaction execution complete diff --git a/src/server/middleware/blob/copy_artifact.go b/src/server/middleware/blob/copy_artifact.go index c54854211..a6600466d 100644 --- a/src/server/middleware/blob/copy_artifact.go +++ b/src/server/middleware/blob/copy_artifact.go @@ -29,7 +29,6 @@ package blob import ( - "fmt" "net/http" "strings" @@ -53,28 +52,27 @@ func CopyArtifactMiddleware() func(http.Handler) http.Handler { return nil } - logPrefix := fmt.Sprintf("[middleware][%s][blob]", r.URL.Path) + ctx := r.Context() + + logger := log.G(ctx).WithFields(log.Fields{"middleware": "blob"}) query := r.URL.Query() - from := query.Get("from") repository, reference, _ := distribution.ParseRef(from) - ctx := r.Context() - art, err := artifactController.GetByReference(ctx, repository, reference, nil) if ierror.IsNotFoundErr(err) { // artifact not found, discontinue the API request return ierror.BadRequestError(nil).WithMessage("artifact %s not found", from) } else if err != nil { - log.Errorf("%s: get artifact %s failed, error: %v", logPrefix, from, err) + logger.Errorf("get artifact %s failed, error: %v", from, err) return err } projectName := util.ParseProjectName(r) project, err := projectController.GetByName(ctx, projectName) if err != nil { - log.Errorf("%s: get project %s failed, error: %v", logPrefix, projectName, err) + logger.Errorf("get project %s failed, error: %v", projectName, err) return err } @@ -89,25 +87,25 @@ func CopyArtifactMiddleware() func(http.Handler) http.Handler { return nil }, nil) if err != nil { - log.Errorf("%s: walk the artifact %s failed, error: %v", logPrefix, art.Digest, err) + logger.Errorf("walk the artifact %s failed, error: %v", art.Digest, err) return err } allBlobs, err := blobController.List(ctx, blob.ListParams{ArtifactDigests: artifactDigests}) if err != nil { - log.Errorf("%s: get blobs for artifacts %s failed, error: %v", logPrefix, strings.Join(artifactDigests, ", "), err) + logger.Errorf("get blobs for artifacts %s failed, error: %v", strings.Join(artifactDigests, ", "), err) return err } blobs, err := blobController.FindMissingAssociationsForProject(ctx, project.ProjectID, allBlobs) if err != nil { - log.Errorf("%s: find missing blobs for project %d failed, error: %v", logPrefix, project.ProjectID, err) + logger.Errorf("find missing blobs for project %d failed, error: %v", project.ProjectID, err) return err } for _, blob := range blobs { if err := blobController.AssociateWithProjectByID(ctx, blob.ID, project.ProjectID); err != nil { - log.Errorf("%s: associate blob %s with project %d failed, error: %v", logPrefix, blob.Digest, project.ProjectID, err) + logger.Errorf("associate blob %s with project %d failed, error: %v", blob.Digest, project.ProjectID, err) return err } } diff --git a/src/server/middleware/blob/post_initiate_blob_upload.go b/src/server/middleware/blob/post_initiate_blob_upload.go index e936ecf4f..a9ad8a601 100644 --- a/src/server/middleware/blob/post_initiate_blob_upload.go +++ b/src/server/middleware/blob/post_initiate_blob_upload.go @@ -15,7 +15,6 @@ package blob import ( - "fmt" "net/http" "github.com/goharbor/harbor/src/common/utils/log" @@ -37,17 +36,18 @@ func PostInitiateBlobUploadMiddleware() func(http.Handler) http.Handler { return nil } - logPrefix := fmt.Sprintf("[middleware][%s][blob]", r.URL.Path) - ctx := r.Context() + + logger := log.G(ctx).WithFields(log.Fields{"middleware": "blob"}) + project, err := projectController.GetByName(ctx, distribution.ParseProjectName(r.URL.Path)) if err != nil { - log.Errorf("%s: get project failed, error: %v", logPrefix, err) + logger.Errorf("get project failed, error: %v", err) return err } if err := blobController.AssociateWithProjectByDigest(ctx, mount, project.ProjectID); err != nil { - log.Errorf("%s: mount blob %s to project %s failed, error: %v", logPrefix, mount, project.Name, err) + logger.Errorf("mount blob %s to project %s failed, error: %v", mount, project.Name, err) return err } diff --git a/src/server/middleware/blob/put_blob_upload.go b/src/server/middleware/blob/put_blob_upload.go index 070cdaaea..ad8826edc 100644 --- a/src/server/middleware/blob/put_blob_upload.go +++ b/src/server/middleware/blob/put_blob_upload.go @@ -15,7 +15,6 @@ package blob import ( - "fmt" "net/http" "strconv" @@ -31,34 +30,34 @@ func PutBlobUploadMiddleware() func(http.Handler) http.Handler { return nil } - logPrefix := fmt.Sprintf("[middleware][%s][blob]", r.URL.Path) + ctx := r.Context() + + logger := log.G(ctx).WithFields(log.Fields{"middleware": "blob"}) size, err := strconv.ParseInt(r.Header.Get("Content-Length"), 10, 64) if err != nil || size == 0 { size, err = blobController.GetAcceptedBlobSize(distribution.ParseSessionID(r.URL.Path)) } if err != nil { - log.Errorf("%s: get blob size failed, error: %v", logPrefix, err) + logger.Errorf("get blob size failed, error: %v", err) return err } - ctx := r.Context() - p, err := projectController.GetByName(ctx, distribution.ParseProjectName(r.URL.Path)) if err != nil { - log.Errorf("%s: get project failed, error: %v", logPrefix, err) + logger.Errorf("get project failed, error: %v", err) return err } digest := w.Header().Get("Docker-Content-Digest") blobID, err := blobController.Ensure(ctx, digest, "application/octet-stream", size) if err != nil { - log.Errorf("%s: ensure blob %s failed, error: %v", logPrefix, digest, err) + logger.Errorf("ensure blob %s failed, error: %v", digest, err) return err } if err := blobController.AssociateWithProjectByID(ctx, blobID, p.ProjectID); err != nil { - log.Errorf("%s: associate blob %s with project %s failed, error: %v", logPrefix, digest, p.Name, err) + logger.Errorf("associate blob %s with project %s failed, error: %v", digest, p.Name, err) return err } diff --git a/src/server/middleware/blob/put_manifest.go b/src/server/middleware/blob/put_manifest.go index e0645ef2a..12292e9bc 100644 --- a/src/server/middleware/blob/put_manifest.go +++ b/src/server/middleware/blob/put_manifest.go @@ -15,7 +15,6 @@ package blob import ( - "fmt" "io/ioutil" "net/http" @@ -39,12 +38,13 @@ func PutManifestMiddleware() func(http.Handler) http.Handler { return nil } - logPrefix := fmt.Sprintf("[middleware][%s][blob]", r.URL.Path) - ctx := r.Context() + + logger := log.G(ctx).WithFields(log.Fields{"middleware": "blob"}) + p, err := projectController.GetByName(ctx, distribution.ParseProjectName(r.URL.Path)) if err != nil { - log.Errorf("%s: get project failed, error: %v", logPrefix, err) + logger.Errorf("get project failed, error: %v", err) return err } @@ -56,13 +56,13 @@ func PutManifestMiddleware() func(http.Handler) http.Handler { contentType := r.Header.Get("Content-Type") manifest, descriptor, err := distribution.UnmarshalManifest(contentType, body) if err != nil { - log.Errorf("%s: unmarshal manifest failed, error: %v", logPrefix, err) + logger.Errorf("unmarshal manifest failed, error: %v", err) return err } // sync blobs if err := blobController.Sync(ctx, manifest.References()); err != nil { - log.Errorf("%s: sync missing blobs from manifest %s failed, error: %c", logPrefix, descriptor.Digest.String(), err) + logger.Errorf("sync missing blobs from manifest %s failed, error: %c", descriptor.Digest.String(), err) return err } @@ -76,12 +76,12 @@ func PutManifestMiddleware() func(http.Handler) http.Handler { // ensure Blob for the manifest blobID, err := blobController.Ensure(ctx, descriptor.Digest.String(), contentType, descriptor.Size) if err != nil { - log.Errorf("%s: ensure blob %s failed, error: %v", logPrefix, descriptor.Digest.String(), err) + logger.Errorf("ensure blob %s failed, error: %v", descriptor.Digest.String(), err) return err } if err := blobController.AssociateWithProjectByID(ctx, blobID, p.ProjectID); err != nil { - log.Errorf("%s: associate manifest with artifact %s failed, error: %v", logPrefix, descriptor.Digest.String(), err) + logger.Errorf("associate manifest with artifact %s failed, error: %v", descriptor.Digest.String(), err) return err } @@ -92,7 +92,7 @@ func PutManifestMiddleware() func(http.Handler) http.Handler { // associate blobs of the manifest with artifact if err := blobController.AssociateWithArtifact(ctx, blobDigests, descriptor.Digest.String()); err != nil { - log.Errorf("%s: associate blobs with artifact %s failed, error: %v", logPrefix, descriptor.Digest.String(), err) + logger.Errorf("associate blobs with artifact %s failed, error: %v", descriptor.Digest.String(), err) return err } diff --git a/src/server/middleware/log/log.go b/src/server/middleware/log/log.go new file mode 100644 index 000000000..9e66e34d1 --- /dev/null +++ b/src/server/middleware/log/log.go @@ -0,0 +1,38 @@ +// Copyright Project Harbor Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "net/http" + + "github.com/goharbor/harbor/src/common/utils/log" + "github.com/goharbor/harbor/src/server/middleware" +) + +// Middleware middleware which add logger to context +func Middleware() func(http.Handler) http.Handler { + return middleware.New(func(w http.ResponseWriter, r *http.Request, next http.Handler) { + rid := r.Header.Get("X-Request-ID") + if rid != "" { + logger := log.G(r.Context()) + logger.Debugf("attach request id %s to the logger for the request %s %s", rid, r.Method, r.URL.Path) + + ctx := log.WithLogger(r.Context(), logger.WithFields(log.Fields{"requestID": rid})) + next.ServeHTTP(w, r.WithContext(ctx)) + } else { + next.ServeHTTP(w, r) + } + }) +} diff --git a/src/server/middleware/log/log_test.go b/src/server/middleware/log/log_test.go new file mode 100644 index 000000000..cb6e9f6da --- /dev/null +++ b/src/server/middleware/log/log_test.go @@ -0,0 +1,65 @@ +// Copyright Project Harbor Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/goharbor/harbor/src/common/utils/log" + "github.com/stretchr/testify/suite" +) + +type MiddlewareTestSuite struct { + suite.Suite +} + +func (suite *MiddlewareTestSuite) TestMiddleware() { + next := func(fields log.Fields) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log.G(r.Context()).WithFields(fields).Info("this is message") + + w.WriteHeader(http.StatusOK) + }) + } + + { + req := httptest.NewRequest("GET", "/v1/library/photon/manifests/2.0", nil) + rr := httptest.NewRecorder() + + Middleware()(next(nil)).ServeHTTP(rr, req) + } + + { + req := httptest.NewRequest("GET", "/v1/library/photon/manifests/2.0", nil) + req.Header.Set("X-Request-ID", "fd6139e6-9092-4181-9220-42d3d48bf658") + rr := httptest.NewRecorder() + + Middleware()(next(nil)).ServeHTTP(rr, req) + } + + { + req := httptest.NewRequest("GET", "/v1/library/photon/manifests/2.0", nil) + req.Header.Set("X-Request-ID", "fd6139e6-9092-4181-9220-42d3d48bf658") + rr := httptest.NewRecorder() + + Middleware()(next(log.Fields{"method": req.Method})).ServeHTTP(rr, req) + } +} + +func TestMiddlewareTestSuite(t *testing.T) { + suite.Run(t, &MiddlewareTestSuite{}) +} diff --git a/src/server/middleware/quota/copy_artifact.go b/src/server/middleware/quota/copy_artifact.go index 0587b9fca..10d0e9672 100644 --- a/src/server/middleware/quota/copy_artifact.go +++ b/src/server/middleware/quota/copy_artifact.go @@ -29,7 +29,6 @@ package quota import ( - "fmt" "net/http" "path" "strconv" @@ -62,20 +61,19 @@ func parseRepositoryName(p string) string { } func copyArtifactResources(r *http.Request, reference, referenceID string) (types.ResourceList, error) { - logPrefix := fmt.Sprintf("[middleware][%s][quota]", r.URL.Path) - query := r.URL.Query() - from := query.Get("from") if from == "" { // miss the from parameter, skip to request the resources return nil, nil } + logger := log.G(r.Context()).WithFields(log.Fields{"middleware": "quota", "action": "request", "url": r.URL.Path}) + repository, reference, err := distribution.ParseRef(from) if err != nil { // bad from parameter, skip to request the resources - log.Errorf("%s: parse from parameter failed, error: %v", logPrefix, err) + logger.Errorf("parse from parameter failed, error: %v", err) return nil, nil } @@ -86,7 +84,7 @@ func copyArtifactResources(r *http.Request, reference, referenceID string) (type // artifact not found, discontinue the API request return nil, ierror.BadRequestError(nil).WithMessage("artifact %s not found", from) } else if err != nil { - log.Errorf("%s: get artifact %s failed, error: %v", logPrefix, from, err) + logger.Errorf("get artifact %s failed, error: %v", from, err) return nil, err } @@ -103,7 +101,7 @@ func copyArtifactResources(r *http.Request, reference, referenceID string) (type return nil }, nil) if err != nil { - log.Errorf("%s: walk the artifact %s failed, error: %v", logPrefix, art.Digest, err) + logger.Errorf("walk the artifact %s failed, error: %v", art.Digest, err) return nil, err } @@ -123,13 +121,13 @@ func copyArtifactResources(r *http.Request, reference, referenceID string) (type allBlobs, err := blobController.List(ctx, blob.ListParams{ArtifactDigests: artifactDigests}) if err != nil { - log.Errorf("%s: get blobs for artifacts %s failed, error: %v", logPrefix, strings.Join(artifactDigests, ", "), err) + logger.Errorf("get blobs for artifacts %s failed, error: %v", strings.Join(artifactDigests, ", "), err) return nil, err } blobs, err := blobController.FindMissingAssociationsForProject(ctx, projectID, allBlobs) if err != nil { - log.Errorf("%s: find missing blobs for project %d failed, error: %v", logPrefix, projectID, err) + logger.Errorf("find missing blobs for project %d failed, error: %v", projectID, err) return nil, err } diff --git a/src/server/middleware/quota/post_initiate_blob_upload.go b/src/server/middleware/quota/post_initiate_blob_upload.go index ec6c208c4..c64ac613c 100644 --- a/src/server/middleware/quota/post_initiate_blob_upload.go +++ b/src/server/middleware/quota/post_initiate_blob_upload.go @@ -15,7 +15,6 @@ package quota import ( - "fmt" "net/http" "strconv" @@ -34,10 +33,7 @@ func PostInitiateBlobUploadMiddleware() func(http.Handler) http.Handler { } func postInitiateBlobUploadResources(r *http.Request, reference, referenceID string) (types.ResourceList, error) { - logPrefix := fmt.Sprintf("[middleware][%s][quota]", r.URL.Path) - query := r.URL.Query() - mount := query.Get("mount") if mount == "" { // it is not mount blob http request, skip to request the resources @@ -46,6 +42,8 @@ func postInitiateBlobUploadResources(r *http.Request, reference, referenceID str ctx := r.Context() + logger := log.G(ctx).WithFields(log.Fields{"middleware": "quota", "action": "request", "url": r.URL.Path}) + blb, err := blobController.Get(ctx, mount) if ierror.IsNotFoundErr(err) { // mount blob not found, skip to request the resources @@ -58,7 +56,7 @@ func postInitiateBlobUploadResources(r *http.Request, reference, referenceID str exist, err := blobController.Exist(ctx, blb.Digest, blob.IsAssociatedWithProject(projectID)) if err != nil { - log.Errorf("%s: checking blob %s is associated with project %d failed, error: %v", logPrefix, blb.Digest, projectID, err) + logger.Errorf("checking blob %s is associated with project %d failed, error: %v", blb.Digest, projectID, err) return nil, err } diff --git a/src/server/middleware/quota/put_blob_upload.go b/src/server/middleware/quota/put_blob_upload.go index 08646462b..ecd3a4b3c 100644 --- a/src/server/middleware/quota/put_blob_upload.go +++ b/src/server/middleware/quota/put_blob_upload.go @@ -15,7 +15,6 @@ package quota import ( - "fmt" "net/http" "strconv" @@ -34,14 +33,14 @@ func PutBlobUploadMiddleware() func(http.Handler) http.Handler { } func putBlobUploadResources(r *http.Request, reference, referenceID string) (types.ResourceList, error) { - logPrefix := fmt.Sprintf("[middleware][%s][quota]", r.URL.Path) + logger := log.G(r.Context()).WithFields(log.Fields{"middleware": "quota", "action": "request", "url": r.URL.Path}) size, err := strconv.ParseInt(r.Header.Get("Content-Length"), 10, 64) if err != nil || size == 0 { size, err = blobController.GetAcceptedBlobSize(distribution.ParseSessionID(r.URL.Path)) } if err != nil { - log.Errorf("%s: get blob size failed, error: %v", logPrefix, err) + logger.Errorf("get blob size failed, error: %v", err) return nil, err } @@ -50,7 +49,7 @@ func putBlobUploadResources(r *http.Request, reference, referenceID string) (typ digest := r.URL.Query().Get("digest") exist, err := blobController.Exist(r.Context(), digest, blob.IsAssociatedWithProject(projectID)) if err != nil { - log.Errorf("%s: checking blob %s is associated with project %d failed, error: %v", logPrefix, digest, projectID, err) + logger.Errorf("checking blob %s is associated with project %d failed, error: %v", digest, projectID, err) return nil, err } diff --git a/src/server/middleware/quota/put_manifest.go b/src/server/middleware/quota/put_manifest.go index 03dd0d26e..a0105b3be 100644 --- a/src/server/middleware/quota/put_manifest.go +++ b/src/server/middleware/quota/put_manifest.go @@ -15,7 +15,6 @@ package quota import ( - "fmt" "io/ioutil" "net/http" "strconv" @@ -51,19 +50,19 @@ var ( ) func putManifestResources(r *http.Request, reference, referenceID string) (types.ResourceList, error) { - logPrefix := fmt.Sprintf("[middleware][%s][quota]", r.URL.Path) + logger := log.G(r.Context()).WithFields(log.Fields{"middleware": "quota", "action": "request", "url": r.URL.Path}) projectID, _ := strconv.ParseInt(referenceID, 10, 64) manifest, descriptor, err := unmarshalManifest(r) if err != nil { - log.Errorf("%s: unmarshal manifest failed, error: %v", logPrefix, err) + logger.Errorf("unmarshal manifest failed, error: %v", err) return nil, err } exist, err := blobController.Exist(r.Context(), descriptor.Digest.String(), blob.IsAssociatedWithProject(projectID)) if err != nil { - log.Errorf("%s: check manifest %s is associated with project failed, error: %v", logPrefix, descriptor.Digest.String(), err) + logger.Errorf("check manifest %s is associated with project failed, error: %v", descriptor.Digest.String(), err) return nil, err } diff --git a/src/server/middleware/quota/quota.go b/src/server/middleware/quota/quota.go index 5329af150..069203e9c 100644 --- a/src/server/middleware/quota/quota.go +++ b/src/server/middleware/quota/quota.go @@ -42,7 +42,7 @@ type RequestConfig struct { // RequestMiddleware middleware which request resources func RequestMiddleware(config RequestConfig, skippers ...middleware.Skipper) func(http.Handler) http.Handler { return middleware.New(func(w http.ResponseWriter, r *http.Request, next http.Handler) { - logPrefix := fmt.Sprintf("[middleware][%s][quota]", r.URL.Path) + logger := log.G(r.Context()).WithFields(log.Fields{"middleware": "quota", "action": "request", "url": r.URL.Path}) if config.ReferenceObject == nil || config.Resources == nil { serror.SendError(w, fmt.Errorf("invald config the for middleware")) @@ -51,7 +51,7 @@ func RequestMiddleware(config RequestConfig, skippers ...middleware.Skipper) fun reference, referenceID, err := config.ReferenceObject(r) if err != nil { - log.Errorf("%s: get reference object failed, error: %v", logPrefix, err) + logger.Errorf("get reference object failed, error: %v", err) serror.SendError(w, err) return @@ -59,21 +59,21 @@ func RequestMiddleware(config RequestConfig, skippers ...middleware.Skipper) fun enabled, err := quotaController.IsEnabled(r.Context(), reference, referenceID) if err != nil { - log.Errorf("%s: check whether quota enabled for %s %s failed, error: %v", logPrefix, reference, referenceID, err) + logger.Errorf("check whether quota enabled for %s %s failed, error: %v", reference, referenceID, err) serror.SendError(w, err) return } if !enabled { // quota is disabled for the reference object, so direct to next handler - log.Infof("%s: quota is disabled for %s %s, so direct to next handler", logPrefix, reference, referenceID) + logger.Infof("quota is disabled for %s %s, so direct to next handler", reference, referenceID) next.ServeHTTP(w, r) return } resources, err := config.Resources(r, reference, referenceID) if err != nil { - log.Errorf("%s: get resources failed, error: %v", logPrefix, err) + logger.Errorf("get resources failed, error: %v", err) serror.SendError(w, err) return @@ -81,7 +81,7 @@ func RequestMiddleware(config RequestConfig, skippers ...middleware.Skipper) fun if len(resources) == 0 { // no resources request for this http request, so direct to next handler - log.Infof("%s: no resources request for this http request, so direct to next handler", logPrefix) + logger.Info("no resources request for this http request, so direct to next handler") next.ServeHTTP(w, r) return } @@ -127,27 +127,27 @@ func RefreshMiddleware(config RefreshConfig, skipers ...middleware.Skipper) func return fmt.Errorf("invald config the for middleware") } - logPrefix := fmt.Sprintf("[middleware][%s][quota]", r.URL.Path) + logger := log.G(r.Context()).WithFields(log.Fields{"middleware": "quota", "action": "refresh", "url": r.URL.Path}) reference, referenceID, err := config.ReferenceObject(r) if err != nil { - log.Errorf("%s: get reference object to refresh quota usage failed, error: %v", logPrefix, err) + logger.Errorf("get reference object to refresh quota usage failed, error: %v", err) return err } enabled, err := quotaController.IsEnabled(r.Context(), reference, referenceID) if err != nil { - log.Errorf("%s: check whether quota enabled for %s %s failed, error: %v", logPrefix, reference, referenceID, err) + logger.Errorf("check whether quota enabled for %s %s failed, error: %v", reference, referenceID, err) return err } if !enabled { - log.Infof("%s: quota is disabled for %s %s, so return directly", logPrefix, reference, referenceID) + logger.Infof("quota is disabled for %s %s, so return directly", reference, referenceID) return nil } if err = quotaController.Refresh(r.Context(), reference, referenceID); err != nil { - log.Errorf("%s: refresh quota for %s %s failed, error: %v", logPrefix, reference, referenceID, err) + logger.Errorf("refresh quota for %s %s failed, error: %v", reference, referenceID, err) return err }