Add option for exhaustive gitserver logging by ggilmore · Pull Request #61270 · sourcegraph/sourcegraph-public-snapshot

ggilmore · 2024-03-19T16:27:26Z

Closes https://github.com/sourcegraph/sourcegraph/issues/62025

This PR adds exhaustive gRPC logging for gitserver when the SRC_GITSERVER_EXHAUSTIVE_LOGGING_ENABLED environment variable is set to true.

Each RPC now logs the method name, duration, status code, and request contents. (I've taken care to omit certain sensitive fields / redact where appropriate - but I'd appreciate a close review here).

Test plan

Unit tests for specific wrapper around gRPC client streaming
Ran sourcegraph locally with env SRC_GITSERVER_EXHAUSTIVE_LOGGING_ENABLED=true sg start and the following diff applied

diff --git a/sg.config.yaml b/sg.config.yaml
index f54f9b52139..11c6896edca 100644
--- a/sg.config.yaml
+++ b/sg.config.yaml
@@ -189,6 +189,7 @@ commands:
     checkBinary: .bin/gitserver
     env:
       HOSTNAME: 127.0.0.1:3178
+      SRC_LOG_LEVEL: dbug
     watch:
       - lib
       - internal

I then saw the following logs:

[    gitserver-0] DEBUG gitserver.gRPCRequestLogger internal/server_grpc_logger.go:44 Handled ResolveRevision RPC {"server": "gitserver.v1.GitserverService", "method": "ResolveRevision", "status": "OK", "traceID": "76fa5d07df4703686a9f3e23fffeae0a", "duration": "50.029ms", "request": {"repoName": "github.com/torvalds/linux", "revSpec": "HEAD", "ensureRevision": false}}
[    gitserver-0] DEBUG gitserver.gRPCRequestLogger internal/server_grpc_logger.go:44 Handled ResolveRevision RPC {"server": "gitserver.v1.GitserverService", "method": "ResolveRevision", "status": "OK", "traceID": "76fa5d07df4703686a9f3e23fffeae0a", "duration": "57.67625ms", "request": {"repoName": "github.com/sourcegraph/sourcegraph", "revSpec": "HEAD", "ensureRevision": false}}
...
[    gitserver-0] DEBUG gitserver.gRPCRequestLogger internal/server_grpc_logger.go:44 Handled DiskInfo RPC {"server": "gitserver.v1.GitserverService", "method": "DiskInfo", "status": "OK", "traceID": "6aad03690ee6c6b541526e8fb1843ba0", "duration": "8.75µs", "request": "<empty>"}
[    gitserver-1] DEBUG gitserver.gRPCRequestLogger internal/server_grpc_logger.go:44 Handled DiskInfo RPC {"server": "gitserver.v1.GitserverService", "method": "DiskInfo", "status": "OK", "traceID": "6aad03690ee6c6b541526e8fb1843ba0", "duration": "25.625µs", "request": "<empty>"}

commit-id:92fb433c

mmanela

Looks good, but I have one question and comment

…ng and redaction purposes

eseliger

This seems like a useful tool for emergency cases where we have no further way to debug what's happening, nice 👍

I'm not sure how I feel yet about how verbose with a limited number of methods this already is (810loc for the logger alone, yet-another-location-to-not-forget-to-update-when-adding-an-endpoint).

If we could make this a bit more transparent I think that would be nice, and largely reusable for all our gRPC services. Using an interceptor I believe we can get duration, error, status code, and traceID generically. For the request fields, we might be able to use a similar approach I used in the transparent proxy where we could use reflection to get field names and use an annotation to mark things as PII.

But that's not a blocker for getting us a debugging tool earlier, so approved.

Left a few small suggestions inline.

eseliger · 2024-04-18T23:15:59Z

-    # visibility = ["//cmd/gitserver:__subpackages__"],
-    visibility = ["//visibility:public"],


oh weird! thx for the fix

This wasn't intentional. Just the result of running sg bazel configure

eseliger · 2024-04-18T23:16:32Z

