Watch sync fails when Fragment is false

[kevburnsjr]

Bug report criteria

• This bug report is not security related, security issues should be disclosed privately via etcd maintainers.
• This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
• You have read the etcd bug reporting guidelines.
• Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

Server having four revisions to sync returns 1 response with 48 events @ 4.8 MB resulting in an error

rpc error: code = ResourceExhausted desc = grpc: received message larger than max (4802091 vs. 4194304)

What did you expect to happen?

Server having four revisions to sync returns 4 responses with 12 events each @ 1.2 MB per response

How can we reproduce it (as minimally and precisely as possible)?

See failing test in #19442

• Submit 4 transactions putting 12 keys each with values of size 100KB
• Start a new watch with:
  • StartRevision = The revision of the first of the four transactions
  • Fragment = false

Anything else we need to know?

Max response size is set to default of 1.5 MB

Etcd version (please run commands below)

Reproduced in

• v3.3.27
• v3.4.35
• v3.5.18
• main

Possibly related

#8188 (comment)

Etcd configuration (command line flags or environment variables)

docker-compose.yml

# Copyright Broadcom, Inc. All Rights Reserved.
# SPDX-License-Identifier: APACHE-2.0

services:
  etcd1:
    image: docker.io/bitnami/etcd:3.3
    environment:
      - ALLOW_NONE_AUTHENTICATION=yes
      - ETCD_NAME=etcd1
      - ETCD_INITIAL_ADVERTISE_PEER_URLS=http://etcd1:2380
      - ETCD_LISTEN_PEER_URLS=http://0.0.0.0:2380
      - ETCD_LISTEN_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_ADVERTISE_CLIENT_URLS=http://etcd1:2379
      - ETCD_INITIAL_CLUSTER_TOKEN=etcd-cluster
      - ETCD_INITIAL_CLUSTER=etcd1=http://etcd1:2380,etcd2=http://etcd2:2380,etcd3=http://etcd3:2380
      - ETCD_LOG_LEVEL=debug
      - ETCD_INITIAL_CLUSTER_STATE=new
    ports:
      - 2379:2379
      - 11180:11180
    volumes:
      - type: tmpfs
        target: /bitnami
        tmpfs:
          mode: 01777
  etcd2:
    image: docker.io/bitnami/etcd:3.3
    environment:
      - ALLOW_NONE_AUTHENTICATION=yes
      - ETCD_NAME=etcd2
      - ETCD_INITIAL_ADVERTISE_PEER_URLS=http://etcd2:2380
      - ETCD_LISTEN_PEER_URLS=http://0.0.0.0:2380
      - ETCD_LISTEN_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_ADVERTISE_CLIENT_URLS=http://etcd2:2379
      - ETCD_INITIAL_CLUSTER_TOKEN=etcd-cluster
      - ETCD_INITIAL_CLUSTER=etcd1=http://etcd1:2380,etcd2=http://etcd2:2380,etcd3=http://etcd3:2380
      - ETCD_LOG_LEVEL=debug
      - ETCD_INITIAL_CLUSTER_STATE=new
    ports:
      - 22379:2379
      - 21180:11180
    volumes:
      - type: tmpfs
        target: /bitnami
        tmpfs:
          mode: 01777
  etcd3:
    image: docker.io/bitnami/etcd:3.3
    environment:
      - ALLOW_NONE_AUTHENTICATION=yes
      - ETCD_NAME=etcd3
      - ETCD_INITIAL_ADVERTISE_PEER_URLS=http://etcd3:2380
      - ETCD_LISTEN_PEER_URLS=http://0.0.0.0:2380
      - ETCD_LISTEN_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_ADVERTISE_CLIENT_URLS=http://etcd3:2379
      - ETCD_INITIAL_CLUSTER_TOKEN=etcd-cluster
      - ETCD_INITIAL_CLUSTER=etcd1=http://etcd1:2380,etcd2=http://etcd2:2380,etcd3=http://etcd3:2380
      - ETCD_LOG_LEVEL=debug
      - ETCD_INITIAL_CLUSTER_STATE=new
    ports:
      - 32379:2379
      - 31180:11180
    volumes:
      - type: tmpfs
        target: /bitnami
        tmpfs:
          mode: 01777

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

See failing test in #19442

