How to debug grpc call?

Question

I'm trying to figure out why my grpc call isn't working, but I can't figure out how to turn on debugging, so I can see the data that's being sent and received over the grpc connection.

How do you turn on debugging for grpc calls?

Answer 1

You can set the GRPC_TRACE environment variable to all to have grpc dump a whole bunch of data about what the connection is doing:

export GRPC_TRACE=all

edit from comment: apparently you also need to set:

export GRPC_VERBOSITY=DEBUG

Answer 2

In Golang, you need to set the GODEBUG environment variable to see HTTP2 traces, i.e. headers set by gRPC:

GODEBUG=http2debug=1   # enable verbose HTTP/2 debug logs
GODEBUG=http2debug=2   # ... even more verbose, with frame dumps

The output will then be sent to stdout. here's an example:

{"level":"info","msg":"2017/06/11 08:52:20 http2: Framer 0xc42009c0e0: wrote SETTINGS len=0","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: Framer 0xc42009c0e0: wrote WINDOW_UPDATE len=4 (conn) incr=983025","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: Framer 0xc42009c0e0: read SETTINGS len=18, settings: ENABLE_PUSH=0, MAX_CONCURRENT_STREAMS=0, INITIAL_WINDOW_SIZE=1048576","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: Framer 0xc42009c0e0: read WINDOW_UPDATE len=4 (conn) incr=983041","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: Framer 0xc42009c0e0: wrote SETTINGS flags=ACK len=0","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: Framer 0xc42009c0e0: read SETTINGS flags=ACK len=0","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: Framer 0xc42009c0e0: read HEADERS flags=END_HEADERS|PRIORITY stream=3 len=249","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \":authority\" = \"\"","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \":path\" = \"/internal.push.v1.UnifiedDevicePush/SendMessage\"","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \":method\" = \"POST\"","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \":scheme\" = \"http\"","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \"content-type\" = \"application/grpc\"","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \"te\" = \"trailers\"","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \"user-agent\" = \"grpc-java-netty/1.0.3\"","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \"root-common.xirequestid-bin\" = \"ChIJzE6lBfCTCsYRoIIJujc92JY=\"","time":"2017-06-11T08:52:20Z"}
{"level":"info","msg":"2017/06/11 08:52:20 http2: decoded hpack field header field \"te\" = \"trailers\"","time":"2017-06-11T08:52:20Z"}

Answer 3

export GRPC_GO_LOG_VERBOSITY_LEVEL=99
export GRPC_GO_LOG_SEVERITY_LEVEL=info

Try this with latest grpc go version.

Answer 4

From the docs

GRPC_VERBOSITY is used to set the minimum level of log messages printed by gRPC (supported values are DEBUG, INFO, and ERROR). If this environment variable is unset, only ERROR logs will be printed.

Also, check GRPC_TRACE

There are 15+ grpc environment variables

A note for Windows users, quoting from docs:

Known limitations: GPRC_TRACE=tcp is currently not implemented for Windows (you won't see any TCP traces).

Answer 5

You can use the Mediator Tool to debug and tracing gRPC calls.

It is a GUI tool just like the charles, but if you need to resolve the protobuf message body, the gRPC server needs to support the Server Reflection.