master branch, 3.5-pre have found panic: KeyValue: illegal tag

[yangxuanjia]

{"level":"panic","ts":"2021-04-08T21:26:57.399+0800","caller":"mvcc/watchable_store.go:417","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: illegal tag 0 (wire type 0)","stacktrace":"go.etcd.io/etcd/v3/mvcc.kvsToEvents\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:417\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchers\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:362\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:224"}

{"level":"panic","ts":"2021-04-09T09:11:21.902+0800","caller":"mvcc/watchable_store.go:417","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: illegal tag 0 (wire type 2)","stacktrace":"go.etcd.io/etcd/v3/mvcc.kvsToEvents\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:417\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchers\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:362\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:224"}

{"level":"panic","ts":"2021-04-09T09:13:02.609+0800","caller":"mvcc/watchable_store.go:417","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: illegal tag 0 (wire type 0)","stacktrace":"go.etcd.io/etcd/v3/mvcc.kvsToEvents\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:417\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchers\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:362\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:224"}

{"level":"warn","ts":"2021-04-08T19:40:33.831+0800","caller":"etcdserver/util.go:158","msg":"apply request took too long","took":"128.022295ms","expected-duration":"100ms","prefix":"","request":"header:<ID:10681543059563361494 > txn:<compare:<key:"/vt/global/keyspaces/poporder3/locks/1458171022708585683" version:0 > success:<request_put:<key:"/vt/global/keyspaces/poporder3/locks/1458171022708585683" value_size:156 lease:1458171022708585683 >> failure:<>>","response":"size:20"}
{"level":"warn","ts":"2021-04-08T19:40:36.968+0800","caller":"etcdserver/util.go:158","msg":"apply request took too long","took":"124.063469ms","expected-duration":"100ms","prefix":"","request":"header:<ID:11411126198913509988 > lease_revoke:id:1e5c76d1b564aa5b","response":"size:31"}

---

It seems may reference /XXX/locks/XXX

[yangxuanjia]

"error":"proto: illegal wireType 7"

{"level":"panic","ts":"2021-04-08T19:23:00.281+0800","caller":"mvcc/watchable_store.go:417","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: illegal wireType 7","stacktrace":"go.etcd.io/etcd/v3/mvcc.kvsToEvents\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:417\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchers\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:362\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:224"}

[yangxuanjia]

"error":"proto: illegal wireType 7"

{"level":"panic","ts":"2021-04-08T19:23:00.281+0800","caller":"mvcc/watchable_store.go:417","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: illegal wireType 7","stacktrace":"go.etcd.io/etcd/v3/mvcc.kvsToEvents\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:417\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchers\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:362\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:224"}

[yangxuanjia]

"error":"proto: KeyValue: wiretype end group for non-group"

{"level":"panic","ts":"2021-04-09T11:25:21.520+0800","caller":"mvcc/watchable_store.go:417","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: wiretype end group for non-group","stacktrace":"go.etcd.io/etcd/v3/mvcc.kvsToEvents\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:417\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchers\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:362\ngo.etcd.io/etcd/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/export/working/src/github.com/etcd-io/etcd/mvcc/watchable_store.go:224"}

[ptabor]

Maybe updates to protobuf runtime 3.5 that we done post 3.5.0-alpha.0 solved this issue. Have you tried to repro using the master branch ?

[yangxuanjia]

For this problem, the business at the time used etcd client version 3.3 and etcd server side 3.5-pre. Normally, there was no problem. This problem occurred several times online. At that time, the business failed to create the vitess container, and this problem occurred. Later, the business was asked to delete several vitess containers that failed, and they did not appear afterwards.

It stands to reason that this problem should not occur. The code logic is proto.unmarsal(), and the key is read from the disk to the watch. Since proto.marsal() is okay, there shouldn't be a problem with unmarsal()? ?? So it feels weird.

[betterliuyu]

This bug still exists, until release 3.5.0.

[simonhou]

