Make logs more grepable

[d-uzlov]

Overview

Right now we have automatic trace logs for network services and registries.
They have some annoying issues:

1. They use info level
2. Different requests are interleaved.

These issues make it difficult to read the logs. It's next to impossible to tell what is going on when there are even mere dozens of requests.

Solution

1. Obviously, we need to change the level for trace logs.
   The obvious choice would be trace. However, our "trace" logs are actually not so detailed. If we were to add a lot of logs inside some chain elements, then we would probably want to be able to distinguish out current trace logs from them, so maybe it would be better to log them at debug level.
2. We can add request ID into logger fields, so interleaving lines of logs can be distinguished by IDs.
   We would still have issues with multiline logs, since they only have logger fields in their first line.
   Most of our log entries are single lines, and the vast majority of multiline entries are stack traces from errors, so this is not a big problem.

The size increase due to adding ID to each line is minor, in comparison to our current logs size. However, we would be able to use, for example, grep 9763b41a-2ff6-40e3-8475-7d9dae986f13, to reduce the big log file to only the important part.

Implementation

1. The log level for traces is set here:
   

   sdk/pkg/tools/log/logruslogger/logruslogger.go

   Line 217 in d4734b5

   s.entry.Infof("%v%s⎆ %v()%v", s.info.incInfo(), prefix, s.operation, s.getSpan())

2. We can add field into the context here, using log.WithFields (same for other trace elements):
   

   sdk/pkg/networkservice/core/trace/server.go

   Line 75 in d4734b5

   ctx, finish := withLog(ctx, operation)

[d-uzlov]

I have actually already implemented it locally for debugging of heal issues found during scalability testing. It helps a lot.

[denis-tingaikin]

@d-uzlov Be free to open PR!

[edwarnicke]

Obviously, we need to change the level for trace logs.
The obvious choice would be trace. However, our "trace" logs are actually not so detailed. If we were to add a lot of logs inside some chain elements, then we would probably want to be able to distinguish out current trace logs from them, so maybe it would be better to log them at debug level.

As a side note, in the sdk-vpp code, I do my internal logs at debug level. That isn't a commentary on what they should be ... just what they are. It can be changed if need be.

[edwarnicke]

We can add request ID into logger fields, so interleaving lines of logs can be distinguished by IDs.
We would still have issues with multiline logs, since they only have logger fields in their first line.
Most of our log entries are single lines, and the vast majority of multiline entries are stack traces from errors, so this is not a big problem.

I like this idea very much... but there's one practical corner case... what do we do in the case where we haven't got a Connection ID yet? I suspect this is quite solvable... but will need to be solved :)

[d-uzlov]

I like this idea very much... but there's one practical corner case... what do we do in the case where we haven't got a Connection ID yet? I suspect this is quite solvable... but will need to be solved :)

When I was doing my testing, I was getting connection ID in 2 ways:

1. When I know that something went wrong on a certain pod, I can search for the pod name and find connection path information containing this pod name. The easiest place for it would actually be the diff of the first request, where we change connection path, and that change is logged.
2. When there is an error in the logs (or just any message we are concerned of), the error line contains connection id, and then I can use grep to see the full history of what happened with the related connection.

[denis-tingaikin]

PR #1012 is not looking great for us and we want to consider a list of improvements for logs in term of the issue.

[Mixaster995]

List of PR's to all cmd, allowing usage of log level env variable

• Added config option for log level cmd-exclude-prefixes-k8s#57
• Added config option for log level cmd-forwarder-ovs#23
• Added config option for log level cmd-forwarder-sriov#311
• Added config option for log level cmd-map-ip-k8s#15
• Added config option for log level cmd-nsc#289
• Added config option for log level cmd-nsc-init#217
• Added config option for log level cmd-nsc-vpp#259
• Added config option for log level cmd-nse-firewall-vpp#78
• Added config option for log level cmd-nse-icmp-responder#306
• Added config option for log level cmd-nsmgr#382
• Added config option for log level cmd-nse-supplier-k8s#91
• Added config option for log level cmd-nse-vfio#241
• Added config option for log level cmd-registry-k8s#213
• Added config option for log level cmd-registry-memory#410
• Added config option for log level cmd-admission-webhook-k8s#23
• Added config option for log level cmd-nse-icmp-responder-vpp#252
• Added config option for log level cmd-registry-proxy-dns#393
• Added config option for log level cmd-nsmgr-proxy#228

[denis-tingaikin]

@edwarnicke Finally, all PRs are merged!

@Mixaster995 Thanks!