如何自訂支援如asynq gRPC: 实现分布式日志跟踪?

[linchao0815]

Q1:我有使用 https://github.com/hibiken/asynq 這個套件, 將task 拆分, 造成中斷而無法使用jaeger將後續利用asynq 的task 連結, 請問要如何修改, 我要如何使用將TraceId手動設定到ctx ?我使用rkgrpcctx.AddHeaderToClient(ctx, rkmid.HeaderTraceId, traceId)

Q2: client 二個相依的Grpc call, 如何讓此二個在jaeger中相關(trace Id相同)?

[dongxuny]

@linchao0815 这个场景还没有研究过，我先研究一下具体用法，然后尽快给出一个方案

[dongxuny]

@linchao0815 Hi

Q1: 我这里写了一个 Demo 程序，可以参考一下。
实现的逻辑是这样的。因为没有办法把 context 传递给 asynq worker，所以，只能把 trace metadata 放在 task payload 里。
Demo 程序里的办法是，Task 里定义一个 TraceHeader http.Header，然后，把 gRPC context 里的 Trace metadata Copy 到 里面。worker server 里添加一个 middleware，让 middleware 读出 trace metadata，然后，创建一个 span，并且上报到 jaeger。

Demo: https://github.com/rookie-ninja/rk-demo/tree/master/grpc/v2/asynq-jaeger

Q2: 这里是两个 grpc server 相互之间 share same traceId 的 Demo 程序。
Demo: https://github.com/rookie-ninja/rk-demo/tree/master/grpc/v2/distributed-log

[linchao0815]

@dongxuny 非常感謝您的幫助,目前我在測試Q1的回應sample code
Q1.1 由於我們將grpc 和asynq work 實作在同一個server中, 想請問worker 用到的trace.yaml要如何直接使用grpc-server.yaml的定義? 如何不用另外定義trace.yaml?
Q1.2 若我在woker 的task 中再呼叫其它的fun, 若也要使用jager 追蹤再呼叫的fun該如何實作?

[linchao0815]

@dongxuny Q2 問題我重新描述,client A是使用http , server B使用grpc , server B如何回應traceId不定義在proto中而附加在http resopnse中, client A第二個request 再利用http headher帶入traceId給sever B,而使jaeger追踨這三個以上的API ?

[dongxuny]

@dongxuny 非常感謝您的幫助,目前我在測試Q1的回應sample code Q1.1 由於我們將grpc 和asynq work 實作在同一個server中, 想請問worker 用到的trace.yaml要如何直接使用grpc-server.yaml的定義? 如何不用另外定義trace.yaml? Q1.2 若我在woker 的task 中再呼叫其它的fun, 若也要使用jager 追蹤再呼叫的fun該如何實作?

用同一个 YAML 这个没问题，我把例子改一下。呼叫其他 Func 原理上一样，我在例子上也加一下，应该就能比较清晰。

[dongxuny]

@dongxuny Q2 問題我重新描述,client A是使用http , server B使用grpc , server B如何回應traceId不定義在proto中而附加在http resopnse中, client A第二個request 再利用http headher帶入traceId給sever B,而使jaeger追踨這三個以上的API ?

场景清楚了，我重新整理一下例子吧，这个在现在的 rk-boot 里可以实现。

[dongxuny]

@dongxuny Q2 問題我重新描述,client A是使用http , server B使用grpc , server B如何回應traceId不定義在proto中而附加在http resopnse中, client A第二個request 再利用http headher帶入traceId給sever B,而使jaeger追踨這三個以上的API ?

@linchao0815 根据我理解的场景，重新上传了例子，可以参考一下。如果希望 http-server 不创建 trace，而使用 grpc-server 产生的 trace，场景会略有不同，不过还是建议 http-server 创建 trace，跟例子里一样。

https://github.com/rookie-ninja/rk-demo/tree/master/grpc/v2/distributed-log

[dongxuny]

