server: don't panic in readonly serializable txn #14149

lavacat · 2022-06-23T23:36:55Z

Problem: We pass grpc context down to applier in readonly serializable txn.
This context can be cancelled for example due to timeout. This will trigger panic.

Solution: provide different error handler for readonly serializable txn.

fixes #14110

Please read https://github.com/etcd-io/etcd/blob/main/CONTRIBUTING.md#contribution-flow.

ahrtr · 2022-06-24T21:05:37Z

Please sign off the commit.

ahrtr · 2022-06-24T21:13:36Z

server/etcdserver/api/v3rpc/grpc.go

@@ -36,7 +36,7 @@ const (
 	maxSendBytes      = math.MaxInt32
 )

-func Server(s *etcdserver.EtcdServer, tls *tls.Config, interceptor grpc.UnaryServerInterceptor, gopts ...grpc.ServerOption) *grpc.Server {
+func Server(s *etcdserver.EtcdServer, tls *tls.Config, interceptors []grpc.UnaryServerInterceptor, gopts ...grpc.ServerOption) *grpc.Server {


unrelated change?

this is to make test work. These interceptors are used only in integrations tests. There is already grpc_testing.GrpcRecorder. I've added another one. See changes in intergration/cluster.go

ahrtr · 2022-06-24T21:21:28Z

server/etcdserver/txn/txn.go

@@ -311,7 +322,7 @@ func newTxnResp(rt *pb.TxnRequest, txnPath []bool) (txnResp *pb.TxnResponse, txn
 	return txnResp, txnCount
 }

-func applyTxn(ctx context.Context, lg *zap.Logger, kv mvcc.KV, lessor lease.Lessor, txnWrite mvcc.TxnWrite, rt *pb.TxnRequest, txnPath []bool, tresp *pb.TxnResponse) (txns int) {
+func applyTxn(ctx context.Context, lg *zap.Logger, kv mvcc.KV, lessor lease.Lessor, txnWrite mvcc.TxnWrite, rt *pb.TxnRequest, txnPath []bool, tresp *pb.TxnResponse, errHander CriticalErrHandler) (txns int, err error) {


The concern is it's hacking the implementation too much. The clearer way is to resolve it out of the box, we can just add a panic-recover, just as I mentioned in issuecomment-1154738363

lavacat · 2022-06-27T08:42:18Z

server/etcdserver/txn/txn.go

+	if err != nil && isWrite {
+		// When txn with write operations starts it has to be successful
+		// We don't have a way to recover state in case of write failure
+		lg.Panic("unexpected error during txnWrite", zap.Error(err))


@ptabor @ahrtr I've tried passing an error handler (see outdated version of this PR) but it seams a bit cumbersome. @ahrtr suggested recover. But it's only going to be for readonly txn not all requests, also seams cumbersome.

How about just panic when txn has write ops?

For ref see, original PR when panic was introduced https://github.com/etcd-io/etcd/pull/3534/files#diff-26b2effd11719aa79af125ed4e17234ef08970839d4f83fb4d802e04614c3cd4R161

Looks good to me!

I have small preference towards apply workflow being extremely strict and deterministic and any unexpected error causing premature exit from function (even in RO) code is something that should lead to investigation and fixing.

But I don't see any exact problem with the proposed approach.

codecov-commenter · 2022-06-27T18:40:19Z

Codecov Report

Merging #14149 (99f9260) into main (4977877) will decrease coverage by 0.15%.
The diff coverage is 63.15%.

@@            Coverage Diff             @@
##             main   #14149      +/-   ##
==========================================
- Coverage   75.42%   75.26%   -0.16%     
==========================================
  Files         456      456              
  Lines       36919    36926       +7     
==========================================
- Hits        27846    27793      -53     
- Misses       7340     7394      +54     
- Partials     1733     1739       +6

Flag	Coverage Δ
all	`75.26% <63.15%> (-0.16%)`	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
server/etcdserver/txn/txn.go	`90.11% <53.33%> (-0.56%)`	⬇️
server/etcdserver/api/v3rpc/grpc.go	`91.42% <100.00%> (ø)`
server/storage/mvcc/kvstore_txn.go	`79.12% <100.00%> (ø)`
client/v3/namespace/watch.go	`87.87% <0.00%> (-6.07%)`	⬇️
client/v3/leasing/cache.go	`87.22% <0.00%> (-4.45%)`	⬇️
client/v3/experimental/recipes/double_barrier.go	`71.87% <0.00%> (-3.13%)`	⬇️
client/v3/retry_interceptor.go	`64.54% <0.00%> (-2.73%)`	⬇️
client/v3/concurrency/election.go	`79.68% <0.00%> (-2.35%)`	⬇️
raft/storage.go	`91.66% <0.00%> (-1.86%)`	⬇️
server/etcdserver/api/v3rpc/watch.go	`86.91% <0.00%> (-1.68%)`	⬇️
... and 11 more

Help us with your feedback. Take ten seconds to tell us how you rate us.

server/etcdserver/txn/txn.go

ahrtr · 2022-07-06T22:10:32Z

tests/integration/v3_grpc_test.go

@@ -1952,3 +1953,77 @@ func waitForRestart(t *testing.T, kvc pb.KVClient) {
 		t.Fatalf("timed out waiting for restart: %v", err)
 	}
 }
+
+func TestV3ReadonlyTxnCancelledContext(t *testing.T) {


Have you considered to add a common test which is executed on both e2e and integration environments? And also use the new interface ?

cc @serathius

It seems we can only add integration test here because we need to inject an interceptor, but we do not support that in command line (and also e2e).

But please consider to use the new interface in https://github.com/etcd-io/etcd/blob/main/tests/framework/integration.go

One problem, new interface is not available in v3.5, so using it now would make backport much harder.

ahrtr · 2022-07-06T22:31:18Z

tests/integration/v3_grpc_test.go

+	clus := integration.NewCluster(t, &integration.ClusterConfig{
+		Size: 1,
+		// Context should be cancelled on the second check that happens inside rangeKeys
+		GrpcInterceptors: []grpc.UnaryServerInterceptor{injectMockContextForTxn(newMockContext(2))},


The 2 here is a little tricky.

I suggest to simplify the test case for better readability:

Remove the Put (line 1968), and let's test the readonly transaction only;

always return a closed channel in (ctx *mockCtx) Done();

Agree that counting calls on context to trigger reaction is not maintainable.
Thinking about alternatives, how about intercepting zap logs, using zap.hooks:

https://stackoverflow.com/questions/64803634/how-to-add-a-hook-into-a-zap-logger

Still not perfect, but allows to e.g. disable context when specific transaction is debug-logged.

@ahrtr Put is there to prevent short circuit in storeTxnRead.Range. We need some data to trigger case <-ctx.Done():
Always returning closed channel doesn't work because it fails early in EtcdServer.linearizableReadNotify and never gets to txn.Txn

@ptabor how do you trigger context cancelled inside storeTxnRead.Range if you don't let the first check in EtcdServer.linearizableReadNotify to pass? Maybe I'm missing something, but how will intercepting zap logs help? As far as I can tell only failure inside storeTxnRead.Range triggers panic, so that's what we want to model in the test.

Another approach I see is to add test only on txn.Txn level and not replicate panic as integration test. Maybe not ideal, but integrations tests don't have to cover every failure scenario.

ahrtr · 2022-07-06T22:52:48Z

tests/integration/v3_grpc_test.go

+	txn := &pb.TxnRequest{Success: []*pb.RequestOp{txnget}}
+	_, err = kvc.Txn(context.TODO(), txn)
+	if err == nil || !strings.Contains(err.Error(), "range context cancelled: mock context error") {
+		t.Fatal(err)


It seems that the err has nothing to do with applyTxn. Note that it's returned by the API instead of the applying workflow.

wrapped err in applyTxn

tests/integration/v3_grpc_test.go

ptabor · 2022-07-13T17:08:28Z

tests/integration/v3_grpc_test.go

+	clus := integration.NewCluster(t, &integration.ClusterConfig{
+		Size: 1,
+		// Context should be cancelled on the second check that happens inside rangeKeys
+		GrpcInterceptors: []grpc.UnaryServerInterceptor{injectMockContextForTxn(newMockContext(2))},


Agree that counting calls on context to trigger reaction is not maintainable.
Thinking about alternatives, how about intercepting zap logs, using zap.hooks:

https://stackoverflow.com/questions/64803634/how-to-add-a-hook-into-a-zap-logger

Still not perfect, but allows to e.g. disable context when specific transaction is debug-logged.

lavacat · 2022-07-26T05:51:52Z

@ahrtr @ptabor updated PR with alternative version of the test that uses reflection to check the name of the caller function and cancel context for rangeKeys.
Added more comments about test setup.
Addressed other small comments.

The only thing that isn't done is migration to new client interface (comment). If this approach looks good, I'll try the new client for main and keep this version for 3.5

ahrtr · 2022-07-27T02:56:00Z

tests/integration/v3_grpc_test.go

+
+	txnget := &pb.RequestOp{Request: &pb.RequestOp_RequestRange{RequestRange: &pb.RangeRequest{Key: []byte("abc")}}}
+	txn := &pb.TxnRequest{Success: []*pb.RequestOp{txnget}}
+	_, err = kvc.Txn(context.TODO(), txn)


I am a little concerned about the readability of the test case. Can you try the following proposal?

pass a context with a deadline, i.e. 5s;

register an unary interceptor, and just sleep a couple of seconds (5+1=6s) in the interceptor;

The kvc.Txn should return an error with something like context timeout

I am also thinking probably we can just add a unit test to accurately test the different behaviors:

For readonly transaction, it should NOT panic due to context timeout;

For non-readonly trancation, it should panic if the context timeout

Deadline approach doesn't work, because it's early terminated here (tried it out).

Unit tests are fine with me. I've mentioned this earlier.

Another approach I see is to add test only on txn.Txn level and not replicate panic as integration test. Maybe not ideal, but integrations tests don't have to cover every failure scenario.

Will work on PR to convert to unit tests and remove this test.

lavacat · 2022-08-05T23:09:51Z

@ahrtr this is ready for review with unit tests instead of integration

ahrtr · 2022-08-08T21:32:48Z

server/etcdserver/txn/txn_test.go

+func cleanupStore(s mvcc.KV, b backend.Backend, path string) {
+	s.Close()
+	b.Close()
+	os.Remove(path)


It should be unnecessary, because the golang build-in test lib can remove the directory returned by t.TempDir() automatically.

ahrtr · 2022-08-08T21:36:45Z

server/etcdserver/txn/txn_test.go

+
+func cleanupStore(s mvcc.KV, b backend.Backend, path string) {
+	s.Close()
+	b.Close()


Please use betesting.Close(t, b) instead.

Problem: We pass grpc context down to applier in readonly serializable txn. This context can be cancelled for example due to timeout. This will trigger panic inside applyTxn Solution: Only panic for transactions with write operations fixes etcd-io#14110 Signed-off-by: Bogdan Kanivets <bkanivets@apple.com>

ahrtr

LGTM

Thank you @lavacat

cc @spzala @ptabor @serathius to double confirm. This is the core applying workflow, there must be at least two approvals.

spzala

lgtm
Thanks @lavacat @ahrtr

ahrtr · 2022-08-13T21:41:51Z

Thanks @spzala

Great work! @lavacat

Problem: We pass grpc context down to applier in readonly serializable txn. This context can be cancelled for example due to timeout. This will trigger panic inside applyTxn Solution: Only panic for transactions with write operations fixes etcd-io#14110 main PR etcd-io#14149

Problem: We pass grpc context down to applier in readonly serializable txn. This context can be cancelled for example due to timeout. This will trigger panic inside applyTxn Solution: Only panic for transactions with write operations fixes etcd-io#14110 main PR etcd-io#14149 Signed-off-by: Bogdan Kanivets <bkanivets@apple.com>

lavacat force-pushed the main-txn-panic branch 2 times, most recently from 75f7a81 to e5fc1de Compare June 24, 2022 00:12

ahrtr reviewed Jun 24, 2022

View reviewed changes

lavacat force-pushed the main-txn-panic branch from e5fc1de to b9c43a6 Compare June 27, 2022 08:29

lavacat commented Jun 27, 2022

View reviewed changes

lavacat force-pushed the main-txn-panic branch from b9c43a6 to a3fa48a Compare June 27, 2022 17:56

lavacat mentioned this pull request Jun 29, 2022

[3.5] server: don't panic in readonly serializable txn #14178

Merged

ahrtr reviewed Jun 29, 2022

View reviewed changes

server/etcdserver/txn/txn.go Outdated Show resolved Hide resolved

lavacat force-pushed the main-txn-panic branch from a3fa48a to 4766fdd Compare July 1, 2022 06:02

lavacat mentioned this pull request Jul 6, 2022

panic: unexpected error during txn #14110

Closed

ahrtr reviewed Jul 6, 2022

View reviewed changes

ptabor reviewed Jul 13, 2022

View reviewed changes

lavacat force-pushed the main-txn-panic branch from 4766fdd to 99f9260 Compare July 26, 2022 05:44

ahrtr reviewed Jul 27, 2022

View reviewed changes

lavacat force-pushed the main-txn-panic branch 2 times, most recently from f41515b to 2a504ef Compare August 3, 2022 07:22

ahrtr reviewed Aug 8, 2022

View reviewed changes

lavacat force-pushed the main-txn-panic branch from 2a504ef to 43bb9d5 Compare August 9, 2022 07:47

ahrtr approved these changes Aug 9, 2022

View reviewed changes

spzala approved these changes Aug 13, 2022

View reviewed changes

ahrtr merged commit fff5d00 into etcd-io:main Aug 13, 2022

ahrtr mentioned this pull request Aug 15, 2022

etcdserver: special apply for readonly transactions #14113

Closed

ahrtr mentioned this pull request Sep 16, 2022

Changelog: add item into 3.6 for the fix on panic in readonly serializable txn #14476

Closed

ahrtr mentioned this pull request Dec 5, 2022

etcdserver: fix nil pointer panic for readonly txn #14895

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

server: don't panic in readonly serializable txn #14149

server: don't panic in readonly serializable txn #14149

lavacat commented Jun 23, 2022

ahrtr commented Jun 24, 2022

ahrtr Jun 24, 2022

lavacat Jun 27, 2022 •

edited

ahrtr Jun 24, 2022

lavacat Jun 27, 2022

ahrtr Jun 29, 2022

ptabor Jul 13, 2022

codecov-commenter commented Jun 27, 2022 •

edited

ahrtr Jul 6, 2022

ahrtr Jul 6, 2022

serathius Jul 12, 2022

ahrtr Jul 6, 2022

ptabor Jul 13, 2022

lavacat Jul 13, 2022

ahrtr Jul 6, 2022

lavacat Jul 26, 2022

ptabor Jul 13, 2022

lavacat commented Jul 26, 2022

ahrtr Jul 27, 2022

ahrtr Jul 27, 2022

lavacat Jul 28, 2022

lavacat commented Aug 5, 2022

ahrtr Aug 8, 2022

ahrtr Aug 8, 2022

ahrtr left a comment

spzala left a comment

ahrtr commented Aug 13, 2022

server: don't panic in readonly serializable txn #14149

server: don't panic in readonly serializable txn #14149

Conversation

lavacat commented Jun 23, 2022

ahrtr commented Jun 24, 2022

Choose a reason for hiding this comment

lavacat Jun 27, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov-commenter commented Jun 27, 2022 • edited

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lavacat commented Jul 26, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lavacat commented Aug 5, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ahrtr left a comment

Choose a reason for hiding this comment

spzala left a comment

Choose a reason for hiding this comment

ahrtr commented Aug 13, 2022

lavacat Jun 27, 2022 •

edited

codecov-commenter commented Jun 27, 2022 •

edited