etcdserver hang with syntactically valid but old token?

[nelljerram]

With this script, and v3.3.11 or v3.3.17, I see that etcdserver does not respond promptly when presented with an Authorization token that is expired but syntactically valid:

#!/bin/bash -x

ETCD_IMAGE=quay.io/coreos/etcd:${ETCD_VERSION:-v3.3.11}

docker rm -f etcdserver || true
docker run \
       --detach \
       --net=host \
       --name etcdserver \
       ${ETCD_IMAGE} \
       etcd \
       --advertise-client-urls "http://127.0.0.1:2379" \
       --listen-client-urls "http://0.0.0.0:2379"

function ectl {
    docker run \
	   --rm \
	   -i \
	   --net=host \
	   -e ETCDCTL_API=3 \
	   -e ETCDCTL_ENDPOINTS=http://127.0.0.1:2379 \
	   ${ETCD_IMAGE} \
	   etcdctl \
	   "$@"
}

ectl user add root --interactive=false <<EOF
rootpasswd
EOF
ectl auth enable

time timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3alpha/kv/range -X POST -d '{"key": "L2NhbGljbwo="}'

time timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3alpha/kv/range -H 'Authorization: IsbMEkdCkHxvTUkO.22' -X POST -d '{"key": "L2NhbGljbwo="}'

time timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3alpha/kv/range -H 'Authorization: IsbMEkdCkHxvTUkO.' -X POST -d '{"key": "L2NhbGljbwo="}'

The output for the last 3 curls shows:

+ timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3alpha/kv/range -X POST -d '{"key": "L2NhbGljbwo="}'
{"error":"etcdserver: user name is empty","code":3}400
real	0m0.008s
user	0m0.006s
sys	0m0.001s
+ timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3alpha/kv/range -H 'Authorization: IsbMEkdCkHxvTUkO.22' -X POST -d '{"key": "L2NhbGljbwo="}'

real	0m5.003s
user	0m0.008s
sys	0m0.002s
+ timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3alpha/kv/range -H 'Authorization: IsbMEkdCkHxvTUkO.' -X POST -d '{"key": "L2NhbGljbwo="}'
{"error":"etcdserver: invalid auth token","code":16}401
real	0m0.013s
user	0m0.007s
sys	0m0.005s

In other words, with no Authorization header, or with a malformed token, we get an immediate negative response (which is good). But with a well formed but non-current token, the etcd server appears to hang. (In other experiments, I've waited up to a minute.)

Is this behavior explicable or somehow expected?

[mitake]

This is a bug fixed in #10218 Could you try the latest master?

[jingyih]

etcd 3.4 releases should also have this fix.

[nelljerram]

Thanks. Would it make sense to cherry pick for a new v3.3.x release as well, or is that EOL now?

I did also try a v3.4 release earlier, but then I got 404 for those URLs above. Do they need to be adjusted in some way for v3.4?

[jingyih]

etcd v3.4 uses [CLIENT-URL]/v3/* while keeping [CLIENT-URL]/v3beta/.
[CLIENT-URL]/v3alpha/ is deprecated.

[jingyih]

I think it is reasonable to cherry pick the fix to 3.3.

[nelljerram]

Perhaps I'm doing this wrong, but I think I'm still seeing a problem with master...

I couldn't see a :master image on quay or docker hub, so I built like this:

./test
ETCD_VERSION=v3-test make build-docker-release-master

Then ran the script above with image changed to gcr.io/etcd-development/etcd and v3alpha changed to v3, and I get:

neil@glaurung:~/go/src/github.com/openstack$ ETCD_IMAGE=gcr.io/etcd-development/etcd:v3-test URL_PATH=v3 ./etcdhang.sh
+ ETCD_IMAGE=gcr.io/etcd-development/etcd:v3-test
+ URL_PATH=v3
+ docker rm -f etcdserver
Error: No such container: etcdserver
+ true
+ docker run --detach --net=host --name etcdserver gcr.io/etcd-development/etcd:v3-test etcd --advertise-client-urls http://127.0.0.1:2379 --listen-client-urls http://0.0.0.0:2379
e7d8c1a88a698803b5afa94a21a10a3c5c40ab2cd6a0447a4006192b1f2f213c
+ ectl user add root --interactive=false
+ docker run --rm -i --net=host -e ETCDCTL_API=3 -e ETCDCTL_ENDPOINTS=http://127.0.0.1:2379 gcr.io/etcd-development/etcd:v3-test etcdctl user add root --interactive=false
User root created
+ ectl auth enable
+ docker run --rm -i --net=host -e ETCDCTL_API=3 -e ETCDCTL_ENDPOINTS=http://127.0.0.1:2379 gcr.io/etcd-development/etcd:v3-test etcdctl auth enable
{"level":"warn","ts":"2019-11-21T00:53:42.177Z","caller":"clientv3/retry_interceptor.go:61","msg":"retrying of unary invoker failed","target":"endpoint://client-d234821a-4bd8-4aa8-b6af-522909a1f61c/127.0.0.1:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: root user does not have root role"}
Authentication Enabled
+ timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3/kv/range -X POST -d '{"key": "L2NhbGljbwo="}'
{"error":"etcdserver: user name is empty","message":"etcdserver: user name is empty","code":3}400
real	0m0.010s
user	0m0.009s
sys	0m0.000s
+ timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3/kv/range -H 'Authorization: IsbMEkdCkHxvTUkO.22' -X POST -d '{"key": "L2NhbGljbwo="}'

real	0m5.003s
user	0m0.006s
sys	0m0.004s
+ timeout 5s curl -w '%{http_code}' -L http://127.0.0.1:2379/v3/kv/range -H 'Authorization: IsbMEkdCkHxvTUkO.' -X POST -d '{"key": "L2NhbGljbwo="}'
{"error":"etcdserver: invalid auth token","message":"etcdserver: invalid auth token","code":16}401
real	0m0.010s
user	0m0.000s
sys	0m0.009s

So I'm still seeing the 5s time for the second curl.

[xiang90]

/cc @mitake can you take another look at this?

[mitake]

Sorry for my late reply, I'll take a look at it.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.