@dongxuny 非常感謝您的幫助,目前我在測試Q1的回應sample code Q1.1 由於我們將grpc 和asynq work 實作在同一個server中, 想請問worker 用到的trace.yaml要如何直接使用grpc-server.yaml的定義? 如何不用另外定義trace.yaml? Q1.2 若我在woker 的task 中再呼叫其它的fun, 若也要使用jager 追蹤再呼叫的fun該如何實作?

@linchao0815 根据需求，更新了例子，参考一下～
https://github.com/rookie-ninja/rk-demo/tree/master/grpc/v2/asynq-jaeger

[linchao0815]

@dongxuny 我試著利用您的二個例子組合我的需求,但遇到問題,
https://github.com/linchao0815/grpc_asynq.git
請參如上 grpc-serverA.go Login(), task.HandleDemoTask() ,在執行 go run httpclient.go 並無法在jaeger中有正確追蹤
我希望在jaeger enqueue -> Login 都可以在jaeger中看到相關

[dongxuny]

@linchao0815 我会 Fork 你的例子，然后做一些修改。

在执行 go run httpclient.go 的时候开始，就生成一个 Trace，然后进行追踪。

[dongxuny]

@linchao0815 这里是我 Fork 了你的项目之后，做的修改，可以参考一下。

https://github.com/dongxuny/grpc_asynq

效果如下图：

[linchao0815]

@dongxuny 感謝您的快速回應
可以麻煩在httpclient.go 提供
send("http://localhost:2008/v1/enqueue", {""})
接收回應取得tracieID, 再次呼叫send("http://localhost:2008/v1/enqueue", {""})
而在jager中能看到二個相依的enqueue->enqueue

[dongxuny]

@linchao0815 根据描述，更新了例子。https://github.com/dongxuny/grpc_asynq

新的例子里，发送 second-enqueue 之前，不会等待 first-enqueue Task 结束。TraceID 在整个生命周期里是唯一的，span.SpanContext().TraceID().String() 这个函数可以在任何地方得到一摸一样的 TraceID。

[linchao0815]

@dongxuny 我參考您的範例試著修改要整合到我的專案,但遇到底層一些panic,我再修改https://github.com/linchao0815/grpc_asynq 模擬, 我有使用https://github.com/linchao0815/protoc-gen-go-asynqgen 來將asynq做類似proto-go 輸出框架,將需要呼叫span相關再gen code中實作,而不在實作API中每個地方都要再呼叫span
另UnaryInterceptor/grpc.UnaryClientInterceptor 也做每個API 收到/送出 時處理span
我試了幾天還是無法解決painc, 我對於何時該處理span由於有太多種方式,一直無法理解XD
麻煩大神協助!

[dongxuny]

@linchao0815 好的，我先了解一下 https://github.com/linchao0815/protoc-gen-go-asynqgen，然后，试一下。

[dongxuny]

@linchao0815 按照你的思路改了一下 protoc-gen-go-asynqgen
代码逻辑解释起来有些复杂，简单来说：把 Trace 信息复制过来，复制过去的过程。可以参考一下例子。

这是应用例子：https://github.com/dongxuny/grpc_asynq

[linchao0815]

感謝 大神幫忙!

[linchao0815]

@dongxuny 請問在trace中的 ignore: ["/v1/CreateUser"] ,我設定但無效, jaeger中還是會看到

app:
name: rk
grpc:

• name: userServer
  enabled: true
  port: 2008
  enableReflection: true
  enableRkGwOption: true
  sw:
  enabled: true
  path: "sw"
  jsonPath: "api/gen/v1"
  middleware:
  trace:
  enabled: true
  ignore: ["/v1/CreateUser"]
  exporter:
  jaeger:
  agent:
  enabled: false
  collector:
  enabled: true

[dongxuny]

@linchao0815 grpc 里 ignore 应该用 grpc 的Path，我给你个例子吧。

[dongxuny]

@linchao0815 这是 ignore 日志的例子，trace 的 ignore 也一样。

https://github.com/rookie-ninja/rk-demo/tree/master/grpc/v2/ignore-middleware

gRPC 得用 gRPC 的 Path。

