Skip to content

Experimenting with making debug log level useful for debugging linearizability issues#21401

Draft
serathius wants to merge 3 commits intoetcd-io:mainfrom
serathius:debug-request
Draft

Experimenting with making debug log level useful for debugging linearizability issues#21401
serathius wants to merge 3 commits intoetcd-io:mainfrom
serathius:debug-request

Conversation

@serathius
Copy link
Copy Markdown
Member

@serathius serathius commented Mar 1, 2026

Goal: Make debugging linearizability issues possible on upstream code without needing to have custom code in Antithesis.

Problem: How to incorporate logging and tracing

Before:

10:42:57 etcd1 | {"level":"debug","ts":"2026-03-01T10:42:57.113997+0100","caller":"v3rpc/interceptor.go:186","msg":"request stats","start time":"2026-03-01T10:42:57.113603+0100","time spent":"379.414µs","remote":"127.0.0.1:60676","response type":"/etcdserverpb.KV/Range","request count":0,"request size":3,"response count":0,"response size":28,"request content":"key:\"a\" "}

After

21:12:00 etcd1 | {"level":"debug","ts":"2026-03-01T21:12:00.149692+0100","caller":"v3rpc/interceptor.go:124","msg":"request","method":"/etcdserverpb.KV/Range","request_id":3632606832826034696,"remote":"127.0.0.1:58622","size":3,"range_begin":"a","range_end":"","range_revision":0,"range_limit":0,"range_count_only":false,"range_keys_only":false}
21:12:00 etcd1 | {"level":"debug","ts":"2026-03-01T21:12:00.149723+0100","caller":"etcdserver/v3_server.go:1128","msg":"sending read index request","read-request-id":3632606832826034694,"timeout":"7s"}
21:12:00 etcd1 | {"level":"debug","ts":"2026-03-01T21:12:00.149779+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"send","message-type":"MsgReadIndex","local-member-id":"8211f1d0f64f3269","remote-peer-id":"fd422379fda50e48","term":0,"index":0,"commit":0,"request-id":3632606832826034694}
21:12:00 etcd3 | {"level":"debug","ts":"2026-03-01T21:12:00.149845+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"receive","message-type":"MsgReadIndex","local-member-id":"fd422379fda50e48","remote-peer-id":"8211f1d0f64f3269","term":0,"index":0,"commit":0,"request-id":3632606832826034694}
21:12:00 etcd3 | {"level":"debug","ts":"2026-03-01T21:12:00.149903+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"send","message-type":"MsgHeartbeat","local-member-id":"fd422379fda50e48","remote-peer-id":"8211f1d0f64f3269","term":24,"index":0,"commit":71,"request-id":3632606832826034694}
21:12:00 etcd3 | {"level":"debug","ts":"2026-03-01T21:12:00.149915+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"send","message-type":"MsgHeartbeat","local-member-id":"fd422379fda50e48","remote-peer-id":"91bc3c398fb3c146","term":24,"index":0,"commit":71,"request-id":3632606832826034694}
21:12:00 etcd2 | {"level":"debug","ts":"2026-03-01T21:12:00.149996+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"receive","message-type":"MsgHeartbeat","local-member-id":"91bc3c398fb3c146","remote-peer-id":"fd422379fda50e48","term":24,"index":0,"commit":71,"request-id":3632606832826034694}
21:12:00 etcd2 | {"level":"debug","ts":"2026-03-01T21:12:00.150060+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"send","message-type":"MsgHeartbeatResp","local-member-id":"91bc3c398fb3c146","remote-peer-id":"fd422379fda50e48","term":24,"index":0,"commit":0,"request-id":3632606832826034694}
21:12:00 etcd1 | {"level":"debug","ts":"2026-03-01T21:12:00.149973+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"receive","message-type":"MsgHeartbeat","local-member-id":"8211f1d0f64f3269","remote-peer-id":"fd422379fda50e48","term":24,"index":0,"commit":71,"request-id":3632606832826034694}
21:12:00 etcd1 | {"level":"debug","ts":"2026-03-01T21:12:00.150103+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"send","message-type":"MsgHeartbeatResp","local-member-id":"8211f1d0f64f3269","remote-peer-id":"fd422379fda50e48","term":24,"index":0,"commit":0,"request-id":3632606832826034694}
21:12:00 etcd3 | {"level":"debug","ts":"2026-03-01T21:12:00.150124+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"receive","message-type":"MsgHeartbeatResp","local-member-id":"fd422379fda50e48","remote-peer-id":"91bc3c398fb3c146","term":24,"index":0,"commit":0,"request-id":3632606832826034694}
21:12:00 etcd3 | {"level":"debug","ts":"2026-03-01T21:12:00.150161+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"send","message-type":"MsgReadIndexResp","local-member-id":"fd422379fda50e48","remote-peer-id":"8211f1d0f64f3269","term":24,"index":71,"commit":0,"request-id":3632606832826034694}
21:12:00 etcd3 | {"level":"debug","ts":"2026-03-01T21:12:00.150197+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"receive","message-type":"MsgHeartbeatResp","local-member-id":"fd422379fda50e48","remote-peer-id":"8211f1d0f64f3269","term":24,"index":0,"commit":0,"request-id":3632606832826034694}
21:12:00 etcd1 | {"level":"debug","ts":"2026-03-01T21:12:00.150239+0100","caller":"rafthttp/transport.go:481","msg":"Raft communication","direction":"receive","message-type":"MsgReadIndexResp","local-member-id":"8211f1d0f64f3269","remote-peer-id":"fd422379fda50e48","term":24,"index":71,"commit":0,"request-id":3632606832826034694}
21:12:00 etcd1 | {"level":"debug","ts":"2026-03-01T21:12:00.150285+0100","caller":"etcdserver/v3_server.go:1165","msg":"linearizable read notify","read-index-id":3632606832826034694,"request-id":3632606832826034696}
21:12:00 etcd1 | {"level":"debug","ts":"2026-03-01T21:12:00.150352+0100","caller":"v3rpc/interceptor.go:191","msg":"response","method":"/etcdserverpb.KV/Range","duration":"643.721µs","size":44,"request_id":3632606832826034696,"size":44,"count":1}

/cc @ahrtr @fuweid @AwesomePatrol
Ref #20418

@k8s-ci-robot k8s-ci-robot requested a review from ahrtr March 1, 2026 10:31
@k8s-ci-robot
Copy link
Copy Markdown

Skipping CI for Draft Pull Request.
If you want CI signal for your change, please convert it to an actual PR.
You can still manually trigger a test run with /test all

@k8s-ci-robot
Copy link
Copy Markdown

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: serathius

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Details Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>
Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>
Signed-off-by: Marek Siarkowicz <siarkowicz@google.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Development

Successfully merging this pull request may close these issues.

3 participants