[EXPERIMENTAL] feat: improve log information

[jvillafanez]

Description

Improve logs by including more information in the log that is attached to the context.

NOTE: The PR just touches the minimum code to showcase how logs could appear. It's far from being finished. It still need changes in all the services, decisions on where to place some of the code, and additional polishing.

Related Issue

#10613

Motivation and Context

The information in the logs should be as homogeneous as possible. Most of the code is associated with a HTTP or GRPC request whose context might contain useful information that could be logged.

How Has This Been Tested?

For GRPC requests associated to our go-micro's services, the log expectation is the following:

{"level":"error","service":"settings",":Authority":"127.0.0.1:9191","Account-Id":"1f951881-f43c-42b5-931c-44bcbdce9ba0","Client-Name":"graph","Client-Version":"7.0.0-rc.3+5c1be18f30","Content-Type":"application/grpc+proto","Grpc-Accept-Encoding":"gzip","Remote":"127.0.0.1:50676","User-Agent":"grpc-go/1.68.0","target":"com.owncloud.api.settings","method":"RoleService.AssignRoleToUser","endpoint":"RoleService.AssignRoleToUser","isStream":false,"time":"2024-11-26T12:48:48Z","message":"test message for debugging purposes"}

The log happens when changing a user's role (the "error" level is just for easier visibility). Note that the log show information that is in the request's context, so there could be additional information not filled by us.

For GRPC requests associated to reva's services:

{"level":"error","service":"collaboration",":authority":["172.18.0.9:9301"],"content-type":["application/grpc"],"grpc-accept-encoding":["gzip"],"initiator-id":["8af453ef-6474-4c7f-997b-36560fdf8cbb"],"traceparent":["00-fb14ac33d1404f843cf0ecf87f88ea5e-9f1e66ef473227cb-00"],"user-agent":["grpc-go/1.68.0"],"x-access-token":["eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJodHRwczovL29jaXMuanAuc29saWRnZWFyLnBydiIsImF1ZCI6WyJyZXZhIl0sImV4cCI6MTczMjcwNTg0NCwiaWF0IjoxNzMyNjE5NDQ0LCJ1c2VyIjp7ImlkIjp7ImlkcCI6Imh0dHBzOi8vb2Npcy5qcC5zb2xpZGdlYXIucHJ2Iiwib3BhcXVlX2lkIjoiMWY5NTE4ODEtZjQzYy00MmI1LTkzMWMtNDRiY2JkY2U5YmEwIiwidHlwZSI6MX0sInVzZXJuYW1lIjoiYWRtaW4iLCJtYWlsIjoiYWRtaW5AZXhhbXBsZS5vcmciLCJkaXNwbGF5X25hbWUiOiJBZG1pbiIsInVpZF9udW1iZXIiOjk5LCJnaWRfbnVtYmVyIjo5OX0sInNjb3BlIjp7InVzZXIiOnsicmVzb3VyY2UiOnsiZGVjb2RlciI6Impzb24iLCJ2YWx1ZSI6ImV5SndZWFJvSWpvaUx5SjkifSwicm9sZSI6MX19fQ.hrs4cbAZSvY6cjEMn_pjWcNtpHGW6DY9qvl7mD6FkDQ"],"x-user-agent":["Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:132.0) Gecko/20100101 Firefox/132.0"],"time":"2024-11-26T11:10:44Z","line":"/home/juan/src/ocis/ocis/services/collaboration/pkg/service/grpc/v0/service.go:71","message":"collaboration openinapp"}

Note that the code is different because we're using the go's GRPC implementation and not a library on top of it. In addition, clients are created in reva, so we don't have control over them to inject our data (mostly client information).
The log happens opening a document with OnlyOffice or Collabora.

For HTTP requests:

