clientv3 doesn't renew the auth token

[ljupchokotev]

The etcd clientv3 doesn't renew the auth token when it expires, it just fails with invalid auth token. It happens with both simple and jwt token types.

Steps to reproduce:

1. Start etcd with etcd --auth-token simple --auth-token-ttl 5
2. Enable authentication

etcdctl user add root
etcdctl user  grant-role  root root
etcdctl auth enable
# Verify that it works
etcdctl --user root:root put test test
etcdctl --user root:root get test

3. Run the following Go program

package main

import (
	"context"
	"fmt"
	"log"
	"time"

	clientv3 "go.etcd.io/etcd/client/v3"
	"google.golang.org/grpc"
)

func main() {
	client, err := clientv3.New(clientv3.Config{
		Context:   context.Background(),
		Endpoints: []string{"127.0.0.1:2379"},
		Username:  "root",
		Password:  "root",
		DialOptions: []grpc.DialOption{
			grpc.WithBlock(),
		},
	})
	if err != nil {
		log.Fatal(err)
	}

	resp, err := client.Get(context.Background(), "test")
	if err != nil {
		log.Fatal(err)
	}

	fmt.Println(resp.Kvs)

	time.Sleep(6 * time.Second)

	_, err = client.Get(context.Background(), "test")
	if err != nil {
		log.Fatal(err)
	}
}

Output:

[key:"test" create_revision:2 mod_revision:2 version:1 value:"test" ]
{"level":"warn","ts":"2021-10-11T11:38:59.474+0200","logger":"etcd-client","caller":"v3@v3.5.0/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0001ef180/#initially=[127.0.0.1:2379]","attempt":0,"error":"rpc error: code = Unauthenticated desc = etcdserver: invalid auth token"}

As you can see, the first client.Get succeeded in fetching the test key, but the second one fails with invalid auth token.

Am I missing something simple here?

EDIT: If you make 10 requests while sleeping for 1 second in-between, the error does not show up.

	for i := 1; i <= 10; i++ {
		time.Sleep(1 * time.Second)
                // no error
		resp, err := client.Get(context.Background(), "test")
		if err != nil {
			log.Fatal(err)
		}

		fmt.Println(resp.Kvs)
	}

	time.Sleep(6 * time.Second)
        // return invalid auth token error
	_, err = client.Get(context.Background(), "test")
	if err != nil {
		log.Fatal(err)
	}

[mitake]

@ljupchokotev which version are you using? Could you try the latest master branch? I think it’s already fixed. Let me backport the change to the stable releases.

[ljupchokotev]

@ljupchokotev which version are you using? Could you try the latest master branch? I think it’s already fixed. Let me backport the change to the stable releases.

Sorry, forgot to include that in the issue. I am using v3.5.0, both etcd cluster and go client. I will try the master branch

[ljupchokotev]

@mitake just tried it with the version from master and it doesn't change the behavior, the client still throws the "invalid auth token" error.

[ljupchokotev]

@mitake in retry_interceptor.go, the client correctly re-authenticates when the initial call fails and retries the request (which succeeds), but the initial error is returned together with the successful response.

There is a log line that is logged each time, the actual return error and response is correct. Looks like the error "invalid auth token" in our app is caused by something else. I will investigate more on our side and see, otherwise I will close this issue in a few days.

[mitake]

@ljupchokotev thanks for checking. BTW did you rebuild your client with the latest version of clientv3 package?

[cfz]

I think it's the same problem with #12385,
I tried both v3.5.1 and latest main branch, and it seems the problem is still there.

[acastong]

We're seeing the same issue after some time for some clients. In this example we started seeing the error after 7d 6h 45min of client being connected:

{"level":"warn","ts":"2021-10-26T09:33:29.570Z","logger":"etcd-client","caller":"v3@v3.5.0/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0004c4700/#initially=[127.0.0.1:2379]","attempt":0,"error":"rpc error: code = Unauthenticated desc = etcdserver: invalid auth token"}

[ahrtr]

@mitake did fixed this issue in commit, but clientv3 is still depending on 3.5.0 api and pkg, please see here.

Users can manually update the go.mod to use the main branch of clientv3, such as,
go.etcd.io/etcd/client/v3 v3.5.0-alpha.0.0.20211026122609-e699a12e15ad

But after running "go mod tidy", it automatically add 3.5.0 version of api and pkg,

	go.etcd.io/etcd/api/v3 v3.5.0 // indirect
	go.etcd.io/etcd/client/pkg/v3 v3.5.0 // indirect