-        # Test requires localhost database
-        "requires-network",


have we actually gotten rid of all the DB stuff in here? That'd be real nice

This wasn't intentional. Just the result of running sg bazel configure

eseliger · 2024-04-18T23:17:22Z

 	"github.com/sourcegraph/sourcegraph/lib/pointers"
 )

+var envGitserverExhaustiveLoggingEnabled = env.MustGetBool("SRC_GITSERVER_EXHAUSTIVE_LOGGING_ENABLED", false, "enable exhaustive request logging in gitserver")


can we move this to the cmd/gitserver/shared/config.go file? https://sourcegraph.sourcegraph.com/-/editor?remote_url=github.com%2Fsourcegraph%2Fsourcegraph&branch=main&file=cmd%2Fgitserver%2Fshared%2Fconfig.go&editor=VSCode&version=2.2.16&start_row=18&start_col=0&end_row=18&end_col=0

eseliger · 2024-04-18T23:35:38Z

+	start := time.Now()
+
+	defer func() {
+		elapsed := time.Since(start)
+
+		l.doLog(
+			proto.GitserverService_ResolveRevision_FullMethodName,
+			status.Code(err),
+			trace.Context(ctx).TraceID,
+			elapsed,
+
+			resolveRevisionRequestToLogFields(request)...,
+		)
+
+	}()


After having read through a lot of these now, they are all very similar and it's kind of repetitive, I wonder if we could make this a little less verbose bu doing something like

func (l *loggingGRPCServer) ResolveRevision(ctx context.Context, request *proto.ResolveRevisionRequest) (response *proto.ResolveRevisionResponse, err error) { collector := l.logCollect(ctx, proto.GitserverService_ResolveRevision_FullMethodName, &err) defer collector(resolveRevisionRequestToLogFields(request)) }

The duration tracking, status code from err, and traceID from ctx seem to always be the same.

) This PR builds on https://github.com/sourcegraph/sourcegraph/pull/61270, and adds the request logging funcionality to the repository grpc server in gitserver. ## Test plan Local testing: Ran `env SRC_GITSERVER_EXHAUSTIVE_LOGGING_ENABLED=true SRC_LOG_SCOPE_LEVEL=gitserver.gRPCRequestLogger=debug sg start` locally, and saw the following output from the logger in my terminal (note that specifically the repository service is mentioned): ``` [ gitserver-0] DEBUG gitserver.gRPCRequestLogger internal/server_grpc_logger.go:46 Handled FetchRepository RPC {"server": "gitserver.v1.GitserverRepositoryService", "method": "FetchRepository", "status": "OK", "traceID": "67f1aa837367fa7ea72b164e70a67419", "duration": "1.068438833s", "request": {"repoName": "github.com/sgtest/megarepo"}} ```

wip add logging for gitserver requests

1f67bc7

commit-id:92fb433c

cla-bot Bot added the cla-signed label Mar 19, 2024

github-actions Bot added team/product-platform team/source Tickets under the purview of Source - the one Source to graph it all labels Mar 19, 2024

ggilmore marked this pull request as draft March 19, 2024 16:28

pjlast added 3 commits March 22, 2024 11:42

More logging

c4a3041

Add experimental siteconfig for gitserver exhaustive logging

42f29eb

Add traceID to logs

cdc339b

mmanela approved these changes Mar 22, 2024

View reviewed changes

Comment thread cmd/gitserver/internal/server_grpc_logger.go

Comment thread cmd/gitserver/internal/server_grpc_logger.go Outdated

pjlast added 2 commits March 25, 2024 15:25

Don't log perforce credentials

1988e5d

Check if experimental features is nil

b6788a9

pjlast changed the title ~~wip add logging for gitserver requests~~ Add option for exhaustive gitserver logging Mar 25, 2024

pjlast reviewed Mar 25, 2024

View reviewed changes

Comment thread cmd/gitserver/internal/server_grpc_logger.go Outdated

pjlast marked this pull request as ready for review March 25, 2024 14:39