{"level":"debug","service":"collaboration","request-id":"","proto":"HTTP/1.1","method":"GET","host":"wopiserver_oo:9300","path":"/wopi/files/17a8f84b33be48f95da12039dbc6b067dbe6be9b8c72eacab9518aec9b1bca16","query":"access_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJXb3BpQ29udGV4dCI6eyJBY2Nlc3NUb2tlbiI6IkJ4YlQ4b19ySV9KSG1qR0RNTFZpRUFmRVhLUFp5Sld5aHN3Ykk1UHc3Zi1TTzFYYmRXZFlNWEQwd2FOQ1FNbkZEWnc0UmNsU0JYNnFNbG9wdVFtQlRNZlV4VEpPZlFDbTRFZUgxOXJENVVneUlyX0tWR3VJNDZNVjZHLWpncFRhNFgyS3ItYzlvTnJ4NDJ6ckdDMzNsU0JhLXNvbEVQOENpSEVNMW5pdDFWdzVhN0NsSjRoVE92RXNDTFJicVN0TVRDc0NnMGRod21iVV93RDFXUTNEZVBBOU13YTdNcEJ2U3R4S3Y2eUp0eWx1d3p0QldZSkxxNkJSUG1GRWp0Mmc1enJ0dC1wa2NXZ2ZUb0dVX2RDd29Qa3lYamp2UF9lNmJaaGxjZUVfdjdkejBhdUczTENJNHRLRkk1OW9BakNFcl9OYUstOTExajE2cVBTMm9QN0hnV2lyamFKRHhRd3ZGZHJZRWo0UUViMkVzenBjd1pIRlVzOVRXWGxkeUp0ckdKZHFPS2stNkg5UmZud2hIa2N6Vl9sMnB3d0pzSTBFQ1k2OVQyUTVmZTN6SnBNRkxYaEVlUUdIQlNEa3BFNnFKeGt2Y1ZWeEhWX3Jxd3RKblNzazk2MTdwX0dqZUVSR1Y0SWFaMW9RSllIZGpqSzNTRE9vNHVPcllpY2VPUXV6azJ3a2lObThzWXZ2QWR5NUd5SWJEX0pNVXdGTzFGYTE1eUNKS1VGenQwRWJQQ3NONkI4Tkt3RFkxZElONDFqcEpsQ2J0ZnNGUFcxaFgzVWk5c2I5Y0wwUTEwdzF0Zlg2VUVlM3BVVVNWLWh0aDhHQWV3Y1FoU05vVGZPb2RVRGxua05iT2lobTFrOFhPZ09YLVBTeFFkUFBzRFFHOVczc2hzYWpFUFNfYTd1LXkyWFVNWUwyMzl5SGtqdERDQy1sUGFpTkg1NExVVFpfVWR4emZta0dpQXB3QUN0UVJDanBMeU9rQUpLdWhqdTJtaXZQbWNLYm91bDFJWW1tM08xR1RYMTQ5c1owaFJlM1VaLXBzQUZRUGdvbklfRE42bHVubjdqOVRlVUx0VEdhanp0UjhhQVEiLCJWaWV3T25seVRva2VuIjoiIiwiRmlsZVJlZmVyZW5jZSI6eyJyZXNvdXJjZV9pZCI6eyJzdG9yYWdlX2lkIjoiMDliYWQxYzYtODcxNS00ZWIxLWE3YzEtNzY5NDQ4NDNhMDg0Iiwib3BhcXVlX2lkIjoiYWQyNjY5N2UtNzU4MS00NTNmLWJlMjctZWMwYmU4MGFlZmYxIiwic3BhY2VfaWQiOiIxZjk1MTg4MS1mNDNjLTQyYjUtOTMxYy00NGJjYmRjZTliYTAifSwicGF0aCI6Ii4ifSwiVGVtcGxhdGVSZWZlcmVuY2UiOm51bGwsIlZpZXdNb2RlIjozfSwiZXhwIjoxNzMyNzA1ODQ0fQ.2skppmjw_faBdwWdmnNENIkdDPPMRlFntuv0zGCxWvo","fragment":"","remote-addr":"172.18.0.2:41834","user-agent":"Node.js/6.13","content-length":"","content-type":"","WopiSessionId":"","WopiOverride":"","WopiProof":"VpJpni7NBmU0VOrXzfbvXDel++YS+3sWwGFR4cZO8msKmZhGvjZYejdz6+D4Qyzjonm4ldvLlRnHOkE3Y3fZwqZQqdq/3zZOzs1bjRpIHJx9fwDxDua2f3/Wba/O/MfHvkwBonOQVCob3iBes80lF2pZd1wMfffOPahC7n8FddcSvGZCUX7Bibqz3AIPEeSNMOu+vc4I/e8wffj4X3n2bB80UWOSdesFJ90xLMbsi7YXi/qCM6JgQT9r2vJ0806X8Sc8vCnSF/Fkl8eYW/IXkk8qtFD2LksEUuga/tgCnltrwLelhp8yAtZlhNqtX1jZumnJ+26+V1j/6YzzTt+KEA==","WopiProofOld":"VpJpni7NBmU0VOrXzfbvXDel++YS+3sWwGFR4cZO8msKmZhGvjZYejdz6+D4Qyzjonm4ldvLlRnHOkE3Y3fZwqZQqdq/3zZOzs1bjRpIHJx9fwDxDua2f3/Wba/O/MfHvkwBonOQVCob3iBes80lF2pZd1wMfffOPahC7n8FddcSvGZCUX7Bibqz3AIPEeSNMOu+vc4I/e8wffj4X3n2bB80UWOSdesFJ90xLMbsi7YXi/qCM6JgQT9r2vJ0806X8Sc8vCnSF/Fkl8eYW/IXkk8qtFD2LksEUuga/tgCnltrwLelhp8yAtZlhNqtX1jZumnJ+26+V1j/6YzzTt+KEA==","WopiStamp":"638682162443690000","FileReference":"resource_id:{storage_id:\"09bad1c6-8715-4eb1-a7c1-76944843a084\" opaque_id:\"ad26697e-7581-453f-be27-ec0be80aeff1\" space_id:\"1f951881-f43c-42b5-931c-44bcbdce9ba0\"} path:\".\"","ViewMode":"VIEW_MODE_READ_WRITE","Requester":"idp:\"https://ocis.jp.solidgear.prv\" opaque_id:\"1f951881-f43c-42b5-931c-44bcbdce9ba0\" type:USER_TYPE_PRIMARY","FileInfo":{"BaseFileName":"Document.docx","Version":"v1686301489864","BreadcrumbDocName":"Document.docx","BreadcrumbFolderName":"Admin","BreadcrumbFolderUrl":"https://ocis.jp.solidgear.prv/f/09bad1c6-8715-4eb1-a7c1-76944843a084$1f951881-f43c-42b5-931c-44bcbdce9ba0%21ad26697e-7581-453f-be27-ec0be80aeff1","PostMessageOrigin":"https://ocis.jp.solidgear.prv","FileSharingUrl":"https://ocis.jp.solidgear.prv/f/09bad1c6-8715-4eb1-a7c1-76944843a084$1f951881-f43c-42b5-931c-44bcbdce9ba0%21ad26697e-7581-453f-be27-ec0be80aeff1?details=sharing","FileVersionUrl":"https://ocis.jp.solidgear.prv/f/09bad1c6-8715-4eb1-a7c1-76944843a084$1f951881-f43c-42b5-931c-44bcbdce9ba0%21ad26697e-7581-453f-be27-ec0be80aeff1?details=versions","HostEditUrl":"https://ocis.jp.solidgear.prv/external-onlyoffice/personal/admin/Document.docx?fileId=09bad1c6-8715-4eb1-a7c1-76944843a084%241f951881-f43c-42b5-931c-44bcbdce9ba0%21ad26697e-7581-453f-be27-ec0be80aeff1&view_mode=write","DisablePrint":false,"UserFriendlyName":"Admin","UserId":"31663935313838312d663433632d343262352d393331632d3434626362646365396261304068747470733a2f2f6f6369732e6a702e736f6c6964676561722e707276","ReadOnly":false,"UserCanNotWriteRelative":false,"UserCanRename":true,"UserCanWrite":true,"SupportsLocks":true,"SupportsRename":true,"SupportsUpdate":true},"time":"2024-11-26T11:10:44Z","line":"/home/juan/src/ocis/ocis/services/collaboration/pkg/connector/fileconnector.go:1283","message":"CheckFileInfo: success"}

