diff --git a/pkg/billing/workflow_client.go b/pkg/billing/workflow_client.go index ecae475ba5..9a69a1b015 100644 --- a/pkg/billing/workflow_client.go +++ b/pkg/billing/workflow_client.go @@ -2,16 +2,22 @@ package billing import ( "context" + "crypto/sha256" "crypto/x509" + "encoding/hex" + "encoding/json" "fmt" + "github.com/golang-jwt/jwt/v5" "google.golang.org/grpc" "google.golang.org/grpc/credentials" "google.golang.org/grpc/credentials/insecure" "google.golang.org/grpc/metadata" + "google.golang.org/protobuf/proto" "google.golang.org/protobuf/types/known/emptypb" auth "github.com/smartcontractkit/chainlink-common/pkg/nodeauth/jwt" + "github.com/smartcontractkit/chainlink-common/pkg/nodeauth/types" pb "github.com/smartcontractkit/chainlink-protos/billing/go" "github.com/smartcontractkit/chainlink-common/pkg/logger" @@ -126,24 +132,96 @@ func (wc *workflowClient) Close() error { } // addJWTAuth creates and signs a JWT token, then adds it to the context -func (wc *workflowClient) addJWTAuth(ctx context.Context, req any) (context.Context, error) { +// Returns the updated context and the JWT token string (for logging purposes) +func (wc *workflowClient) addJWTAuth(ctx context.Context, req any) (context.Context, string, error) { // Skip authentication if no JWT manager provided if wc.jwtGenerator == nil { - return ctx, nil + return ctx, "", nil } // Create JWT token using the JWT manager jwtToken, err := wc.jwtGenerator.CreateJWTForRequest(req) if err != nil { - return nil, fmt.Errorf("failed to create JWT: %w", err) + return nil, "", fmt.Errorf("failed to create JWT: %w", err) } // Add JWT to Authorization header - return metadata.AppendToOutgoingContext(ctx, "authorization", "Bearer "+jwtToken), nil + return metadata.AppendToOutgoingContext(ctx, "authorization", "Bearer "+jwtToken), jwtToken, nil +} + +// parseJWTForLogging parses the JWT token without verification to extract claims for logging purposes +func parseJWTForLogging(tokenString string) *types.NodeJWTClaims { + if tokenString == "" { + return nil + } + parser := jwt.NewParser() + token, _, err := parser.ParseUnverified(tokenString, &types.NodeJWTClaims{}) + if err != nil { + return nil + } + + claims, ok := token.Claims.(*types.NodeJWTClaims) + if !ok { + return nil + } + + return claims +} + +// DigestDebugInfo contains debugging information about digest calculation +type DigestDebugInfo struct { + RequestType string + IsProtoMessage bool + SerializedLength int + RequestJSON string + MarshalSuccess bool +} + +// calculateDigestWithDebugging calculates the request digest with detailed debugging information +func calculateDigestWithDebugging(req any) (string, DigestDebugInfo) { + debugInfo := DigestDebugInfo{ + RequestType: fmt.Sprintf("%T", req), + } + + var data []byte + if m, ok := req.(proto.Message); ok { + debugInfo.IsProtoMessage = true + // Use protobuf canonical serialization + serialized, err := proto.Marshal(m) + if err == nil { + debugInfo.MarshalSuccess = true + data = serialized + } else { + debugInfo.MarshalSuccess = false + // fallback to string representation if marshal fails + data = fmt.Appendf(nil, "%v", req) + } + } else if s, ok := req.(fmt.Stringer); ok { + debugInfo.IsProtoMessage = false + debugInfo.MarshalSuccess = true + data = []byte(s.String()) + } else { + debugInfo.IsProtoMessage = false + debugInfo.MarshalSuccess = true + data = fmt.Appendf(nil, "%v", req) + } + + debugInfo.SerializedLength = len(data) + + // Create JSON representation of the request for human-readable debugging + if jsonBytes, err := json.Marshal(req); err == nil { + debugInfo.RequestJSON = string(jsonBytes) + } else { + // Fallback to string representation + debugInfo.RequestJSON = fmt.Sprintf("%+v", req) + } + + hash := sha256.Sum256(data) + return hex.EncodeToString(hash[:]), debugInfo } func (wc *workflowClient) GetOrganizationCreditsByWorkflow(ctx context.Context, req *pb.GetOrganizationCreditsByWorkflowRequest) (*pb.GetOrganizationCreditsByWorkflowResponse, error) { - ctx, err := wc.addJWTAuth(ctx, req) + ctx, _, err := wc.addJWTAuth(ctx, req) if err != nil { wc.logger.Errorw("Failed to add custom auth header to GetOrganizationCreditsByWorkflow request", "error", err) return nil, err @@ -157,7 +235,7 @@ func (wc *workflowClient) GetOrganizationCreditsByWorkflow(ctx context.Context, } func (wc *workflowClient) GetWorkflowExecutionRates(ctx context.Context, req *pb.GetWorkflowExecutionRatesRequest) (*pb.GetWorkflowExecutionRatesResponse, error) { - ctx, err := wc.addJWTAuth(ctx, req) + ctx, _, err := wc.addJWTAuth(ctx, req) if err != nil { wc.logger.Errorw("Failed to add custom auth header to GetWorkflowExecutionRates request", "error", err) return nil, err @@ -171,7 +249,7 @@ func (wc *workflowClient) GetWorkflowExecutionRates(ctx context.Context, req *pb } func (wc *workflowClient) ReserveCredits(ctx context.Context, req *pb.ReserveCreditsRequest) (*pb.ReserveCreditsResponse, error) { - ctx, err := wc.addJWTAuth(ctx, req) + ctx, _, err := wc.addJWTAuth(ctx, req) if err != nil { wc.logger.Errorw("Failed to add JWT auth to ReserveCredits request", "error", err) return nil, err @@ -185,14 +263,51 @@ func (wc *workflowClient) ReserveCredits(ctx context.Context, req *pb.ReserveCre } func (wc *workflowClient) SubmitWorkflowReceipt(ctx context.Context, req *pb.SubmitWorkflowReceiptRequest) (*emptypb.Empty, error) { - ctx, err := wc.addJWTAuth(ctx, req) + // Calculate digest and get debug info before adding JWT + clientDigest, debugInfo := calculateDigestWithDebugging(req) + + // Add JWT authentication + ctx, jwtToken, err := wc.addJWTAuth(ctx, req) if err != nil { wc.logger.Errorw("Failed to add JWT auth to SubmitWorkflowReceipt request", "error", err) return nil, err } + + // Parse JWT claims for logging + parsedClaims := parseJWTForLogging(jwtToken) + + // Log detailed request information (matching billing service format) + logFields := []any{ + "method", "SubmitWorkflowReceipt", + "jwt_token", jwtToken, + "client_calculated_digest", clientDigest, + "request_type", debugInfo.RequestType, + "is_proto_message", debugInfo.IsProtoMessage, + "serialized_length", debugInfo.SerializedLength, + "request_json", debugInfo.RequestJSON, + "marshal_success", debugInfo.MarshalSuccess, + } + + if parsedClaims != nil { + logFields = append(logFields, + "parsed_public_key", parsedClaims.PublicKey, + "parsed_digest_from_jwt", parsedClaims.Digest, + "digest_match", parsedClaims.Digest == clientDigest, + "parsed_issuer", parsedClaims.Issuer, + "parsed_subject", parsedClaims.Subject, + "parsed_expires_at", parsedClaims.ExpiresAt, + "parsed_issued_at", parsedClaims.IssuedAt, + "parsed_audience", parsedClaims.Audience, + ) + } + + wc.logger.Infow("Sending SubmitWorkflowReceipt request", logFields...) + + // Make the actual RPC call resp, err := wc.client.SubmitWorkflowReceipt(ctx, req) if err != nil { - wc.logger.Errorw("SubmitWorkflowReceipt failed", "error", err) + // Log error with the same detailed information for debugging + wc.logger.Errorw("SubmitWorkflowReceipt failed", append(logFields, "error", err)...) return nil, err } return resp, nil diff --git a/pkg/billing/workflow_client_test.go b/pkg/billing/workflow_client_test.go index 7c84f569d1..7e737fc0ff 100644 --- a/pkg/billing/workflow_client_test.go +++ b/pkg/billing/workflow_client_test.go @@ -239,8 +239,9 @@ func TestWorkflowClient_AddJWTAuthToContext(t *testing.T) { } ctx := context.Background() - newCtx, err := wc.addJWTAuth(ctx, req) + newCtx, jwtToken, err := wc.addJWTAuth(ctx, req) require.NoError(t, err) + require.Equal(t, expectedToken, jwtToken, "Expected JWT token to be returned") // Verify JWT is added to metadata md, ok := metadata.FromOutgoingContext(newCtx) @@ -260,8 +261,9 @@ func TestWorkflowClient_NoSigningKey(t *testing.T) { logger: logger.Test(t), jwtGenerator: nil, } - newCtx, err := wc.addJWTAuth(ctx, req) + newCtx, jwtToken, err := wc.addJWTAuth(ctx, req) require.NoError(t, err) + require.Empty(t, jwtToken, "Expected empty JWT token when no JWT generator is provided") // Should return the same context assert.Equal(t, ctx, newCtx) @@ -280,8 +282,9 @@ func TestWorkflowClient_VerifySignature_Invalid(t *testing.T) { } ctx := context.Background() - _, err := wc.addJWTAuth(ctx, req) + _, jwtToken, err := wc.addJWTAuth(ctx, req) require.Error(t, err) + require.Empty(t, jwtToken, "Expected empty JWT token on error") assert.Contains(t, err.Error(), "failed to create JWT") } @@ -299,12 +302,14 @@ func TestWorkflowClient_RepeatedSign(t *testing.T) { } ctx1 := context.Background() - newCtx1, err := wc.addJWTAuth(ctx1, req) + newCtx1, jwtToken1, err := wc.addJWTAuth(ctx1, req) require.NoError(t, err) + require.Equal(t, expectedToken, jwtToken1, "Expected JWT token to match") ctx2 := context.Background() - newCtx2, err := wc.addJWTAuth(ctx2, req) + newCtx2, jwtToken2, err := wc.addJWTAuth(ctx2, req) require.NoError(t, err) + require.Equal(t, expectedToken, jwtToken2, "Expected JWT token to match") // Both should have the same token since we're mocking the same response md1, ok := metadata.FromOutgoingContext(newCtx1) @@ -314,3 +319,57 @@ func TestWorkflowClient_RepeatedSign(t *testing.T) { assert.Equal(t, md1["authorization"], md2["authorization"], "Expected same authorization header for same request") } + +func TestWorkflowClient_SubmitWorkflowReceipt_WithLogging(t *testing.T) { + // Start a test gRPC server + lis, err := net.Listen("tcp", "localhost:0") + require.NoError(t, err) + grpcServer := grpc.NewServer() + testSrv := &testWorkflowServer{} + pb.RegisterCreditReservationServiceServer(grpcServer, testSrv) + go func() { + _ = grpcServer.Serve(lis) + }() + defer grpcServer.Stop() + + addr := lis.Addr().String() + + // Create mock JWT manager for testing + mockJWT := mocks.NewJWTGenerator(t) + expectedToken := "test.jwt.token.for.logging" + + // Create a test request + req := &pb.SubmitWorkflowReceiptRequest{ + WorkflowOwner: "test-owner", + WorkflowId: "test-workflow-id", + WorkflowExecutionId: "test-execution-id", + WorkflowRegistryAddress: "0x123", + WorkflowRegistryChainSelector: 1, + CreditsConsumed: "100", + } + + // Expect JWT creation + mockJWT.EXPECT().CreateJWTForRequest(req).Return(expectedToken, nil).Once() + + lggr := logger.Test(t) + wc, err := NewWorkflowClient(lggr, addr, + WithWorkflowTransportCredentials(insecure.NewCredentials()), + WithJWTGenerator(mockJWT), + WithServerName("localhost"), + ) + require.NoError(t, err) + defer func(wc WorkflowClient) { + _ = wc.Close() + }(wc) + + // Call SubmitWorkflowReceipt + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + resp, err := wc.SubmitWorkflowReceipt(ctx, req) + require.NoError(t, err) + require.NotNil(t, resp) + + // Note: In a real test, we would inspect the logs to verify the detailed + // logging is happening. For now, we're just ensuring the method works + // with the new logging code. +}