> go test -run=TestV3WatchLargeTxnFragmentFalse -v
=== RUN   TestV3WatchLargeTxnFragmentFalse
    v3_watch_test.go:1656:
        Error Trace:    /home/kev/etcd/tests/integration/v3_watch_test.go:1656
                        /home/kev/etcd/tests/integration/v3_watch_test.go:1601
        Error:          Expected nil, but got: &status.Error{s:(*status.Status)(0xc000090098)}
        Test:           TestV3WatchLargeTxnFragmentFalse
        Messages:       rpc error: code = ResourceExhausted desc = grpc: received message larger than max (4802091 vs. 4194304)

Relevant log output

[ahrtr]

Thanks @kevburnsjr for raising this issue. We might need to figure out starting from which grpc version the behavour changed.

@dfawley, @easwars is there any behaviour change on grpc side in term of the default max response size the grpc support?

[ahrtr]

FYI. etcd sets the response limit as math.MaxInt32, so there is no limit at all. Not sure why grpc still complains the message size

etcd/client/v3/options.go

Line 40 in 1e3710a

defaultMaxCallRecvMsgSize = grpc.MaxCallRecvMsgSize(math.MaxInt32)

[easwars]

We did have this recent change which might be related: grpc/grpc-go#7918

@arjan-bal might have more context since he was involved in that change's review.

[kevburnsjr]

I found this client test which seems to indicate that this might have been expected behavior for the last 7 years.
https://github.com/etcd-io/etcd/blob/main/tests/integration/clientv3/watch_fragment_test.go#L38-L46

[arjan-bal]

@easwars the change in grpc/grpc-go#7918 effected the decompression code path. The error seen here is returned before that, at the time of splitting the http/2 data frame into grpc header and body.

FYI. etcd sets the response limit as math.MaxInt32, so there is no limit at all. Not sure why grpc still complains the message size

I think the error is returned by the gRPC server on receiving a 4.8MB request from the client. I see a 1.5MB limit on the max receive size for the server coming from here

etcd/tests/framework/integration/cluster.go

Lines 682 to 684 in deb9178

	if m.MaxRequestBytes == 0 {
	m.MaxRequestBytes = embed.DefaultMaxRequestBytes
	}

The value is used to specify a server option here after adding another 0.5MB

etcd/server/etcdserver/api/v3rpc/grpc.go

Line 77 in deb9178

opts = append(opts, grpc.MaxRecvMsgSize(int(s.Cfg.MaxRequestBytesWithOverhead())))

This still doesn't match with the error message which indicates a 4MB limit.

[arjan-bal]

4MB is the default max receive message size for gRPC servers specified here. This default has been there since a long time (8 years).

[arjan-bal]

After adding logs within gRPC to debug this, the problem is happening in the gRPC client. The max receive size is being set using a call option. The call options are not set on the entire ClientConn, instead they are stored in a field of the client and used every time a stream is created.

etcd/client/v3/client.go

Line 75 in deb9178

callOpts []grpc.CallOption

Based on the logs, it looks like the call options are not provided when the watch is created by the following lines in the test code:

ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second)
defer cancel()
wStream, err := integration.ToGRPC(clus.RandClient()).Watch.Watch(ctx) // No call options passed to gRPC
require.Nil(t, err)

As a result gRPC uses the default value of 4MB as the max receive size.

Passing a call option during stream creation makes the test pass.

wStream, err := integration.ToGRPC(clus.RandClient()).Watch.Watch(ctx, grpc.MaxCallRecvMsgSize(math.MaxInt32))

[ahrtr]

Passing a call option during stream creation makes the test pass.

wStream, err := integration.ToGRPC(clus.RandClient()).Watch.Watch(ctx, grpc.MaxCallRecvMsgSize(math.MaxInt32))

Thanks @arjan-bal . Also Thanks @easwars . Actually the etcd client automatically adds such grpc option by default.

@kevburnsjr Note that you won't see this issue if you call the client.Watch interface. See below, let me know whether if it resolve your problem.

etcd/client/v3/watch.go

Line 82 in ef65923

Watch(ctx context.Context, key string, opts ...OpOption) WatchChan

etcd/client/v3/watch.go

Line 298 in ef65923

func (w *watcher) Watch(ctx context.Context, key string, opts ...OpOption) WatchChan {

[ahrtr]

https://github.com/etcd-io/etcd/blob/main/tests/integration/clientv3/watch_fragment_test.go#L38-L46

It's because the test case intentionally sets a 1.5MiB max recv msg size.

etcd/tests/integration/clientv3/watch_fragment_test.go

Line 73 in ef65923

cfg.ClientMaxCallRecvMsgSize = 1.5 * 1024 * 1024

Please feel free to reopen this ticket if you still have any concern.

Thanks all again!