[linchao0815]

@dongxuny
我加到
trace:
ignore:
我只是不想log到 jaeger ,但還是希望可以呼叫此api,但加了會出現以下錯誤
{"error":{"code":500,"status":"Internal Server Error","message":"runtime error: invalid memory address or nil pointer dereference","details":[]}}

雖然加到
logging:
ignore:
不會有上面錯誤, 但jaeger中還是會看到, 因為服務上k8s 使用ingress 會一直被呼叫healthcheck,不想在jaeger一直看到healthcheck

[dongxuny]

@linchao0815 ignore 只会忽略 jaeger，不会影响 API 的调用。你的这个错误是从哪里出来的？有全部的 Stack trace 吗？
或者把你的 boot.yaml 配置发一下。

[dongxuny]

@linchao0815 我重新写了个 trace ignore 的例子，可以对比一下哈。

https://github.com/rookie-ninja/rk-demo/tree/master/grpc/v2/ignore-middleware

[linchao0815]

@linchao0815 ignore 只会忽略 jaeger，不会影响 API 的调用。你的这个错误是从哪里出来的？有全部的 Stack trace 吗？ 或者把你的 boot.yaml 配置发一下。

@dongxuny 請參考以下範例
https://github.com/linchao0815/grpc_asynq.git

$ go run user-server.go
$ curl localhost:2008/HealthCheck

就會出現以下

