Structured logging for indexserver using sourcegraph/log

[gl-srgr]

UPDATE: Go 1.18 is required in sourcegraph/log go.mod and four days ago we rolled back zoekt from 1.18 to 1.17 in this PR. We'll leave this open until the go version is upgraded to 1.18

---

Utilize sourcegraph/log for structured logging of two zoekt-sourcegraph-indexserver calls: git fetch and indexing job duration.

Issue https://github.com/sourcegraph/sourcegraph/issues/34951

The currently logged messages provide accurate values re: duration of the aforementioned operations but the messages are not as easy to parse for the relevant data. A structured log message can provide fields and nested attributes/objects within. In this PR to reduce scope we are only implementing the new message log approach for only two calls in zoekt-sourcegraph-indexserver which help evaluate performance of incremental indexing zoekt effort.

One challenge encountered in this PR is that we have a debug flag for zoekt-sourcegraph-indexserver:

1. The sourcegraph/log logger uses the environment variable to determine logging level at the time of initialization.
2. Logging level can only increase level after initialization e.g. initialize with Info, then later obtain a logger with Warn or Error level (debug would not be allowed though)

Considering the above, if the debug flag is enabled and the environment level is a logging level higher than debug then we will:

1. update the environment variable before initialization to debug
2. Init() the logger
3. revert the environment variable to its original value.

To accomplish this we also split ParseAndRun() into two calls so that the debug flag is available to us. This split is pretty common and shouldn't impact us. Also suggested by pkg.go.dev: "ParseAndRun can also be split into distinct Parse and Run phases, allowing you to perform two-phase setup or initialization of e.g. API clients that require user-supplied configuration."

---

The previous PR 355 for the aforementioned Issue 34951 will be closed and we'll proceed with this PR for this effort.

[gl-srgr]

Here are the messages in the new output format, with two repos indexed. Note the Resource changes based on repo but Scope stays the same.

{"SeverityText":"INFO","Timestamp":1655321133882789000,"InstrumentationScope":"zoekt-sourcegraph-indexserver","Caller":"zoekt-sourcegraph-indexserver/main.go:407","Function":"main.(*Server).Run","Body":"updated index","Resource":{"service.name":"zoekt-sourcegraph-indexserver","service.version":"a825d4bd1fe50294973d147c7ff0fb5ecaef8f73","service.instance.id":"MacBook-Pro.local"},"Attributes":{"repo":"git220614","id":754935985,"branches":["HEAD=034225c9c6f4dba32ee9eab817663663b28fb347"],"duration":0.388097375}}

{"SeverityText":"INFO","Timestamp":1655321134211092000,"InstrumentationScope":"zoekt-sourcegraph-indexserver","Caller":"zoekt-sourcegraph-indexserver/main.go:407","Function":"main.(*Server).Run","Body":"updated index","Resource":{"service.name":"zoekt-sourcegraph-indexserver","service.version":"a825d4bd1fe50294973d147c7ff0fb5ecaef8f73","service.instance.id":"MacBook-Pro.local"},"Attributes":{"repo":"newgit220521","id":475511032,"branches":["HEAD=19e58456817413eaee1cbceac6791f5d5785d62b"],"duration":0.328216625}}

{"SeverityText":"DEBUG","Timestamp":1655321133634280000,"InstrumentationScope":"zoekt-sourcegraph-indexserver","Caller":"zoekt-sourcegraph-indexserver/index.go:274","Function":"main.gitIndex","Body":"successfully fetched git data","Resource":{"service.name":"zoekt-sourcegraph-indexserver","service.version":"a825d4bd1fe50294973d147c7ff0fb5ecaef8f73","service.instance.id":"MacBook-Pro.local"},"Attributes":{"repo":"git220614","id":754935985,"commits_count":1,"duration":0.091539792}}

{"SeverityText":"DEBUG","Timestamp":1655321133983635000,"InstrumentationScope":"zoekt-sourcegraph-indexserver","Caller":"zoekt-sourcegraph-indexserver/index.go:274","Function":"main.gitIndex","Body":"successfully fetched git data","Resource":{"service.name":"zoekt-sourcegraph-indexserver","service.version":"a825d4bd1fe50294973d147c7ff0fb5ecaef8f73","service.instance.id":"MacBook-Pro.local"},"Attributes":{"repo":"newgit220521","id":475511032,"commits_count":1,"duration":0.080913917}}

[gl-srgr]

Updated PR description and will also add PR comments to the code after the recent push. If debug flag is included AND is set to true then we overwrite the environment variable just for logger Init(), and revert after Init(). This requires splitting parseAndRun() into separate calls since we need access to the flags.

Alternatively we could just read the os.Args but I'd prefer to use a parsed version of the args/flags. The Run() command uses rootConfig which AFAIK is not accessible from Main(). rootConfig does appear to be overwritten by the parsed arguments that populate FlagSet, which is why I decided to iterate over FlagSet with Visit().

[gl-srgr]

Note that for the current debug logger if debug=false then it outputs nothing, regardless of the value of SRC_LOG_LEVEL env var. This is because the debug logger is its own entity and debug=false will prevent this block from changing the logger to output message logs.

The new logger is different in that if debug=false then we rely on the value of the SRC_LOG_LEVEL env variable, which could be set to "debug"

[keegancsmith]

@gl-srgr what is the state of this PR? FYI we are back on 1.18 for now. This may change, so I sent this PR to log to ensure we continue to work on 1.17 with the log library https://github.com/sourcegraph/log/pull/11. So we should be able to move forward. Ready for more review?

[gl-srgr]

@keegancsmith Thanks for having the go version modified for sourcegraph/log. I've just pushed some commits and the checks pass now. go.mod has the recent version / commit for sourcegraph/log now. So this PR is good to go for moving forward with further code review

[keegancsmith]

FYI I introduced sourcegraph/log for zoekt-webserver here https://github.com/sourcegraph/zoekt/pull/411. It should be rather minimal to introduce to indexserver based on that PR.