Upstream/harbor
1
0
Fork 0
mirror of https://github.com/goharbor/harbor.git synced 2024-12-24 17:47:46 +01:00
Code Issues Projects Releases Wiki Activity

feat(log): track request id in the log message (#11095)

Browse Source 
Signed-off-by: He Weiwei <hweiwei@vmware.com>
This commit is contained in:
He Weiwei 2020-03-17 19:29:59 +08:00 committed by GitHub
parent 01ec93856b
commit f8983fe198
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
18 changed files with 331 additions and 123 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
src/api/blob/controller.go
View File

@ -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
}
}

6
src/api/event/handler/auditlog/auditlog_test.go
View File

@ -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() {

14
src/api/quota/controller.go
View File

@ -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)
}
}()

45
src/common/utils/log/context.go Normal file
View File

@ -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)
}

112
src/common/utils/log/logger.go
View File

@ -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)
}

33
src/common/utils/log/logger_test.go
View File

@ -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)
}

8
src/core/middlewares/middlewares.go
View File

@ -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

20
src/server/middleware/blob/copy_artifact.go
View File

@ -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
}
}

10
src/server/middleware/blob/post_initiate_blob_upload.go
View File

@ -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
}

15
src/server/middleware/blob/put_blob_upload.go
View File

@ -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
}

18
src/server/middleware/blob/put_manifest.go
View File

@ -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
}

38
src/server/middleware/log/log.go Normal file
View File

@ -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)
}
})
}

65
src/server/middleware/log/log_test.go Normal file
View File

@ -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{})
}

16
src/server/middleware/quota/copy_artifact.go
View File

@ -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
}

8
src/server/middleware/quota/post_initiate_blob_upload.go
View File

@ -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
}

7
src/server/middleware/quota/put_blob_upload.go
View File

@ -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
}

7
src/server/middleware/quota/put_manifest.go
View File

@ -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
}

22
src/server/middleware/quota/quota.go
View File

@ -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
}