I met the same error. v3.5.0
{"level":"panic","ts":"2021-07-13T08:13:48.403+0800","caller":"mvcc/watchable_store.go:414","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: illegal tag 0 (wire type 0)","stacktrace":"go.etcd.io/etcd/server/v3/mvcc.kvsToEvents\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:414\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:359\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:222"}

[okaybase]

I also met the same case in v3.5.0

date: 2021-09-23T10:59:41.354+0800

{"level":"panic","ts":"2021-09-23T07:00:40.717+0800","caller":"mvcc/watchable_store.go:414","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: illegal tag 0 (wire type 0)","stacktrace":"go.etcd.io/etcd/server/v3/mvcc.kvsToEvents\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:414\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:359\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:222"}
panic: failed to unmarshal mvccpb.KeyValue

goroutine 136 [running]:
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc006c8b380, 0xc000670000, 0x1, 0x1)
/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/zapcore/entry.go:234 +0x58d
go.uber.org/zap.(*Logger).Panic(0xc0001a1360, 0x12257a4, 0x23, 0xc000670000, 0x1, 0x1)
/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/logger.go:227 +0x85
go.etcd.io/etcd/server/v3/mvcc.kvsToEvents(0xc0001a1360, 0xc00050c400, 0xc00d746000, 0x215ef, 0x25d55, 0xc00d3ba000, 0x215ef, 0x25d55, 0x12, 0x7fffffffffffffff, ...)
/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:414 +0x296
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers(0xc00050c3c0, 0x0)
/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:359 +0x3e8
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop(0xc00050c3c0)
/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:222 +0x1e8
created by go.etcd.io/etcd/server/v3/mvcc.newWatchableStore
/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:95 +0x3a7

[hexiang1219]

I also met the same case in v3.5.0

{"level":"panic","ts":"2021-09-28T11:26:39.702+0800","caller":"mvcc/watchable_store.go:414","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: illegal tag 0 (wire type 0)","stacktrace":"go.etcd.io/etcd/server/v3/mvcc.kvsToEvents\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:414\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:359\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:222"}
panic: failed to unmarshal mvccpb.KeyValue
goroutine 225 [running]:
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc046ed9b00, 0xc03c688600, 0x1, 0x1)
/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/zapcore/entry.go:234 +0x58d
go.uber.org/zap.(*Logger).Panic(0xc00048d040, 0x12257a4, 0x23, 0xc03c688600, 0x1, 0x1)
/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/logger.go:227 +0x85
go.etcd.io/etcd/server/v3/mvcc.kvsToEvents(0xc00048d040, 0xc011feebc0, 0xc05bf08000, 0x796e0, 0x90955, 0xc05b17a000, 0x796e0, 0x90955, 0x12, 0x7fffffffffffffff, ...)
/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:414 +0x296
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers(0xc000196000, 0x0)
/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:359 +0x3e8
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop(0xc000196000)
/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:222 +0x1e8
created by go.etcd.io/etcd/server/v3/mvcc.newWatchableStore
/tmp/etcd-release-3.5.0/etcd/release/etcd/server/mvcc/watchable_store.go:95 +0x3a7

[DeadLion]

i also met the same case in v3.5.1 ，two kinds of log

{"level":"panic","ts":"2021-12-26T22:23:59.728+0800","caller":"mvcc/watchable_store.go:414","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: wiretype end group for non-group","stacktrace":"go.etcd.io/etcd/server/v3/mvcc.kvsToEvents\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:414\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:359\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:222"}
panic: failed to unmarshal mvccpb.KeyValue

goroutine 166 [running]:
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc0048a2fc0, 0xc006c12540, 0x1, 0x1)
/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/zapcore/entry.go:234 +0x58d
go.uber.org/zap.(*Logger).Panic(0xc000134d20, 0x12268a2, 0x23, 0xc006c12540, 0x1, 0x1)
/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/logger.go:227 +0x85
go.etcd.io/etcd/server/v3/mvcc.kvsToEvents(0xc000134d20, 0xc0004b02c0, 0xc00a2d6000, 0x16b5b, 0x182aa, 0xc009fb8000, 0x16b5b, 0x182aa, 0x12, 0x7fffffffffffffff, ...)
/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:414 +0x296
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers(0xc0004b0280, 0x0)
/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:359 +0x3e8
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop(0xc0004b0280)
/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:222 +0x1e8
created by go.etcd.io/etcd/server/v3/mvcc.newWatchableStore
/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:95 +0x3a7