pjlast requested a review from eseliger March 25, 2024 14:39

eseliger reviewed Mar 27, 2024

View reviewed changes

ggilmore force-pushed the spr/main/92fb433c branch 2 times, most recently from 9adc726 to b6788a9 Compare April 15, 2024 19:30

ggilmore added 2 commits April 17, 2024 22:34

wip

db6c612

Merge remote-tracking branch 'origin/main' into git-log-all-methods-2

6c8f3d1

ggilmore force-pushed the spr/main/92fb433c branch from a23f5c3 to 85a61a4 Compare April 18, 2024 07:46

add support for logging get commit from binary

56c4813

ggilmore force-pushed the spr/main/92fb433c branch from 85a61a4 to 56c4813 Compare April 18, 2024 20:07

ggilmore added 3 commits April 18, 2024 13:11

Merge remote-tracking branch 'origin/main' into git-log-all-methods-2

932c982

adjust tests to make sure that all methods are fowarded properly

8120154

create custom log.Fields functions for all requests for ease of readi…

8604dd8

…ng and redaction purposes

ggilmore force-pushed the spr/main/92fb433c branch from 2c33079 to 8604dd8 Compare April 18, 2024 22:17

switch to using env var

86d0d41

ggilmore force-pushed the spr/main/92fb433c branch from 89adce0 to 86d0d41 Compare April 18, 2024 22:37

give logger its own scope

2a8f4d7

ggilmore added 2 commits April 18, 2024 15:49

ignore dep lint rule

f7ee292

changelog

e568e70

ggilmore requested review from eseliger and pjlast April 18, 2024 22:52

ggilmore added 2 commits April 18, 2024 16:14

Merge remote-tracking branch 'origin/main' into git-log-all-methods-2

ed5bf35

remove comment

b717e2a

eseliger approved these changes Apr 18, 2024

View reviewed changes

ggilmore added 3 commits April 18, 2024 21:55

move env var to shared

1097a5a

use composition instead of embedding

97875a1

Merge remote-tracking branch 'origin/main' into git-log-all-methods-2

56f5502

ggilmore force-pushed the spr/main/92fb433c branch from 8ba9ca4 to 56f5502 Compare April 22, 2024 23:09

redact gitolite host

a52ab8c

ggilmore force-pushed the spr/main/92fb433c branch from 3745840 to a52ab8c Compare April 22, 2024 23:14

fix syntax errors

f34693b

ggilmore force-pushed the spr/main/92fb433c branch from edf47f9 to f34693b Compare April 22, 2024 23:29

ggilmore added 2 commits April 22, 2024 16:38

remove duplicate env var

5ab4c52

update

16c1963

ggilmore force-pushed the spr/main/92fb433c branch from df66498 to 16c1963 Compare April 23, 2024 00:16

fix build bazel

bd2d72e

ggilmore enabled auto-merge (squash) April 23, 2024 06:40

ggilmore merged commit 92e4931 into main Apr 23, 2024

ggilmore deleted the spr/main/92fb433c branch April 23, 2024 06:41

ggilmore mentioned this pull request Apr 24, 2024

gitserver: grpc: create exhaustive logger for repository service #62158

Merged

		# visibility = ["//cmd/gitserver:__subpackages__"],
		visibility = ["//visibility:public"],

Conversation

ggilmore commented Mar 19, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Test plan

Uh oh!

mmanela left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

eseliger left a comment

Choose a reason for hiding this comment

Uh oh!

eseliger Apr 18, 2024

Choose a reason for hiding this comment

Uh oh!

ggilmore Apr 19, 2024

Choose a reason for hiding this comment

Uh oh!

eseliger Apr 18, 2024

Choose a reason for hiding this comment

Uh oh!

ggilmore Apr 19, 2024

Choose a reason for hiding this comment

Uh oh!

eseliger Apr 18, 2024

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

eseliger Apr 18, 2024

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

ggilmore commented Mar 19, 2024 •

edited

Loading