s3: log each request at -v=2 (#10931)

* s3: log each request at -v=2

* s3: quote requester and path in the access log line

* s3: record the post-policy signing identity as the requester

weed/s3api/auth_signature_v2.go

@@ -68,11 +68,11 @@ func (iam *IdentityAccessManagement) isReqAuthenticatedV2(r *http.Request) (*Ide
 	return iam.doesPresignV2SignatureMatch(r)
 }
 
-func (iam *IdentityAccessManagement) doesPolicySignatureV2Match(formValues http.Header) s3err.ErrorCode {
+func (iam *IdentityAccessManagement) doesPolicySignatureV2Match(formValues http.Header) (*Identity, s3err.ErrorCode) {
 
 	accessKey := formValues.Get("AWSAccessKeyId")
 	if accessKey == "" {
-		return s3err.ErrMissingFields
+		return nil, s3err.ErrMissingFields
 	}
 
 	identity, cred, found := iam.lookupByAccessKey(accessKey)
@@ -85,35 +85,35 @@ func (iam *IdentityAccessManagement) doesPolicySignatureV2Match(formValues http.
 		glog.Warningf("InvalidAccessKeyId (V2 POST): attempted key '%s' not found. Available keys: %d, Auth enabled: %v",
 			accessKey, availableKeyCount, iam.isAuthEnabled)
 
-		return s3err.ErrInvalidAccessKeyID
+		return nil, s3err.ErrInvalidAccessKeyID
 	}
 
 	// Check service account expiration
 	if cred.isCredentialExpired() {
 		glog.V(2).Infof("Service account credential %s has expired (expiration: %d, now: %d)",
 			accessKey, cred.Expiration, time.Now().Unix())
-		return s3err.ErrAccessDenied
+		return nil, s3err.ErrAccessDenied
 	}
 
 	bucket := formValues.Get("bucket")
 	if !identity.CanDo(s3_constants.ACTION_WRITE, bucket, "") {
-		return s3err.ErrAccessDenied
+		return nil, s3err.ErrAccessDenied
 	}
 
 	policy := formValues.Get("Policy")
 	if policy == "" {
-		return s3err.ErrMissingFields
+		return nil, s3err.ErrMissingFields
 	}
 
 	signature := formValues.Get("Signature")
 	if signature == "" {
-		return s3err.ErrMissingFields
+		return nil, s3err.ErrMissingFields
 	}
 
 	if !compareSignatureV2(signature, calculateSignatureV2(policy, cred.SecretKey)) {
-		return s3err.ErrSignatureDoesNotMatch
+		return nil, s3err.ErrSignatureDoesNotMatch
 	}
-	return s3err.ErrNone
+	return identity, s3err.ErrNone
 }
 
 // doesSignV2Match - Verify authorization header with calculated header in accordance with

weed/s3api/auth_signature_v4.go

@@ -757,12 +757,12 @@ func parseSignedHeaderList(signedHeadersValue string) ([]string, s3err.ErrorCode
 	return signedHeaders, s3err.ErrNone
 }
 
-func (iam *IdentityAccessManagement) doesPolicySignatureV4Match(formValues http.Header) s3err.ErrorCode {
+func (iam *IdentityAccessManagement) doesPolicySignatureV4Match(formValues http.Header) (*Identity, s3err.ErrorCode) {
 
 	// Parse credential tag.
 	credHeader, err := parseCredentialHeader("Credential=" + formValues.Get("X-Amz-Credential"))
 	if err != s3err.ErrNone {
-		return err
+		return nil, err
 	}
 
 	identity, cred, found := iam.lookupByAccessKey(credHeader.accessKey)
@@ -775,19 +775,19 @@ func (iam *IdentityAccessManagement) doesPolicySignatureV4Match(formValues http.
 		glog.Warningf("InvalidAccessKeyId (POST policy): attempted key '%s' not found. Available keys: %d, Auth enabled: %v",
 			credHeader.accessKey, availableKeyCount, iam.isAuthEnabled)
 
-		return s3err.ErrInvalidAccessKeyID
+		return nil, s3err.ErrInvalidAccessKeyID
 	}
 
 	// Check service account expiration
 	if cred.isCredentialExpired() {
 		glog.V(2).Infof("Service account credential %s has expired (expiration: %d, now: %d)",
 			credHeader.accessKey, cred.Expiration, time.Now().Unix())
-		return s3err.ErrAccessDenied
+		return nil, s3err.ErrAccessDenied
 	}
 
 	bucket := formValues.Get("bucket")
 	if !identity.CanDo(s3_constants.ACTION_WRITE, bucket, "") {
-		return s3err.ErrAccessDenied
+		return nil, s3err.ErrAccessDenied
 	}
 
 	// Get signing key.
@@ -798,9 +798,9 @@ func (iam *IdentityAccessManagement) doesPolicySignatureV4Match(formValues http.
 
 	// Verify signature.
 	if !compareSignatureV4(newSignature, formValues.Get("X-Amz-Signature")) {
-		return s3err.ErrSignatureDoesNotMatch
+		return nil, s3err.ErrSignatureDoesNotMatch
 	}
-	return s3err.ErrNone
+	return identity, s3err.ErrNone
 }
 
 // sigV4PayloadHashHeader is x-amz-content-sha256. It participates in the

weed/s3api/s3api_object_handlers_postpolicy.go

@@ -79,11 +79,14 @@ func (s3a *S3ApiServer) PostPolicyBucketHandler(w http.ResponseWriter, r *http.R
 	}
 
 	// Verify policy signature.
-	errCode := s3a.iam.doesPolicySignatureMatch(formValues)
+	identity, errCode := s3a.iam.doesPolicySignatureMatch(formValues)
 	if errCode != s3err.ErrNone {
 		s3err.WriteErrorResponse(w, r, errCode)
 		return
 	}
+	if identity != nil {
+		r = r.WithContext(s3_constants.SetIdentityNameInContext(r.Context(), identity.Name))
+	}
 
 	policyBytes, err := base64.StdEncoding.DecodeString(formValues.Get("Policy"))
 	if err != nil {
@@ -319,8 +322,8 @@ func getRedirectPostRawQuery(bucket, key, etag string) string {
 	return redirectValues.Encode()
 }
 
-// Check to see if Policy is signed correctly.
-func (iam *IdentityAccessManagement) doesPolicySignatureMatch(formValues http.Header) s3err.ErrorCode {
+// Check to see if Policy is signed correctly, returning the signing identity.
+func (iam *IdentityAccessManagement) doesPolicySignatureMatch(formValues http.Header) (*Identity, s3err.ErrorCode) {
 	// For SignV2 - Signature field will be valid
 	if _, ok := formValues["Signature"]; ok {
 		return iam.doesPolicySignatureV2Match(formValues)

weed/s3api/stats.go

@@ -7,6 +7,7 @@ import (
 
 	"github.com/seaweedfs/seaweedfs/weed/util/version"
 
+	"github.com/seaweedfs/seaweedfs/weed/glog"
 	"github.com/seaweedfs/seaweedfs/weed/s3api/s3_constants"
 	"github.com/seaweedfs/seaweedfs/weed/s3api/s3err"
 	stats_collect "github.com/seaweedfs/seaweedfs/weed/stats"
@@ -31,10 +32,19 @@ func track(f http.HandlerFunc, action string) http.HandlerFunc {
 		r = s3_constants.EnsureIdentityHolder(r)
 		start := time.Now()
 		f(recorder, r)
+		elapsed := time.Since(start)
+		if glog.V(2) {
+			requester := s3_constants.GetIdentityNameFromContext(r)
+			if requester == "" {
+				requester = "-"
+			}
+			// %q keeps requester- and key-supplied bytes (e.g. newlines) on one line
+			glog.Infof("%q %s %q %d %s", requester, r.Method, r.URL.Path, recorder.Status, elapsed)
+		}
 		if recorder.Status == http.StatusForbidden {
 			bucket = ""
 		}
-		stats_collect.S3RequestHistogram.WithLabelValues(action, bucket).Observe(time.Since(start).Seconds())
+		stats_collect.S3RequestHistogram.WithLabelValues(action, bucket).Observe(elapsed.Seconds())
 		stats_collect.S3RequestCounter.WithLabelValues(action, strconv.Itoa(recorder.Status), bucket).Inc()
 		stats_collect.RecordBucketActiveTime(bucket)
 		if !s3err.AuditAlreadyLogged(r) {