{"level":"panic","ts":"2021-12-24T06:49:58.950+0800","caller":"mvcc/watchable_store.go:414","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: illegal tag 0 (wire type 0)","stacktrace":"go.etcd.io/etcd/server/v3/mvcc.kvsToEvents\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:414\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:359\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:222"}
panic: failed to unmarshal mvccpb.KeyValue

goroutine 61 [running]:
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc004756c00, 0xc006602040, 0x1, 0x1)
/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/zapcore/entry.go:234 +0x58d
go.uber.org/zap.(*Logger).Panic(0xc0001a0820, 0x12268a2, 0x23, 0xc006602040, 0x1, 0x1)
/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/logger.go:227 +0x85
go.etcd.io/etcd/server/v3/mvcc.kvsToEvents(0xc0001a0820, 0xc0001504a0, 0xc0097ec000, 0xd506, 0xf6aa, 0xc00967a000, 0xd506, 0xf6aa, 0x12, 0x7fffffffffffffff, ...)
/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:414 +0x296
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers(0xc000150460, 0x0)
/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:359 +0x3e8
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop(0xc000150460)
/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:222 +0x1e8
created by go.etcd.io/etcd/server/v3/mvcc.newWatchableStore
/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:95 +0x3a7

Are they all the same reason ? and will fix in 3.5.2?

[ushell]

i got same panic use bitnami/etcd:3.5.1 docker image in k8s environment, how to avoid the panic?

log info

{"level":"panic","ts":"2022-02-08T06:06:15.563Z","caller":"mvcc/watchable_store.go:414","msg":"failed to unmarshal mvccpb.KeyValue","error":"proto: KeyValue: illegal tag 0 (wire type 0)","stacktrace":"go.etcd.io/etcd/server/v3/mvcc.kvsToEvents\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:414\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:359\ngo.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop\n\t/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:222"}
panic: failed to unmarshal mvccpb.KeyValue

goroutine 109 [running]:
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc003528c00, 0xc000eb2980, 0x1, 0x1)
	/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/zapcore/entry.go:234 +0x58d
go.uber.org/zap.(*Logger).Panic(0xc000088730, 0x12268a2, 0x23, 0xc000eb2980, 0x1, 0x1)
	/home/remote/sbatsche/.gvm/pkgsets/go1.16.3/global/pkg/mod/go.uber.org/zap@v1.17.0/logger.go:227 +0x85
go.etcd.io/etcd/server/v3/mvcc.kvsToEvents(0xc000088730, 0xc000462180, 0xc00816e000, 0x1dac1, 0x1e400, 0xc007e98000, 0x1dac1, 0x1e400, 0x12, 0x7fffffffffffffff, ...)
	/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:414 +0x296
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchers(0xc000462140, 0x0)
	/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:359 +0x3e8
go.etcd.io/etcd/server/v3/mvcc.(*watchableStore).syncWatchersLoop(0xc000462140)
	/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:222 +0x1e8
created by go.etcd.io/etcd/server/v3/mvcc.newWatchableStore
	/tmp/etcd-release-3.5.1/etcd/release/etcd/server/mvcc/watchable_store.go:95 +0x3a7

some warning log

{"level":"warn","ts":"2022-02-08T05:57:15.311Z","caller":"etcdserver/util.go:166","msg":"apply request took too long","took":"100.472336ms","expected-duration":"100ms","prefix":"","request":"header:<ID:16749870896904696847 > put:<key:\"/apisix/data_plane/server_info/12339034-b1e3-4826-8432-9a1c43cc71ae\" value_size:194 lease:7526498860049921037 prev_kv:true >","response":"size:297"}

[serathius]

Should be fixed by #13505
Please upgrade to v3.5.2