2022-10-20T13:58:42.210+0800 ERROR panic/interceptor.go:42 panic occurs:
goroutine 45 [running]:
runtime/debug.Stack()
C:/Program Files/Go/src/runtime/debug/stack.go:24 +0x65
github.com/rookie-ninja/rk-grpc/v2/middleware/panic.UnaryServerInterceptor.func1.1()
C:/Users/linchao/go/pkg/mod/github.com/rookie-ninja/rk-grpc/[email protected]/middleware/panic/interceptor.go:42 +0x208
panic({0xc37fe0, 0xef92e0})
C:/Program Files/Go/src/runtime/panic.go:838 +0x207
context.WithValue({0x0?, 0x0?}, {0xc367e0?, 0xef90f8?}, {0xd3a3a0?, 0x155fdf8?})
C:/Program Files/Go/src/context/context.go:525 +0x178
go.opentelemetry.io/otel/trace.ContextWithSpan(...)
C:/Users/linchao/go/pkg/mod/go.opentelemetry.io/otel/[email protected]/context.go:25
go.opentelemetry.io/otel/trace.noopTracer.Start({}, {0x0, 0x0}, {0xc0001afd70?, 0x0?}, {0xb?, 0xc0001ecd00?, 0x30e287?})
C:/Users/linchao/go/pkg/mod/go.opentelemetry.io/otel/[email protected]/noop.go:53 +0x7c
github.com/rookie-ninja/rk-grpc/v2/middleware/context.GetTraceSpan({0x0, 0x0})
C:/Users/linchao/go/pkg/mod/github.com/rookie-ninja/rk-grpc/[email protected]/middleware/context/context.go:162 +0x7a
github.com/rookie-ninja/rk-demo/grpcInterceptor.UnaryInterceptor({0x0, 0x0}, {0xce4700, 0xc0001afb00}, 0xc00021e300?, 0xc000010258?)
S:/NFT/test/grpc_asynq/grpcInterceptor/grpcInterceptor.go:19 +0xe5
google.golang.org/grpc.chainUnaryInterceptors.func1.1({0x0?, 0x0?}, {0xce4700?, 0xc0001afb00?})
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:1129 +0x5b
github.com/rookie-ninja/rk-grpc/v2/middleware/tracing.UnaryServerInterceptor.func1({0xf05328?, 0xc0001afb60?}, {0xce4700, 0xc0001afb00}, 0xc000512300, 0xc000012200)
C:/Users/linchao/go/pkg/mod/github.com/rookie-ninja/rk-grpc/[email protected]/middleware/tracing/server_interceptor.go:54 +0x794
google.golang.org/grpc.chainUnaryInterceptors.func1.1({0xf05328?, 0xc0001afb60?}, {0xce4700?, 0xc0001afb00?})
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:1132 +0x83
github.com/rookie-ninja/rk-grpc/v2/middleware/panic.UnaryServerInterceptor.func1({0xf05328?, 0xc0001afb60?}, {0xce4700, 0xc0001afb00}, 0xc0f0e0?, 0xc000012200)
C:/Users/linchao/go/pkg/mod/github.com/rookie-ninja/rk-grpc/[email protected]/middleware/panic/interceptor.go:46 +0x19e
google.golang.org/grpc.chainUnaryInterceptors.func1.1({0xf05328?, 0xc0001afb60?}, {0xce4700?, 0xc0001afb00?})
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:1132 +0x83
github.com/rookie-ninja/rk-grpc/v2/middleware/log.UnaryServerInterceptor.func1({0xf05328?, 0xc0001afad0?}, {0xce4700, 0xc0001afb00}, 0xc000512300, 0xc000012200)
C:/Users/linchao/go/pkg/mod/github.com/rookie-ninja/rk-grpc/[email protected]/middleware/log/server_interceptor.go:54 +0x8ef
google.golang.org/grpc.chainUnaryInterceptors.func1.1({0xf05328?, 0xc0001afad0?}, {0xce4700?, 0xc0001afb00?})
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:1132 +0x83
google.golang.org/grpc.chainUnaryInterceptors.func1({0xf05328, 0xc0001afad0}, {0xce4700, 0xc0001afb00}, 0xc000512300, 0xc000010258)
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:1134 +0x12b
github.com/rookie-ninja/rk-demo/api/gen/v1._User_HealthCheck_Handler({0xcc0ee0?, 0xc0001f9480}, {0xf05328, 0xc0001afad0}, 0xc000146380, 0xc000115a00)
S:/NFT/test/grpc_asynq/api/gen/v1/user_grpc.pb.go:116 +0x138
google.golang.org/grpc.(*Server).processUnaryRPC(0xc00047c780, {0xf08ef0, 0xc0000736c0}, 0xc0005f0000, 0xc0002a31a0, 0x14f05c0, 0x0)
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:1295 +0xb0b
google.golang.org/grpc.(*Server).handleStream(0xc00047c780, {0xf08ef0, 0xc0000736c0}, 0xc0005f0000, 0x0)
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:1636 +0xa1b
google.golang.org/grpc.(*Server).serveStreams.func1.2()
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:932 +0x98
created by google.golang.org/grpc.(*Server).serveStreams.func1
C:/Users/linchao/go/pkg/mod/google.golang.org/[email protected]/server.go:930 +0x28a
{"error": "rpc error: code = Internal desc = cannot create context from nil parent"}

[dongxuny]

@linchao0815 rk-entry 有一个很隐蔽的 Bug，修好了。并且把 rk-xxx 其他 package 的版本也升级了一下。我用你的例子验证了一下，不会再抛出 Panic 了。

升级成下面的版本应该就 OK，可以验证一下。

[linchao0815]

感謝!!

[linchao0815]

@dongxuny 我測試以下範例 https://github.com/dongxuny/grpc_asynq
我故意要在task中回傳err
func (t *userTaskServer) CreateUser(ctx context.Context, payload *demo.CreateUserPayload) error {
...
return fmt.Errorf("CreateUser test")
}
我發現底層的span.go
func (s *recordingSpan) SetStatus(code codes.Code, description string) {
if !s.IsRecording() {
return //會在此 return 導致err 沒有寫出, 因此無法在jaeger中查看到err的訊息
}

[linchao0815]

@dongxuny 請問上面有解?

[dongxuny]

@linchao0815 我先研究一下吧，可能会晚一点。

[dongxuny]

@linchao0815 https://github.com/dongxuny/protoc-gen-go-asynqgen 有个 Bug，改了之后，error 能在 jaeger 里查到了。

可以参考最新的 https://github.com/dongxuny/grpc_asynq。