This might not be a good example... We're logging most of the relevant request info, although it's unfortunate that the path's query is very long in this case (note that the access token is part of the url, so it's public anyway). WOPI context is chained afterwards, and finally additional information from the code path.

For all the HTTP requests, regardless of the service, the information should be the same until the "content-type" key. The rest of the information will be dependent on the specific service (for example, WOPI information in this case).

Screenshots (if appropriate):

Types of changes

• 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 change)
• Technical debt
• Tests only (no source changes)

Checklist:

• Code changes
• Unit tests added
• Acceptance tests added
• Documentation ticket raised:

NOTES:

• This is still experimental. The code is incomplete and it will change.
• For reva's GRPC, the related code should be moved to the reva repository. Knowing who's calling which method could help to debug issues, and we need client information that we don't have at the moment.
  • It makes more sense for reva to provide a client interceptor that could be automatically added when a client is created. From our side, we should just need to provide the information
  • It also makes sense that, in this case, the collaboration service, would use the reva's provided interceptor in order to log the metadata from the GRPC connection. We just need to configure it.
• For our GRPC service, we still need to decide what information we want to show:
  • Client's name and version might be useful in order to know who's calling the service and whether the client is in the latest version (we assume that the binary will be the same for all the services, but something might go wrong).
  • We might need to include something to distinguish among replicas. It isn't clear if a combination of "Client-Name" + "Remote" is enough.
  • As said, the logger will show whatever is in the context's metadata. This could include information we might not want to show that might come from anywhere, not just the client.
  • Services are expected to get and use the logger attached to the context (which will contain this information).
• For HTTP services:
  • There should be an "initial logger", which is the "NewContextLogger". This will include all the basic information we want to log from the HTTP request.
  • The access logger should use this "NewContextLogger" by retrieving it from the request's context. This is what the "AcessLogger2" is doing in the collaboration service.
    • The plan is to replace the access loggers, but we'll need to touch all the services. For now, only the collaboration service is touched because is more isolated than the rest.
    • The "NewContextLogger" must be the first one in the chain. The access logger must be placed later in order to get the data added by the context logger. Additional loggers can be placed in between in order to include additional information that we want to include as part of the access logger (such as the WOPI context in the collaboration service, for example).
  • Handling of replicas still needs to be tested. We might need to include additional information if we can't distinguish among them.

[update-docs]

Thanks for opening this pull request! The maintainers of this repository would appreciate it if you would create a changelog item based on your changes.

[sonarcloud]

Quality Gate failed

Failed conditions
2 New Bugs (required ≤ 0)

See analysis details on SonarQube Cloud

Catch issues before they fail your Quality Gate with our IDE extension SonarQube for IDE