Enabling authentication causes noisy logs for every /readyz call

[ahmetb]

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?

We run etcd with authentication enabled, we have a service discovery system that frequently polls the /readyz HTTP endpoint on etcd server. For every /readyz request, etcd prints two log statements saying "deleted a simple token". Example output:

{"level":"info","ts":"2024-06-28T11:55:48.638643-0700",
  "caller":"auth/simple_token.go:170",
  "msg":"deleted a simple token",
  "user-name":"root","token":"swUCgfCSXzbNbVvM.0"}
...

Combined with the fact that our service discovery system polls this endpoint every 5 seconds, practically this statement single handedly emits most of the logs we get out of etcd.

What did you expect to happen?

No logs at the default level for something inconsequential like this.

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

1. Run etcd server on a macOS terminal

   etcd --auth-token-ttl=5
   

2. In another terminal window, add a user, then enable authentication

   etcdctl user add root:root
   etcdctl auth enable
   

3. Make a few successive /readyz queries back to back

   curl 127.0.0.1:2379/readyz 
   

4. Wait 5 seconds, and observe logs are flooded with this:

    {"level":"info","ts":"2024-06-28T11:55:48.638643-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"swUCgfCSXzbNbVvM.0"}
    {"level":"info","ts":"2024-06-28T11:55:48.638762-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"HbaByRCspoGGJDSQ.0"}
    {"level":"info","ts":"2024-06-28T11:55:50.638493-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"JHPWIPccneJuHHVo.0"}
    {"level":"info","ts":"2024-06-28T11:55:50.638675-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"bPwzKSxHgcHAqDWY.0"}
    {"level":"info","ts":"2024-06-28T11:55:50.638696-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"vHLnwqtzzYivgdjW.0"}
    {"level":"info","ts":"2024-06-28T11:55:50.638828-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"JorAHnUcTharTcGT.0"}
    {"level":"info","ts":"2024-06-28T11:55:50.638845-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"fEcjpFDKzbpmdymM.0"}
    {"level":"info","ts":"2024-06-28T11:55:50.638861-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"nqjiEIoiBHwIMEIz.0"}
    {"level":"info","ts":"2024-06-28T11:55:50.638875-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"AdmAVtAzjwEdYnmV.0"}
    {"level":"info","ts":"2024-06-28T11:55:50.638888-0700","caller":"auth/simple_token.go:170","msg":"deleted a simple token","user-name":"root","token":"lzlBlKmLtPrTxzrh.0"}
   

Anything else we need to know?

No response

Etcd version (please run commands below)

$ etcd --version
etcd Version: 3.5.13
Git SHA: c9063a0dc
Go Version: go1.22.1
Go OS/Arch: darwin/arm64

$ etcdctl version
etcdctl version: 3.5.13
API version: 3.5

Etcd configuration (command line flags or environment variables)

etcd --auth-token-ttl=5

(shortened the TTL to illustrate the problem).

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

Not applicable.

Relevant log output

No response

[serathius]

cc @siyuanfoundation

[siyuanfoundation]

Thanks @ahmetb for reporting this issue.
This happens because whenever \readyz is called, a root token is created to check if read is healthy.

etcd/server/etcdserver/api/etcdhttp/health.go

Line 429 in 04082b7

ctx = srv.AuthStore().WithRoot(ctx)

@serathius does it make sense to log the msg of "deleted a simple token" at debug level instead of info level?

[serathius]

Sounds good.

[ivanvc]

@ahmetb, can you help backporting the fix to release-3.5? Thanks

[ahmetb]

@ivanvc requires org member permissions, if you have them, please rerun the command on the PR.

[ivanvc]

Ah, we used to do backports manually; we recently enabled the cherrypick plugin. Let me give it a try, but if it needs manual intervention, I don't think I'm allowed to work on top of that branch.

[ivanvc]

@ahmetb, can you open a PR to update 3.5's CHANGELOG with the backport?

[ahmetb]

@ivanvc you got it #18278

[jmhbnz]

Discussed during sig-etcd triage meeting. Closing as complete as main, release-3.5 and CHANGELOG updated. Change will be included in v3.5.15 planned to be released next week.