After the fix in commit is merged into the main branch, a new tag, i.e. 3.6.0-rc.1, should be added for api and pkg, and then update the clientv3's go.mod to point to the tags. Otherwises, it will break all new applications which depend-on/try the latest main branch.

[ahrtr]

I just realized that it isn't an issue at all, it is just a warning message, please see retry_interceptor.go#L62-L66.

The clientv3 can get a new token automatically when the error is ErrInvalidAuthToken, please see retry_interceptor.go#L83.

Actually the second "client.Get(context.Background(), "test")" returns the expected K/V, and the err is nil.

The issue I pointed out in previous comment is still valid. The clientv3's go.mod in main branch is still pointing to 3.5.0 version of api and pkg. It is not correct, because an application depends on the newest clientv3 in main branch can't even be compiled successfully.

[mitake]

thanks for checking @ahrtr , I agree with your findings. The warning log message is not harmful at all. Also can we compile the example program if we have the cloned repository of etcd in GOPATH, right?

@ljupchokotev @cfz could you check that it's still reproducible on main? I'm also backporting the fix to release-3.5: #13477

[ahrtr]

Also can we compile the example program if we have the cloned repository of etcd in GOPATH, right?

Yes, I verified that it's working on etcd 3.5.1.

Please note the concern I raised previously isn't valid. Although the clientv3 on main branch is still depending on 3.5.0 pkg & api, the versions are replaced with local directories, please see go.mod#L42-L43 , so it shouldn't be a problem. Actually in golang 1.18, a workspace mode will be supported, in that case, we only need to add a go.work in the top directory and get all the required replace directives included in it.

On the other hand, I think we should remove all the replace directives in the go.mod files in all modules, so as to remove the build level dependencies on the files on local disk. If this is true and accepted, then we do not need the go.work in future.

I raised an issue to track the improvement etcd/issues/13478 .

[cfz]

thanks for checking @ahrtr , I agree with your findings. The warning log message is not harmful at all. Also can we compile the example program if we have the cloned repository of etcd in GOPATH, right?

@ljupchokotev @cfz could you check that it's still reproducible on main? I'm also backporting the fix to release-3.5: #13477

hi @mitake,

i checked latest main branch, and your backport branch (https://github.com/mitake/etcd/tree/backport-13308-to-3.5), both are failed with my test case described in #12385.
maybe you can help me to double check? (the original test case is using v3.4 module.)

[ahrtr]

thanks for checking @ahrtr , I agree with your findings. The warning log message is not harmful at all. Also can we compile the example program if we have the cloned repository of etcd in GOPATH, right?
@ljupchokotev @cfz could you check that it's still reproducible on main? I'm also backporting the fix to release-3.5: #13477

hi @mitake,

i checked latest main branch, and your backport branch (https://github.com/mitake/etcd/tree/backport-13308-to-3.5), both are failed with my test case described in #12385. maybe you can help me to double check? (the original test case is using v3.4 module.)

@cfz The following is my go.mod file for the example, and it's working. Please have a try and let me know the result.

module etcd/tokenRenewDemo

go 1.17

require (
	go.etcd.io/etcd/client/v3 v3.5.1
	google.golang.org/grpc v1.41.0
)

require (
	github.com/coreos/go-semver v0.3.0 // indirect
	github.com/coreos/go-systemd/v22 v22.3.2 // indirect
	github.com/gogo/protobuf v1.3.2 // indirect
	github.com/golang/protobuf v1.5.2 // indirect
	go.etcd.io/etcd/api/v3 v3.5.1 // indirect
	go.etcd.io/etcd/client/pkg/v3 v3.5.1 // indirect
	go.uber.org/atomic v1.7.0 // indirect
	go.uber.org/multierr v1.6.0 // indirect
	go.uber.org/zap v1.17.0 // indirect
	golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4 // indirect
	golang.org/x/sys v0.0.0-20210603081109-ebe580a85c40 // indirect
	golang.org/x/text v0.3.5 // indirect
	google.golang.org/genproto v0.0.0-20210602131652-f16073e35f0c // indirect
	google.golang.org/protobuf v1.26.0 // indirect
)

[cfz]

hi @ahrtr , my mistake. the backport works for this issue.

so there maybe some other please lead to the problem of #12385.

sorry for my late reply....

[ahrtr]

Closing this issue since it's already been fixed in commit

[Yancy0220]

How can the bug in etcd v3.5.13 still exist and be resolved?