Repository: ratify-project/ratify
Pull request #1697 (2024-08-08 14:12:05)

feat: add timestamp and traceId to verification response
# Description

## What this PR does / why we need it:
Per discussion with @yizha1, we should add more info in the verification response and the error msg from contraint template to help users pinpoint related Ratify logs.

This PR adds `timestamp` and `traceID` in verification response to help users identity the failing request easily. And the default constraint template is updated to report the timestamp and traceID when validation fails.

Example:
When we get an error message from admission webhook in terminal:
```
Error from server (Forbidden): admission webhook "validation.gatekeeper.sh" denied the request: [ratify-constraint] Time=2024-08-08T13:55:51.647024898Z, failed to verify the artifact: libinbinacr.azurecr.io/testcosign@sha256:f2502800f0663995420b13214a0d20eae1ec9a3c072f99c462cef0132a684556, trace-id: 57e4f5ac-7152-4a0b-b056-cf8a117398f5
```
We could search for traceID in Ratify logs:
![image](https://github.com/user-attachments/assets/86fd43cf-d8d1-419c-939b-5ce1f358b566)
And if we have ELK set up, traceID can be used to filter logs directly.

The verification response will also include traceID and timestamp fields:
![image](https://github.com/user-attachments/assets/6eb79ff5-a330-470c-bfe9-1ea608e7577c)



## Which issue(s) this PR fixes *(optional, using `fixes #<issue number>(, fixes #<issue_number>, ...)` format, will close the issue(s) when the PR gets merged)*:
Fixes https://github.com/ratify-project/ratify/issues/1669

## Type of change

Please delete options that are not relevant.

- [ ] Bug fix (non-breaking change which fixes an issue)
- [ ] New feature (non-breaking change which adds functionality)
- [ ] Breaking change (fix or feature that would cause existing functionality to not work as expected)
- [ ] Helm Chart Change (any edit/addition/update that is necessary for changes merged to the `main` branch)
- [ ] This change requires a documentation update

# How Has This Been Tested?

Please describe the tests that you ran to verify your changes. Please also list any relevant details for your test configuration

- [ ] Test A
- [ ] Test B

# Checklist:

- [ ] Does the affected code have corresponding tests?
- [ ] Are the changes documented, not just with inline documentation, but also with conceptual documentation such as an overview of a new feature, or task-based documentation like a tutorial? Consider if this change should be announced on your project blog.
- [ ] Does this introduce breaking changes that would require an announcement or bumping the major version?
- [ ] Do all new files have appropriate license header?

# Post Merge Requirements
- [ ] MAINTAINERS: manually trigger the "Publish Package" workflow after merging any PR that indicates `Helm Chart Change`


codecov[bot]: ## [Codecov](https://app.codecov.io/gh/ratify-project/ratify/pull/1697?dropdown=coverage&src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project) Report
Attention: Patch coverage is `83.33333%` with `2 lines` in your changes missing coverage. Please review.

| [Files](https://app.codecov.io/gh/ratify-project/ratify/pull/1697?dropdown=coverage&src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project) | Patch % | Lines |
|---|---|---|
| [internal/logger/logger.go](https://app.codecov.io/gh/ratify-project/ratify/pull/1697?src=pr&el=tree&filepath=internal%2Flogger%2Flogger.go&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project#diff-aW50ZXJuYWwvbG9nZ2VyL2xvZ2dlci5nbw==) | 60.00% | [1 Missing and 1 partial :warning: ](https://app.codecov.io/gh/ratify-project/ratify/pull/1697?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project) |

| [Files](https://app.codecov.io/gh/ratify-project/ratify/pull/1697?dropdown=coverage&src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project) | Coverage Δ | |
|---|---|---|
| [httpserver/handlers.go](https://app.codecov.io/gh/ratify-project/ratify/pull/1697?src=pr&el=tree&filepath=httpserver%2Fhandlers.go&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project#diff-aHR0cHNlcnZlci9oYW5kbGVycy5nbw==) | `75.66% <100.00%> (+0.12%)` | :arrow_up: |
| [httpserver/types.go](https://app.codecov.io/gh/ratify-project/ratify/pull/1697?src=pr&el=tree&filepath=httpserver%2Ftypes.go&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project#diff-aHR0cHNlcnZlci90eXBlcy5nbw==) | `100.00% <100.00%> (ø)` | |
| [internal/logger/logger.go](https://app.codecov.io/gh/ratify-project/ratify/pull/1697?src=pr&el=tree&filepath=internal%2Flogger%2Flogger.go&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project#diff-aW50ZXJuYWwvbG9nZ2VyL2xvZ2dlci5nbw==) | `96.49% <60.00%> (-3.51%)` | :arrow_down: |

... and [27 files with indirect coverage changes](https://app.codecov.io/gh/ratify-project/ratify/pull/1697/indirect-changes?src=pr&el=tree-more&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=ratify-project)


Patch:
diff --git a/httpserver/handlers.go b/httpserver/handlers.go
index 13db60f..7c4596f 100644
--- a/httpserver/handlers.go
+++ b/httpserver/handlers.go
@@ -141,12 +141,12 @@ func (server *Server) verify(ctx context.Context, w http.ResponseWriter, r *http
 						logger.GetLogger(ctx, server.LogOption).Warnf("unable to insert cache entry for subject %v", resolvedSubjectReference)
 					}
 				}
-
-				if res, err := json.MarshalIndent(result, "", "  "); err == nil {
-					logger.GetLogger(ctx, server.LogOption).Infof("verify result for subject %s: %s", resolvedSubjectReference, string(res))
-				}
 			}
-			returnItem.Value = fromVerifyResult(result, server.GetExecutor(ctx).PolicyEnforcer.GetPolicyType(ctx))
+			verificationResponse := fromVerifyResult(ctx, result, server.GetExecutor(ctx).PolicyEnforcer.GetPolicyType(ctx))
+			returnItem.Value = verificationResponse
+			if res, err := json.MarshalIndent(verificationResponse, "", "  "); err == nil {
+				logger.GetLogger(ctx, server.LogOption).Infof("verification response for subject %s: \n%s", resolvedSubjectReference, string(res))
+			}
 			logger.GetLogger(ctx, server.LogOption).Debugf("verification: execution time for image %s: %dms", resolvedSubjectReference, time.Since(routineStartTime).Milliseconds())
 		}(utils.SanitizeString(key), ctx)
 	}
diff --git a/httpserver/types.go b/httpserver/types.go
index 8e3655c..dafad65 100644
--- a/httpserver/types.go
+++ b/httpserver/types.go
@@ -16,6 +16,10 @@ limitations under the License.
 package httpserver
 
 import (
+	"context"
+	"time"
+
+	"github.com/ratify-project/ratify/internal/logger"
 	"github.com/ratify-project/ratify/pkg/executor/types"
 	pt "github.com/ratify-project/ratify/pkg/policyprovider/types"
 )
@@ -32,10 +36,12 @@ const (
 type VerificationResponse struct {
 	Version         string        `json:"version"`
 	IsSuccess       bool          `json:"isSuccess"`
+	TraceID         string        `json:"traceID,omitempty"`
+	Timestamp       string        `json:"timestamp,omitempty"`
 	VerifierReports []interface{} `json:"verifierReports,omitempty"`
 }
 
-func fromVerifyResult(res types.VerifyResult, policyType string) VerificationResponse {
+func fromVerifyResult(ctx context.Context, res types.VerifyResult, policyType string) VerificationResponse {
 	version := ResultVersion0_2_0
 	if policyType == pt.RegoPolicy {
 		version = ResultVersion1_1_0
@@ -43,6 +49,8 @@ func fromVerifyResult(res types.VerifyResult, policyType string) VerificationRes
 	return VerificationResponse{
 		Version:         version,
 		IsSuccess:       res.IsSuccess,
+		Timestamp:       time.Now().Format(time.RFC3339Nano),
+		TraceID:         logger.GetTraceID(ctx),
 		VerifierReports: res.VerifierReports,
 	}
 }
diff --git a/internal/logger/logger.go b/internal/logger/logger.go
index ff050ce..3a65de0 100644
--- a/internal/logger/logger.go
+++ b/internal/logger/logger.go
@@ -101,6 +101,15 @@ func GetLogger(ctx context.Context, opt Option) dcontext.Logger {
 	return dcontext.GetLogger(ctx, ContextKeyComponentType)
 }
 
+// GetTraceID returns the trace ID from the context.
+func GetTraceID(ctx context.Context) string {
+	traceID := ctx.Value(ContextKeyTraceID)
+	if traceID == nil {
+		return ""
+	}
+	return traceID.(string)
+}
+
 // setTraceID sets the trace ID in the context. If the trace ID is not present in the request headers, a new one is generated.
 func setTraceID(ctx context.Context, r *http.Request) context.Context {
 	traceID := ""
diff --git a/library/default/template.yaml b/library/default/template.yaml
index a371921..6cc46ec 100644
--- a/library/default/template.yaml
+++ b/library/default/template.yaml
@@ -44,5 +44,5 @@ spec:
         general_violation[{"result": result}] {
           subject_validation := remote_data.responses[_]
           subject_validation[1].isSuccess == false
-          result := sprintf("Failed to verify the artifact: %s", [subject_validation[0]])
+          result := sprintf("Time=%s, failed to verify the artifact: %s, trace-id: %s", [subject_validation[1].timestamp, subject_validation[0], subject_validation[1].traceID])
         }


Test patch:
diff --git a/httpserver/types_test.go b/httpserver/types_test.go
index 04ed6da..c03d694 100644
--- a/httpserver/types_test.go
+++ b/httpserver/types_test.go
@@ -16,6 +16,7 @@ limitations under the License.
 package httpserver
 
 import (
+	"context"
 	"testing"
 
 	"github.com/ratify-project/ratify/pkg/executor/types"
@@ -43,7 +44,7 @@ func TestFromVerifyResult(t *testing.T) {
 
 	for _, tc := range testCases {
 		t.Run(tc.name, func(t *testing.T) {
-			if res := fromVerifyResult(result, tc.policyType); res.Version != tc.expectedVersion {
+			if res := fromVerifyResult(context.Background(), result, tc.policyType); res.Version != tc.expectedVersion {
 				t.Fatalf("Expected version to be %s, got %s", tc.expectedVersion, res.Version)
 			}
 		})
diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go
index 6024134..9aa95d3 100644
--- a/internal/logger/logger_test.go
+++ b/internal/logger/logger_test.go
@@ -23,7 +23,6 @@ import (
 	"testing"
 
 	logstash "github.com/bshuster-repo/logrus-logstash-hook"
-	dcontext "github.com/docker/distribution/context"
 	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 )
@@ -75,7 +74,7 @@ func TestInitContext(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			traceIDHeaderNames = tc.headerNames
 			ctx := InitContext(context.Background(), tc.r)
-			traceID := dcontext.GetStringValue(ctx, ContextKeyTraceID)
+			traceID := GetTraceID(ctx)
 			if traceID == "" {
 				t.Fatalf("expected non-empty traceID, but got empty one")
 			}