Tcpdump or Wireshark are powerful network tools which can help debug network problems easily, but sometimes, we need more. For example, a few days ago, we met a strange problem — TiKV raised KeyNotInRange error, which meant that TiKV received a request which wanted to get value with a key like c in the range [b, c) , but in fact, it tried to fetch the key in the range [a, b) .

This was strange, we suspected that there might have three possible cases:

A bug in TiKV, which meant the TiKV received correct key and range, but it met an over-bounded error and sought the key in the wrong range.

A bug in TiDB, which meant the TiDB sent the request with a wrong range.

A bug in PD client, which meant the TiDB asked for the PD for the range of the key, but PD returned a wrong range.

To locate the problem, we need to login to the three services and check their logs, but unfortunately, most of the time, we don’t record any log for request except this request triggers an error. Another solution is to change the log level from info to debug , but this can introduce too many log messages. If nothing else, we can build a customized version, but this is impossible in production.

If we can inspect the network communication in these services, we may ensure which component has a problem. For example, if we find the TIDB sends a wrong range and PD returns the correct range information, we can know there is a bug in TiDB.

We use gRPC, so what we only need to do is to dump the gRPC communication, decode data with our own protobuf. This is easy but there is no existing tool for us. But we are programmers, and like reinvent the wheel , so we build gRPC assembly.

To build an assembly, we need to do:

Capture the TCP data Decode the TCP data with HTTP/2 protocol Map the HTTP/2 protocol to gRPC protocol Decode the message with our own protobuf

gopacket

We can use gopacket to capture the TCP data easily. There is an example called httpassembly in gopacket, which can capture TCP and decode HTTP/1 protocol. So it is easy for us to reuse this example and decode HTTP/2.

We won’t talk about more about how to use gopacket, you can google it because it is developed by Google :-)

HTTP/2

Through gopacket, we can get a TCP stream, and next, we need to decode HTTP/2 from the stream. Different from HTTP/1, the message of HTTP/2 is based on frame, you can refer to RFC7540. So for us, decoding HTTP/2 is just to decode the frame.

Here, we will use another Go library http2. This library is not recommended for outside use, and you can’t find any doc or example. But luckily, we can learn how to use it from the Go gRPC in http_util.go :

func (h *httpStream) run() {

buf := bufio.NewReader(&h.r)

framer := http2.NewFramer(ioutil.Discard, buf)

framer.MaxHeaderListSize = uint32(16 << 20)

framer.ReadMetaHeaders = hpack.NewDecoder(4096, nil)

The above code is simple, what we need to care is the header of HTTP/2, here we use the HPACK encoder, you can access RFC7541 to know more about HPACK.

After we create the framer, we can call framer.ReadFrame() in the for the loop. But there has a problem with the first handshake message of HTTP/2. The first message is not a frame, so if we call ReadFrame directly we may meet an error. You can access the chapter of HTTP/2 starting to know more about the handshake.

Luckily, because we all use gRPC, we use the Connection Preface way for the handshake. We only need to peek some characters and check whether they are PRI * HTTP/2.0 . If not, which means this is a common frame, and we can use ReadFrame directly.

There is another problem for PD. PD can use the same port to support gRPC and HTTP/1, so we not only need to check the message is the handshake of HTTP/2, but also need to check the message is HTTP/1. For HTTP/1, the request starts from “GET” / “POST” / “PUT”, etc, and the response starts from “HTTP”, so it is easy to check HTTP/1 too.

gRPC

After we get the frame of HTTP/2, we can easily map the frame to gRPC. You can read gRPC over HTTP2 to know how to map.

We need to take care of MetaHeadersFrame and DataFrame. For MetaHeadersFrame, if it contains :path , the frame is a request(the client sends to the server). If if contains :status , the frame is a response (the server returns to the client).

If the frame is a request, it may contain a :path , the path is very important for us, through it we can know the defined gRPC service and method, and then we can know the corresponding protobuf and decode it in the following DataFrame.

For example, a header frame has a path /pdpb.PD/StoreHeartbeat , and we can know the service PD is defined in the file pdpb , and the method is StoreHeartbeat , we can know the request and response specifically.

If we meet :path , we need to bind the stream ID in this frame with :path , and then for the corresponding response, we can get the :path with the frame ID of response.

For DataFrame, the first byte of data is for compression. If it is 1, we need to use the compression algorithm defined in the field grpc-encoding of the previous header.

Protocol Buffer

Here, again, we do most of the work, but we still meet a serious problem. If the assembly tries to inspect an existing connection, mostly we can’t get :path and if we can’t know :path , we can’t decode the corresponding protobuf message.

The problem is due to the HPACK which may compress some duplicated header to reduce network traffic. For gRPC, the client may call the same method too many times in one connection, HAPCK will ignore the field.

So now we can’t know the actual protobuf, the only way here is to decode the message with standard protobuf encoding format which defined here — encoding. For Go, we build our own decoder based on DebugPrint.

The final output looks like:

tag=1 struct

tag=1 varint=2037210783374497686

tag=2 varint=13195394291058371180

tag=3 varint=244

tag=4 varint=2

tag=2 varint=1

tag=3 struct

tag=2 struct

tag=1 struct

tag=3 varint=244

Of course, we have to guess the actual protobuf now, but better than nothing.

Demo

Below is the final demo, we start TiKV and inspect port 20160:

go run assembly.go -f "port 20160" -i lo0

2018/12/29 20:17:17 Starting capture on interface "lo0"

2018/12/29 20:17:17 reading in packets

2018/12/29 20:17:26 127.0.0.1:64989 -> 127.0.0.1:20160 /tikvpb.Tikv/KvPrewrite context:<region_id:2 region_epoch:<conf_ver:1 version:1 > peer:<id:3 store_id:1 > > mutations:<key:"usertable:a" value:"\010\000\002\0020" > primary_lock:"usertable:a" start_version:405297128206237697 lock_ttl:3000

2018/12/29 20:17:26 127.0.0.1:20160 -> 127.0.0.1:64989 /tikvpb.Tikv/KvPrewrite

2018/12/29 20:17:26 127.0.0.1:64995 -> 127.0.0.1:20160 /tikvpb.Tikv/KvCommit context:<region_id:2 region_epoch:<conf_ver:1 version:1 > peer:<id:3 store_id:1 > > start_version:405297128206237697 keys:"usertable:a" commit_version:405297128206237698

2018/12/29 20:17:26 127.0.0.1:20160 -> 127.0.0.1:64995 /tikvpb.Tikv/KvCommit

2018/12/29 20:17:29 127.0.0.1:64999 -> 127.0.0.1:20160 /tikvpb.Tikv/KvGet context:<region_id:2 region_epoch:<conf_ver:1 version:1 > peer:<id:3 store_id:1 > > key:"usertable:a" version:405297128901443585

2018/12/29 20:17:29 127.0.0.1:20160 -> 127.0.0.1:64999 /tikvpb.Tikv/KvGet value:"\010\000\002\0020"

This is just a simple demo, but through it, we can know the communication between different components and can help us debug the problem.