upstream of transparanty kms logger

[beejones]

Extend Logger with LogContext including scope and request id. This allow us to correlate requests with the logs in KMS in order to debug transactions.
The basis of this development was done by @yf23.

1. Request ID enhancement

   • Reads request ID from KMS endpoint requests from the following fields (in order)

     [
       'x-ms-kms-request-id',
       'x-ms-request-id',
       'x-request-id',
       'request-id',
       'requestid',
     ]
     

   • Use timestamp as request ID if request does not contain request ID.
     • Need to improve: I cannot get uuid package working. Preferrable to generate random UUID.
   • Returns accepted request ID in response header x-ms-kms-request-id

2. Log Enrichment with LogContext
   Add function scope stack and request ID to KMS log with LogContext. The output format is [requestId=***,scope=***]

2024-10-24T00:08:51.131926Z -0.002 0   [info ][app] c/js/extensions/console.cpp:156 | [INFO] [requestId=12345678,scope=publickeyEndpoint->OhttpPublicKey] Generate OTTP public key for key id: 1

3. Add / Format the logs for KMS endpoints and policy operations.

[beejones]

tests:
https://github.com/microsoft/privacy-sandbox-dev/actions/runs/11726442638

[takuro-sato]

@beejones Did you check how the actual CCF log looks like with B&A services used? If not can you do that please? If it prints out too much warnings maybe we want to consider not putting them as warnings to avoid people from ignoring other important warnings.

[takuro-sato]

What's our criteria for using debug and using info?

[beejones]

DEBUG is only for debugging. There are too many Logger.info calls because debug was broken. I fixed this in the new PR:
#221

There is minimal info logging for the endpoints. In principal just the name of request and the result of the endpoint. With debug flag you see all details

[takuro-sato]

CI with better CCF log: https://github.com/microsoft/privacy-sandbox-dev/actions/runs/11834527642

[takuro-sato]

https://github.com/microsoft/privacy-sandbox-dev/actions/runs/11841224146

[takuro-sato]

Ronny triggered new CI: CI · microsoft/privacy-sandbox-dev@9dc0c53. Thanks!

@beejones

Looks like printing out some objects is not successful e.g. [DEBUG] [requestId=1731665433037,scope=listpubkeys] Request: [object Object] . Is it expected? If not can you fix it or make an issue to fix later please?

[beejones]

We need to sync the codebase of https://github.com/microsoft/azure-privacy-sandbox-kms/ with https://github.com/microsoft/azure-transparent-kms because this repo has important changes which are beneficial for azure-transparent-kms. The PR was needed to upstream big changes in azure-transparent-kms to this repo. Once this PR is merged, it will be possible to merge the changes into azure-transparent-kms with minimal merge conflicts.
Next step:
#201 to address the open points in this review.

[beejones]

Ronny triggered new CI: CI · microsoft/privacy-sandbox-dev@9dc0c53. Thanks!

@beejones

Looks like printing out some objects is not successful e.g. [DEBUG] [requestId=1731665433037,scope=listpubkeys] Request: [object Object] . Is it expected? If not can you fix it or make an issue to fix later please?

This is fixed in #221
See:
2024-11-26T13:39:35.570110Z -0.004 0 [info ][app] c/js/extensions/console.cpp:156 | [DEBUG] Request: {
"isLogContext": true,
"scopeStack": [
"key",
"loadSettingsFromMap"
],
"requestId": "1732628375568"
} {
"headers": {
":authority": "127.0.0.1:8000",
":method": "POST",
":path": "/app/key",
":scheme": "https",
"content-type": "application/json"
},
"query": "",
"path": "/app/key",
"method": "POST",
"hostname": null,
"route": "/app/key",
"url": "/app/key",
"params": {},
"body": {},
"caller": {
"policy": "jwt",
"jwt": {
"keyIssuer": "http://Demo-jwt-issuer",
"header": {
"alg": "RS256",
"kid": "Demo IDP kid",
"typ": "JWT"
},
"payload": {
"exp": 1732631975,
"iat": 1732628375,
"iss": "http://Demo-jwt-issuer",
"name": "Cool caller",
"nbf": 1732628375,
"sub": "c0d8e9a7-6b8e-4e1f-9e4a-3b2c1d0f5a6b"
}
}
}
}