Browse code

Refactor dockerregistry: unify logging style with upstream's codebase

Configure logging the way, upstream does it.

Propagate context where the logging is needed.

Signed-off-by: Michal Minar <miminar@redhat.com>

Michal Minar authored on 2015/12/12 02:44:34
Showing 5 changed files
... ...
@@ -8,8 +8,10 @@ import (
8 8
 	"io/ioutil"
9 9
 	"net/http"
10 10
 	"os"
11
+	"time"
11 12
 
12 13
 	log "github.com/Sirupsen/logrus"
14
+	"github.com/Sirupsen/logrus/formatters/logstash"
13 15
 	"github.com/docker/distribution/configuration"
14 16
 	"github.com/docker/distribution/context"
15 17
 	"github.com/docker/distribution/digest"
... ...
@@ -19,6 +21,7 @@ import (
19 19
 	"github.com/docker/distribution/registry/handlers"
20 20
 	_ "github.com/docker/distribution/registry/storage/driver/filesystem"
21 21
 	_ "github.com/docker/distribution/registry/storage/driver/s3"
22
+	"github.com/docker/distribution/uuid"
22 23
 	"github.com/docker/distribution/version"
23 24
 	gorillahandlers "github.com/gorilla/handlers"
24 25
 	"github.com/openshift/origin/pkg/cmd/server/crypto"
... ...
@@ -32,15 +35,15 @@ func Execute(configFile io.Reader) {
32 32
 		log.Fatalf("Error parsing configuration file: %s", err)
33 33
 	}
34 34
 
35
-	logLevel, err := log.ParseLevel(string(config.Log.Level))
35
+	ctx := context.Background()
36
+	ctx, err = configureLogging(ctx, config)
36 37
 	if err != nil {
37
-		log.Errorf("Error parsing log level %q: %s", config.Log.Level, err)
38
-		logLevel = log.InfoLevel
38
+		log.Fatalf("error configuring logger: %v", err)
39 39
 	}
40
-	log.SetLevel(logLevel)
41
-
42 40
 	log.Infof("version=%s", version.Version)
43
-	ctx := context.Background()
41
+	// inject a logger into the uuid library. warns us if there is a problem
42
+	// with uuid generation under low entropy.
43
+	uuid.Loggerf = context.GetLogger(ctx).Warnf
44 44
 
45 45
 	app := handlers.NewApp(ctx, config)
46 46
 
... ...
@@ -140,6 +143,71 @@ func Execute(configFile io.Reader) {
140 140
 	}
141 141
 }
142 142
 
143
+// configureLogging prepares the context with a logger using the
144
+// configuration.
145
+func configureLogging(ctx context.Context, config *configuration.Configuration) (context.Context, error) {
146
+	if config.Log.Level == "" && config.Log.Formatter == "" {
147
+		// If no config for logging is set, fallback to deprecated "Loglevel".
148
+		log.SetLevel(logLevel(config.Loglevel))
149
+		ctx = context.WithLogger(ctx, context.GetLogger(ctx))
150
+		return ctx, nil
151
+	}
152
+
153
+	log.SetLevel(logLevel(config.Log.Level))
154
+
155
+	formatter := config.Log.Formatter
156
+	if formatter == "" {
157
+		formatter = "text" // default formatter
158
+	}
159
+
160
+	switch formatter {
161
+	case "json":
162
+		log.SetFormatter(&log.JSONFormatter{
163
+			TimestampFormat: time.RFC3339Nano,
164
+		})
165
+	case "text":
166
+		log.SetFormatter(&log.TextFormatter{
167
+			TimestampFormat: time.RFC3339Nano,
168
+		})
169
+	case "logstash":
170
+		log.SetFormatter(&logstash.LogstashFormatter{
171
+			TimestampFormat: time.RFC3339Nano,
172
+		})
173
+	default:
174
+		// just let the library use default on empty string.
175
+		if config.Log.Formatter != "" {
176
+			return ctx, fmt.Errorf("unsupported logging formatter: %q", config.Log.Formatter)
177
+		}
178
+	}
179
+
180
+	if config.Log.Formatter != "" {
181
+		log.Debugf("using %q logging formatter", config.Log.Formatter)
182
+	}
183
+
184
+	if len(config.Log.Fields) > 0 {
185
+		// build up the static fields, if present.
186
+		var fields []interface{}
187
+		for k := range config.Log.Fields {
188
+			fields = append(fields, k)
189
+		}
190
+
191
+		ctx = context.WithValues(ctx, config.Log.Fields)
192
+		ctx = context.WithLogger(ctx, context.GetLogger(ctx, fields...))
193
+	}
194
+
195
+	return ctx, nil
196
+}
197
+
198
+func logLevel(level configuration.Loglevel) log.Level {
199
+	l, err := log.ParseLevel(string(level))
200
+	if err != nil {
201
+		l = log.InfoLevel
202
+		log.Warnf("error parsing level %q: %v, using %q	", level, err, l)
203
+	}
204
+
205
+	return l
206
+}
207
+
143 208
 // alive simply wraps the handler with a route that always returns an http 200
144 209
 // response when the path is matched. If the path is not matched, the request
145 210
 // is passed to the provided handler. There is no guarantee of anything but
... ...
@@ -4,8 +4,8 @@ import (
4 4
 	"fmt"
5 5
 	"net/http"
6 6
 
7
-	"github.com/Sirupsen/logrus"
8 7
 	"github.com/docker/distribution"
8
+	"github.com/docker/distribution/context"
9 9
 	ctxu "github.com/docker/distribution/context"
10 10
 	"github.com/docker/distribution/digest"
11 11
 	"github.com/docker/distribution/registry/api/errcode"
... ...
@@ -163,7 +163,7 @@ func ignoreNotFoundError(ctx *handlers.Context, err error, unknownErrorDetail st
163 163
 				return err
164 164
 			}
165 165
 		}
166
-		logrus.Infof("%T: ignoring %T error: %v", ctx, err, err)
166
+		context.GetLogger(ctx).Infof("%T: ignoring %T error: %v", ctx, err, err)
167 167
 	}
