Add access log gRPC interceptor & Update observability features #852

rinx · 2020-11-19T09:00:55Z

Description:

Changes

Add access log gRPC interceptor
- Add internal/net/grpc/interceptor/server/logging package
- By appending "AccessLogInterceptor" to server_config.servers.grpc.server.grpc.interceptors field in config.yaml, it will be enabled.

{"level":"info","ts":1606366367.1742995,"msg":"rpc completed","details":{"grpc":{"kind":"unary","service":"core.Agent","method":"IndexInfo"},"startTime":1606366367.1742105,"latency":0.0000113,"traceID":"bd2375a0b3aa4a2607d042416c56420d"}}

Add zap logger
- it is better JSON formatting than the existing logging library.
Update Grafana dashboards
Add values-observability-demo.yaml to charts/vald

Known problem

when logger=glg and format=raw, it cannot print a valid structured log. please use zap instead or disable AccessLogInterceptor.

2020-11-26 04:50:33     [INFO]: rpc completed &{0xc00024cc30 1.6063662337968597e+09 1.45e-05 86c42bd1164bf434f95b3f51f9d5b755 <nil>}

Related Issue:

nothing

How Has This Been Tested?:

nothing

Environment:

Go Version: 1.15.2
Docker Version: 19.03.8
Kubernetes Version: 1.18.2
NGT Version: 1.12.1

Types of changes:

Bug fix [type/bug]
New feature [type/feature]
Add tests [type/test]
Security related changes [type/security]
Add documents [type/documentation]
Refactoring [type/refactoring]
Update dependencies [type/dependency]
Update benchmarks and performances [type/bench]
Update CI [type/ci]

Changes to Core Features:

Have you added an explanation of what your changes do and why you'd like us to include them?
Have you written new tests for your core changes, as applicable?
Have you successfully ran tests with your changes locally?

Checklist:

I have read the CONTRIBUTING document.
I have checked open Pull Requests for the similar feature or fixes?
I have added tests and benchmarks to cover my changes.
I have ensured all new and existing tests passed.
I have commented my code, particularly in hard-to-understand areas
I have updated the documentation accordingly.

vdaas-ci · 2020-11-19T09:02:15Z

[CHATOPS:HELP] ChatOps commands.

🙆‍♀️ /approve - approve
💌 /changelog - add changelog comment
🍱 /format - format codes and add licenses
✅ /gen-test - generate test codes
🏷️ /label - add labels
⏪ /rebase - rebase master

codecov · 2020-11-19T09:09:27Z

Codecov Report

Merging #852 (3e558e5) into master (7a78959) will increase coverage by 0.11%.
The diff coverage is 77.57%.

@@            Coverage Diff             @@
##           master     #852      +/-   ##
==========================================
+ Coverage   15.93%   16.05%   +0.11%     
==========================================
  Files         474      475       +1     
  Lines       23693    23786      +93     
==========================================
+ Hits         3776     3818      +42     
- Misses      19680    19722      +42     
- Partials      237      246       +9

Impacted Files	Coverage Δ
internal/log/format/format.go	`100.00% <ø> (ø)`
internal/log/logger/type.go	`100.00% <ø> (ø)`
...ternal/observability/metrics/agent/core/ngt/ngt.go	`0.00% <0.00%> (ø)`
internal/log/zap/zap.go	`94.20% <94.20%> (ø)`
internal/log/zap/option.go	`100.00% <100.00%> (ø)`
internal/servers/server/option.go	`95.55% <100.00%> (+0.20%)`	⬆️
internal/db/storage/blob/s3/reader/reader.go	`63.04% <0.00%> (-31.53%)`	⬇️
internal/worker/queue.go	`95.00% <0.00%> (-3.34%)`	⬇️
internal/log/option.go
... and 2 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update e1941bd...3e558e5. Read the comment docs.

internal/log/zap/zap.go

github-actions · 2020-11-26T06:21:48Z

internal/log/zap/zap.go