168 168
 
169 169
 	return nil
... ...
@@ -112,7 +112,7 @@ func (ac *AccessController) Authorized(ctx context.Context, accessRecords ...reg
112 112
 		return nil, ac.wrapErr(err)
113 113
 	}
114 114
 
115
-	bearerToken, err := getToken(req)
115
+	bearerToken, err := getToken(ctx, req)
116 116
 	if err != nil {
117 117
 		return nil, ac.wrapErr(err)
118 118
 	}
... ...
@@ -124,7 +124,7 @@ func (ac *AccessController) Authorized(ctx context.Context, accessRecords ...reg
124 124
 
125 125
 	// In case of docker login, hits endpoint /v2
126 126
 	if len(accessRecords) == 0 {
127
-		if err := verifyOpenShiftUser(client); err != nil {
127
+		if err := verifyOpenShiftUser(ctx, client); err != nil {
128 128
 			return nil, ac.wrapErr(err)
129 129
 		}
130 130
 	}
... ...
@@ -134,7 +134,7 @@ func (ac *AccessController) Authorized(ctx context.Context, accessRecords ...reg
134 134
 	// Validate all requested accessRecords
135 135
 	// Only return failure errors from this loop. Success should continue to validate all records
136 136
 	for _, access := range accessRecords {
137
-		log.Debugf("Origin auth: checking for access to %s:%s:%s", access.Resource.Type, access.Resource.Name, access.Action)
137
+		context.GetLogger(ctx).Debugf("Origin auth: checking for access to %s:%s:%s", access.Resource.Type, access.Resource.Name, access.Action)
138 138
 
139 139
 		switch access.Resource.Type {
140 140
 		case "repository":
... ...
@@ -160,12 +160,12 @@ func (ac *AccessController) Authorized(ctx context.Context, accessRecords ...reg
160 160
 				if verifiedPrune {
161 161
 					continue
162 162
 				}
163
-				if err := verifyPruneAccess(client); err != nil {
163
+				if err := verifyPruneAccess(ctx, client); err != nil {
164 164
 					return nil, ac.wrapErr(err)
165 165
 				}
166 166
 				verifiedPrune = true
167 167
 			default:
168
-				if err := verifyImageStreamAccess(imageStreamNS, imageStreamName, verb, client); err != nil {
168
+				if err := verifyImageStreamAccess(ctx, imageStreamNS, imageStreamName, verb, client); err != nil {
169 169
 					return nil, ac.wrapErr(err)
170 170
 				}
171 171
 			}
... ...
@@ -176,7 +176,7 @@ func (ac *AccessController) Authorized(ctx context.Context, accessRecords ...reg
176 176
 				if verifiedPrune {
177 177
 					continue
178 178
 				}
179
-				if err := verifyPruneAccess(client); err != nil {
179
+				if err := verifyPruneAccess(ctx, client); err != nil {
180 180
 					return nil, ac.wrapErr(err)
181 181
 				}
182 182
 				verifiedPrune = true
... ...
@@ -207,7 +207,7 @@ func getNamespaceName(resourceName string) (string, string, error) {
207 207
 	return ns, name, nil
208 208
 }
209 209
 
210
-func getToken(req *http.Request) (string, error) {
210
+func getToken(ctx context.Context, req *http.Request) (string, error) {
211 211
 	authParts := strings.SplitN(req.Header.Get("Authorization"), " ", 2)
212 212
 	if len(authParts) != 2 || strings.ToLower(authParts[0]) != "basic" {
213 213
 		return "", ErrTokenRequired
... ...
@@ -216,7 +216,7 @@ func getToken(req *http.Request) (string, error) {
216 216
 
217 217
 	payload, err := base64.StdEncoding.DecodeString(basicToken)
218 218
 	if err != nil {
219
-		log.Errorf("Basic token decode failed: %s", err)
219
+		context.GetLogger(ctx).Errorf("Basic token decode failed: %s", err)
220 220
 		return "", ErrTokenInvalid
221 221
 	}
222 222
 
... ...
@@ -229,9 +229,9 @@ func getToken(req *http.Request) (string, error) {
229 229
 	return bearerToken, nil
230 230
 }
231 231
 
232
-func verifyOpenShiftUser(client *client.Client) error {
232
+func verifyOpenShiftUser(ctx context.Context, client *client.Client) error {
233 233
 	if _, err := client.Users().Get("~"); err != nil {
234
-		log.Errorf("Get user failed with error: %s", err)
234
+		context.GetLogger(ctx).Errorf("Get user failed with error: %s", err)
235 235
 		if kerrors.IsUnauthorized(err) || kerrors.IsForbidden(err) {
236 236
 			return ErrOpenShiftAccessDenied
237 237
 		}
... ...
@@ -241,7 +241,7 @@ func verifyOpenShiftUser(client *client.Client) error {
241 241
 	return nil
242 242
 }
243 243
 
244
-func verifyImageStreamAccess(namespace, imageRepo, verb string, client *client.Client) error {
244
+func verifyImageStreamAccess(ctx context.Context, namespace, imageRepo, verb string, client *client.Client) error {
245 245
 	sar := authorizationapi.LocalSubjectAccessReview{
246 246
 		Action: authorizationapi.AuthorizationAttributes{
247 247
 			Verb:         verb,
... ...
@@ -252,7 +252,7 @@ func verifyImageStreamAccess(namespace, imageRepo, verb string, client *client.C
252 252
 	response, err := client.LocalSubjectAccessReviews(namespace).Create(&sar)
253 253
 
254 254
 	if err != nil {
255
-		log.Errorf("OpenShift client error: %s", err)
255
+		context.GetLogger(ctx).Errorf("OpenShift client error: %s", err)
256 256
 		if kerrors.IsUnauthorized(err) || kerrors.IsForbidden(err) {
257 257
 			return ErrOpenShiftAccessDenied
258 258
 		}
... ...
@@ -260,14 +260,14 @@ func verifyImageStreamAccess(namespace, imageRepo, verb string, client *client.C
260 260
 	}
261 261
 
262 262
 	if !response.Allowed {
263
-		log.Errorf("OpenShift access denied: %s", response.Reason)
263
+		context.GetLogger(ctx).Errorf("OpenShift access denied: %s", response.Reason)
264 264
 		return ErrOpenShiftAccessDenied
265 265
 	}
266 266
 
267 267
 	return nil
268 268
 }
269 269
 
270
-func verifyPruneAccess(client *client.Client) error {
270
+func verifyPruneAccess(ctx context.Context, client *client.Client) error {
271 271
 	sar := authorizationapi.SubjectAccessReview{
272 272
 		Action: authorizationapi.AuthorizationAttributes{
273 273
 			Verb:     "delete",
... ...
@@ -276,14 +276,14 @@ func verifyPruneAccess(client *client.Client) error {
276 276
 	}
277 277
 	response, err := client.SubjectAccessReviews().Create(&sar)
278 278
 	if err != nil {
279
-		log.Errorf("OpenShift client error: %s", err)
279
+		context.GetLogger(ctx).Errorf("OpenShift client error: %s", err)
280 280
 		if kerrors.IsUnauthorized(err) || kerrors.IsForbidden(err) {
281 281
 			return ErrOpenShiftAccessDenied
282 282
 		}
283 283
 		return err
284 284
 	}
285 285
 	if !response.Allowed {
286
-		log.Errorf("OpenShift access denied: %s", response.Reason)
286
+		context.GetLogger(ctx).Errorf("OpenShift access denied: %s", response.Reason)
287 287
 		return ErrOpenShiftAccessDenied
288 288
 	}
289 289
 	return nil
... ...
@@ -10,11 +10,11 @@ import (
10 10
 	"testing"
11 11
 
12 12
 	"github.com/docker/distribution/registry/auth"
13
-	"golang.org/x/net/context"
14 13
 
15 14
 	kapi "k8s.io/kubernetes/pkg/api"
16 15
 	"k8s.io/kubernetes/pkg/runtime"
17 16
 
17
+	"github.com/docker/distribution/context"
18 18
 	"github.com/openshift/origin/pkg/api/latest"
19 19
 	"github.com/openshift/origin/pkg/authorization/api"
20 20
 	userapi "github.com/openshift/origin/pkg/user/api"
... ...
@@ -58,12 +58,13 @@ func TestVerifyImageStreamAccess(t *testing.T) {
58 58
 		},
59 59
 	}
60 60
 	for _, test := range tests {
61
+		ctx := context.Background()
61 62
 		server, _ := simulateOpenShiftMaster([]response{test.openshiftResponse})
62 63
 		client, err := NewUserOpenShiftClient("magic bearer token")
63 64
 		if err != nil {
64 65
 			t.Fatal(err)
65 66
 		}
66
-		err = verifyImageStreamAccess("foo", "bar", "create", client)
67
+		err = verifyImageStreamAccess(ctx, "foo", "bar", "create", client)
67 68
 		if err == nil || test.expectedError == nil {
68 69
 			if err != test.expectedError {
69 70
 				t.Fatalf("verifyImageStreamAccess did not get expected error - got %s - expected %s", err, test.expectedError)
... ...
@@ -271,7 +272,7 @@ func TestAccessController(t *testing.T) {
271 271
 		if len(test.basicToken) > 0 {
272 272
 			req.Header.Set("Authorization", fmt.Sprintf("Basic %s", test.basicToken))
273 273
 		}
274
-		ctx := context.WithValue(nil, "http.request", req)
274
+		ctx := context.WithValue(context.Background(), "http.request", req)
275 275
 
276 276
 		server, actions := simulateOpenShiftMaster(test.openshiftResponses)
277 277
 		authCtx, err := accessController.Authorized(ctx, test.access...)
... ...
@@ -8,7 +8,6 @@ import (
8 8
 	"os"
9 9
 	"strings"
10 10
 
11
-	log "github.com/Sirupsen/logrus"
12 11
 	"github.com/docker/distribution"
13 12
 	"github.com/docker/distribution/context"
14 13
 	"github.com/docker/distribution/digest"
... ...
@@ -112,13 +111,13 @@ func (r *repository) ExistsByTag(tag string) (bool, error) {
112 112
 // Get retrieves the manifest with digest `dgst`.
113 113
 func (r *repository) Get(dgst digest.Digest) (*schema1.SignedManifest, error) {
114 114
 	if _, err := r.getImageStreamImage(dgst); err != nil {
115
-		log.Errorf("Error retrieving ImageStreamImage %s/%s@%s: %v", r.namespace, r.name, dgst.String(), err)
115
+		context.GetLogger(r.ctx).Errorf("Error retrieving ImageStreamImage %s/%s@%s: %v", r.namespace, r.name, dgst.String(), err)
116 116
 		return nil, err
117 117
 	}
118 118
 
119 119
 	image, err := r.getImage(dgst)
120 120
 	if err != nil {
121
-		log.Errorf("Error retrieving image %s: %v", dgst.String(), err)
121
+		context.GetLogger(r.ctx).Errorf("Error retrieving image %s: %v", dgst.String(), err)
122 122
 		return nil, err
123 123
 	}
124 124
 
... ...
@@ -139,20 +138,20 @@ func (r *repository) GetByTag(tag string, options ...distribution.ManifestServic
139 139
 	}
140 140
 	imageStreamTag, err := r.getImageStreamTag(tag)
141 141
 	if err != nil {
142
-		log.Errorf("Error getting ImageStreamTag %q: %v", tag, err)
142
+		context.GetLogger(r.ctx).Errorf("Error getting ImageStreamTag %q: %v", tag, err)
143 143
 		return nil, err
144 144
 	}
145 145
 	image := &imageStreamTag.Image
146 146
 
147 147
 	dgst, err := digest.ParseDigest(imageStreamTag.Image.Name)
148 148
 	if err != nil {
149
-		log.Errorf("Error parsing digest %q: %v", imageStreamTag.Image.Name, err)
149
+		context.GetLogger(r.ctx).Errorf("Error parsing digest %q: %v", imageStreamTag.Image.Name, err)
150 150
 		return nil, err
151 151
 	}
152 152
 
153 153
 	image, err = r.getImage(dgst)
154 154
 	if err != nil {
155
-		log.Errorf("Error getting image %q: %v", dgst.String(), err)
155
+		context.GetLogger(r.ctx).Errorf("Error getting image %q: %v", dgst.String(), err)
156 156
 		return nil, err
157 157
 	}
158 158
 
... ...
@@ -196,13 +195,13 @@ func (r *repository) Put(manifest *schema1.SignedManifest) error {
196 196
 		// if the error was that the image stream wasn't found, try to auto provision it
197 197
 		statusErr, ok := err.(*kerrors.StatusError)
198 198
 		if !ok {
199
-			log.Errorf("Error creating ImageStreamMapping: %s", err)
199
+			context.GetLogger(r.ctx).Errorf("Error creating ImageStreamMapping: %s", err)
200 200
 			return err
201 201
 		}
202 202
 
203 203
 		status := statusErr.ErrStatus
204 204
 		if status.Code != http.StatusNotFound || status.Details.Kind != "imageStream" || status.Details.Name != r.name {
205
-			log.Errorf("Error creating ImageStreamMapping: %s", err)
205
+			context.GetLogger(r.ctx).Errorf("Error creating ImageStreamMapping: %s", err)
206 206
 			return err
207 207
 		}
208 208
 
... ...
@@ -214,18 +213,18 @@ func (r *repository) Put(manifest *schema1.SignedManifest) error {
214 214
 
215 215
 		client, ok := UserClientFrom(r.ctx)
216 216
 		if !ok {
217
-			log.Errorf("Error creating user client to auto provision image stream: Origin user client unavailable")
217
+			context.GetLogger(r.ctx).Errorf("Error creating user client to auto provision image stream: Origin user client unavailable")
218 218
 			return statusErr
219 219
 		}
220 220
 
221 221
 		if _, err := client.ImageStreams(r.namespace).Create(&stream); err != nil {
222
-			log.Errorf("Error auto provisioning image stream: %s", err)
222
+			context.GetLogger(r.ctx).Errorf("Error auto provisioning image stream: %s", err)
223 223
 			return statusErr
224 224
 		}
225 225
 
226 226
 		// try to create the ISM again
227 227
 		if err := r.registryClient.ImageStreamMappings(r.namespace).Create(&ism); err != nil {
228
-			log.Errorf("Error creating image stream mapping: %s", err)
228
+			context.GetLogger(r.ctx).Errorf("Error creating image stream mapping: %s", err)
229 229
 			return err
230 230
 		}
231 231
 	}
... ...
@@ -238,7 +237,7 @@ func (r *repository) Put(manifest *schema1.SignedManifest) error {
238 238
 
239 239
 	for _, signature := range signatures {
240 240
 		if err := r.Signatures().Put(dgst, signature); err != nil {
241
-			log.Errorf("Error storing signature: %s", err)
241
+			context.GetLogger(r.ctx).Errorf("Error storing signature: %s", err)
242 242
 			return err
243 243
 		}
244 244
 	}