+import (
+	"github.com/vdaas/vald/internal/log/format"
+	"github.com/vdaas/vald/internal/log/level"
+


[golangci] _{reported by reviewdog 🐶}
File is not gci-ed (gci)

github-actions · 2020-11-26T06:21:48Z

internal/log/zap/option.go

+type Option func(l *logger)
+
+var (
+	defaultOpts = []Option{


[golangci] _{reported by reviewdog 🐶}
defaultOpts is a global variable (gochecknoglobals)

github-actions · 2020-11-26T06:21:48Z

internal/log/zap/zap.go

+)
+
+var (
+	zapcore_NewConsoleEncoder = zapcore.NewConsoleEncoder


[golangci] _{reported by reviewdog 🐶}
zapcore_NewConsoleEncoder is a global variable (gochecknoglobals)

github-actions · 2020-11-26T06:21:48Z

internal/log/zap/zap.go

+
+var (
+	zapcore_NewConsoleEncoder = zapcore.NewConsoleEncoder
+	zapcore_NewJSONEncoder    = zapcore.NewJSONEncoder


[golangci] _{reported by reviewdog 🐶}
zapcore_NewJSONEncoder is a global variable (gochecknoglobals)

github-actions · 2020-11-26T06:21:49Z

internal/log/zap/option.go

@@ -0,0 +1,56 @@
+//


[golangci] _{reported by reviewdog 🐶}
package comment should be of the form "Package zap ..." (golint)

github-actions · 2020-11-26T06:21:49Z

internal/log/zap/zap.go

@@ -0,0 +1,189 @@
+//


[golangci] _{reported by reviewdog 🐶}
package comment should be of the form "Package zap ..." (golint)

github-actions · 2020-11-26T06:21:49Z

internal/log/zap/zap.go

+}
+
+// New returns a new logger instance.
+func New(opts ...Option) (*logger, error) {


[golangci] _{reported by reviewdog 🐶}
exported func New returns unexported type *github.com/vdaas/vald/internal/log/zap.logger, which can be annoying to use (golint)

github-actions · 2020-11-26T06:21:49Z

internal/log/zap/zap.go

+// New returns a new logger instance.
+func New(opts ...Option) (*logger, error) {
+	l := new(logger)
+	for _, opt := range append(defaultOpts, opts...) {


[golangci] _{reported by reviewdog 🐶}
ranges should only be cuddled with assignments used in the iteration (wsl)

github-actions · 2020-11-26T06:21:49Z

internal/log/zap/option_test.go

+// See the License for the specific language governing permissions and
+// limitations under the License.
+//
+package zap


[golangci] _{reported by reviewdog 🐶}
package should be zap_test instead of zap (testpackage)

github-actions · 2020-11-26T06:21:50Z

internal/log/zap/zap_test.go

+// See the License for the specific language governing permissions and
+// limitations under the License.
+//
+package zap


[golangci] _{reported by reviewdog 🐶}
package should be zap_test instead of zap (testpackage)

kpango · 2021-01-20T06:58:24Z

internal/log/zap/zap.go

+	l.logger = zap.New(core, opts...)
+
+	l.sugar = l.logger.Sugar()


I think we should be define finelizer for logger & sugar.
zap has internal buffering we should call .Sync() method when application exits

FYI: https://pkg.go.dev/go.uber.org/zap#Logger.Sync
https://pkg.go.dev/go.uber.org/zap#SugaredLogger.Sync

internal/net/grpc/interceptor/server/logging/accesslog.go

Signed-off-by: Rintaro Okamura <[email protected]> :white_check_mark: fix tests for logger type, format Signed-off-by: Rintaro Okamura <[email protected]>

Signed-off-by: Rintaro Okamura <[email protected]>

kpango · 2021-01-20T07:16:05Z

internal/net/grpc/interceptor/server/logging/accesslog.go

+
+		resp, err = handler(ctx, req)
+
+		latency := float64(time.Since(start)) / float64(time.Second)


I think it would be better to store time as unix nano second scale.
then we can calculate it on the monitoring query

okay i'll revise it.

Signed-off-by: Rintaro Okamura <[email protected]> :wrench: update Grafana dashboards & Prometheus config Signed-off-by: Rintaro Okamura <[email protected]> :pencil2: Use same rule for task naming Signed-off-by: Rintaro Okamura <[email protected]>

Signed-off-by: Rintaro Okamura <[email protected]>

kpango

Others LGTM

internal/net/grpc/interceptor/server/logging/accesslog.go

kpango · 2021-01-20T07:18:32Z

internal/net/grpc/interceptor/server/logging/accesslog.go

+			entity.Error = err
+			log.Error("rpc completed", entity)
+		} else {
+			log.Info("rpc completed", entity)


I think debug is better

AccessLogInterceptor is disabled by default, so i think it is okay to use Info level here.
I think it is too many logs when turning on Debug logs (such as Agent's CreateIndex operation log). it is better to put access logs in different level compared to them.

If there is a lot of access, it will be difficult to get other Info logs according to the number of accesses, so I think this Interceptor is used for Debug, I think Debug is fine.

The Info log should contain more important information, and I think it is too much to output every successful access.

The users of this AccessLogInterceptor will use Loki or something to query the aggregated logs. so there's no problem if there is a lot of accesses.
If access logs is Debug level, it is bigger problem that meaningless Debug level logs require large storage capacity to store them.

Also I think it is correct according to contributing guide. https://github.com/vdaas/vald/blob/master/docs/contributing/coding-style.md#logging

hmm, but I'd like to divide trace log and Info log, so how about make new log level called TRACE?

kpango · 2021-01-20T07:20:40Z

internal/net/grpc/interceptor/server/logging/accesslog.go

+
+		if err != nil {
+			entity.Error = err
+			log.Error("rpc completed", entity)


may be you want print entity on error log right?
so, entity print should be %#v print pragma because of entity is pointer type , error log will show thier address only...

We should use log.Error instead of log.Errorf here because Zap logger prints the second argument as the "details" field.
https://pkg.go.dev/go.uber.org/zap#Logger.Info
Please see the description of this PR. There's an example.

So you know, there's a known problem (as described in the description) when using Glg logger.

Since the log.Error interface is independent of zap, it should not be implemented to work only with zap.
Even if we specify a standard Go logger here, if the group of arguments is the same interface, the address will be displayed as in Glg.
I think it would be more appropriate to consider a more explicit Print method, but I'm not sure.

hmm...
I don't know how to print correctly structured JSON logs with that format without using log.Error.
Okay, I'll close this PR.

wait, you don't need to close this pr.
let's discuss about it.

this pr feature is really effective.

Signed-off-by: Rintaro Okamura <[email protected]>

rinx added the status/draft label Nov 19, 2020

github-actions bot added area/agent/core area/internal size/L type/feature New feature priority/medium labels Nov 19, 2020

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch from 1663540 to f7dcc29 Compare November 25, 2020 01:13

github-actions bot added team/set SET team size/XL and removed size/L labels Nov 25, 2020

github-actions bot reviewed Nov 25, 2020

View reviewed changes

internal/log/zap/zap.go Show resolved Hide resolved

internal/log/zap/zap.go Show resolved Hide resolved

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch from f7dcc29 to a2329f0 Compare November 25, 2020 01:23

github-actions bot reviewed Nov 25, 2020

View reviewed changes

internal/log/zap/zap.go Show resolved Hide resolved

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch from a2329f0 to 55b731a Compare November 25, 2020 08:35

github-actions bot added size/XXL and removed size/XL labels Nov 25, 2020

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch 3 times, most recently from 13f0884 to eb7a89f Compare November 26, 2020 02:47

github-actions bot added the area/helm label Nov 26, 2020

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch 2 times, most recently from 89771b9 to 1444329 Compare November 26, 2020 06:16

github-actions bot reviewed Nov 26, 2020

View reviewed changes

github-actions bot added area/makefile team/sre SRE team size/XXXL and removed size/XXL labels Dec 2, 2020

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch from 0402bb6 to 1f66615 Compare December 8, 2020 08:31

rinx marked this pull request as draft January 12, 2021 07:11

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch from f699079 to ee598eb Compare January 20, 2021 04:29

rinx marked this pull request as ready for review January 20, 2021 04:39

rinx requested review from hlts2 and kpango January 20, 2021 04:39

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch from ad99d8b to df36f12 Compare January 20, 2021 06:31

kpango reviewed Jan 20, 2021

View reviewed changes

internal/net/grpc/interceptor/server/logging/accesslog.go Outdated Show resolved Hide resolved

rinx added 8 commits January 20, 2021 16:12

🚸 Comment out unusable logtype and logformat

c837905

Signed-off-by: Rintaro Okamura <[email protected]> :white_check_mark: fix tests for logger type, format Signed-off-by: Rintaro Okamura <[email protected]>

➕ add zap logger

daa93e0

Signed-off-by: Rintaro Okamura <[email protected]>

✅ add zap tests

baa2418

Signed-off-by: Rintaro Okamura <[email protected]>

✨ add AccessLogInterceptor (UnaryInterceptor)

5409776

Signed-off-by: Rintaro Okamura <[email protected]>

✨ add AccessLogStreamInterceptor (StreamInterceptor)

4e8eb93

Signed-off-by: Rintaro Okamura <[email protected]>

🔧 add AccessLogInterceptor to grpc server config

ffcdf0c

Signed-off-by: Rintaro Okamura <[email protected]>

✅ add test for WithGRPCInterceptors function using AccessLogInterceptor

6dc454a

Signed-off-by: Rintaro Okamura <[email protected]>

🔧 fix validator for defaults.logging.logger

08c3ab0

Signed-off-by: Rintaro Okamura <[email protected]>

kpango reviewed Jan 20, 2021

View reviewed changes

rinx added 5 commits January 20, 2021 16:18

🔧 Add loki & tempo k8s manifests

996d886

Signed-off-by: Rintaro Okamura <[email protected]> :wrench: update Grafana dashboards & Prometheus config Signed-off-by: Rintaro Okamura <[email protected]> :pencil2: Use same rule for task naming Signed-off-by: Rintaro Okamura <[email protected]>

🔧 Add observability demo values

6537069

Signed-off-by: Rintaro Okamura <[email protected]>

🚚 Rename NGT metrics names

b072230

📄 Update license header

23d84a9

Signed-off-by: Rintaro Okamura <[email protected]>

🔧 Update demo values

2a482da

Signed-off-by: Rintaro Okamura <[email protected]>

kpango requested changes Jan 20, 2021

View reviewed changes

rinx added 2 commits January 20, 2021 16:23

💄 Rename access log entity name

1adde94

Signed-off-by: Rintaro Okamura <[email protected]>

🚨 Revise to use const for grpc kind values

3e558e5

Signed-off-by: Rintaro Okamura <[email protected]>

rinx force-pushed the feature/internal/add-access-log-grpc-interceptor branch from df36f12 to 3e558e5 Compare January 20, 2021 07:25

rinx closed this Jan 20, 2021

This was referenced Jan 20, 2021

Update Grafana dashboards #940

Merged

Add Zap logger and access log interceptor #944

Merged

kpango deleted the feature/internal/add-access-log-grpc-interceptor branch February 23, 2021 08:59

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add access log gRPC interceptor & Update observability features #852

Add access log gRPC interceptor & Update observability features #852

rinx commented Nov 19, 2020 •

edited

Loading

vdaas-ci commented Nov 19, 2020

codecov bot commented Nov 19, 2020 •

edited

Loading

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

github-actions bot Nov 26, 2020

kpango Jan 20, 2021

kpango Jan 20, 2021

kpango Jan 20, 2021

rinx Jan 20, 2021

kpango Jan 20, 2021

kpango left a comment

kpango Jan 20, 2021

rinx Jan 20, 2021

kpango Jan 20, 2021

rinx Jan 20, 2021

kpango Jan 20, 2021

kpango Jan 20, 2021

rinx Jan 20, 2021

kpango Jan 20, 2021

rinx Jan 20, 2021

kpango Jan 20, 2021


		resp, err = handler(ctx, req)

		latency := float64(time.Since(start)) / float64(time.Second)

Add access log gRPC interceptor & Update observability features #852

Add access log gRPC interceptor & Update observability features #852

Conversation

rinx commented Nov 19, 2020 • edited Loading

Description:

Changes

Known problem

Related Issue:

How Has This Been Tested?:

Environment:

Types of changes:

Changes to Core Features:

Checklist:

vdaas-ci commented Nov 19, 2020

codecov bot commented Nov 19, 2020 • edited Loading

Codecov Report

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

github-actions bot Nov 26, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kpango left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rinx commented Nov 19, 2020 •

edited

Loading

codecov bot commented Nov 19, 2020 •

edited

Loading