Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TTL=0 too soon #6978

Closed
heyitsanthony opened this issue Dec 9, 2016 · 13 comments · Fixed by #7015
Closed

TTL=0 too soon #6978

heyitsanthony opened this issue Dec 9, 2016 · 13 comments · Fixed by #7015
Assignees
Labels

Comments

@heyitsanthony
Copy link
Contributor

via irc,

Version: 3.0.15

Code: https://github.com/immesys/wdd/blob/dev/actionRunner.go#L237-L253

Client-side logs:

began actionRunner at 2016-12-09 20:44:20.410794237 +0000 UTC
lease ID: 1713998858250880988 &clientv3.LeaseGrantResponse{ResponseHeader:(*etcdserverpb.ResponseHeader)(0xc4206934e0), ID:1713998858250880988, TTL:60, Error:""}
lease problem (resp= &clientv3.LeaseKeepAliveResponse{ResponseHeader:(*etcdserverpb.ResponseHeader)(0xc4205cc440), ID:1713998858250880988, TTL:0}) at 2016-12-09 20:44:20.449213404 +0000 UTC (1713998858250880988)
panic: etcdserver: requested lease not found

So it's triggering the TTL == 0 path in the client to report the lease is gone. However, given that there's a minute-length TTL, the TTL shouldn't be 0 so soon.

About 1/1000 chance of happening.

@fanminshi fanminshi self-assigned this Dec 10, 2016
@immesys
Copy link

immesys commented Dec 10, 2016

It's a cluster of 3 etcd machines, here are the logs for the three machines at the time this happened:

Server 3/3 application logs:

Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: began actionRunner at 2016-12-09 23:20:38.280300978 +0000 UTC
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: lease ID: 1713998858250893126 &clientv3.LeaseGrantResponse{ResponseHeader:(*etcdserverpb.ResponseHeader)(0xc420247aa0), ID:1713998858250893126, TTL:60, Error:""}
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: lease problem (resp= &clientv3.LeaseKeepAliveResponse{ResponseHeader:(*etcdserverpb.ResponseHeader)(0xc420247da0), ID:1713998858250893126, TTL:0}) at 2016-12-09 23:20:38.291247976 +0000 UTC (1713998858250893126)
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: panic: etcdserver: requested lease not found
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: goroutine 30 [running]:
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: panic(0x90d6a0, 0xc420151a60)
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]:         /usr/local/go/src/runtime/panic.go:500 +0x1a1
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: main.actionRunner()
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]:         /home/immesys/w/go/src/github.com/immesys/wdd/actionRunner.go:256 +0x17f3
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: main.actionRunnerLoop()
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]:         /home/immesys/w/go/src/github.com/immesys/wdd/actionRunner.go:309 +0x22
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]: created by main.main
Dec 09 23:20:38 ip-172-30-2-86 wdd[9129]:         /home/immesys/w/go/src/github.com/immesys/wdd/main.go:142 +0x4c
Dec 09 23:20:38 ip-172-30-2-86 systemd[1]: wdd.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Dec 09 23:20:38 ip-172-30-2-86 systemd[1]: wdd.service: Unit entered failed state.
Dec 09 23:20:38 ip-172-30-2-86 systemd[1]: wdd.service: Failed with result 'exit-code'.
Dec 09 23:20:38 ip-172-30-2-86 systemd[1]: wdd.service: Service hold-off time over, scheduling restart.
Dec 09 23:20:38 ip-172-30-2-86 systemd[1]: Stopped wdd.
Dec 09 23:20:38 ip-172-30-2-86 systemd[1]: Started wdd.

Server 3/3 etcd logs:

Dec 09 23:15:25 ip-172-30-2-86 etcd[32563]: compacted raft log at 10636184
Dec 09 23:15:53 ip-172-30-2-86 etcd[32563]: purged file /srv/etcd/member/snap/000000000000001d-0000000000a19bcb.snap successfully
Dec 09 23:16:02 ip-172-30-2-86 etcd[32563]: apply entries took too long [10.319602ms for 1 entries]
Dec 09 23:16:02 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:16:15 ip-172-30-2-86 etcd[32563]: apply entries took too long [13.980275ms for 1 entries]
Dec 09 23:16:15 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:16:50 ip-172-30-2-86 etcd[32563]: store.index: compact 13997656
Dec 09 23:16:52 ip-172-30-2-86 etcd[32563]: finished scheduled compaction at 13997656 (took 1.111694177s)
Dec 09 23:17:48 ip-172-30-2-86 etcd[32563]: apply entries took too long [21.53577ms for 1 entries]
Dec 09 23:17:48 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:17:52 ip-172-30-2-86 etcd[32563]: apply entries took too long [10.891494ms for 1 entries]
Dec 09 23:17:52 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:17:57 ip-172-30-2-86 etcd[32563]: apply entries took too long [10.97979ms for 1 entries]
Dec 09 23:17:57 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:18:52 ip-172-30-2-86 etcd[32563]: apply entries took too long [16.315694ms for 1 entries]
Dec 09 23:18:52 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:19:54 ip-172-30-2-86 etcd[32563]: apply entries took too long [15.228846ms for 1 entries]
Dec 09 23:19:54 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:20:07 ip-172-30-2-86 etcd[32563]: apply entries took too long [14.42986ms for 1 entries]
Dec 09 23:20:07 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:20:18 ip-172-30-2-86 etcd[32563]: apply entries took too long [11.783642ms for 1 entries]
Dec 09 23:20:18 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:20:33 ip-172-30-2-86 etcd[32563]: apply entries took too long [10.887894ms for 1 entries]
Dec 09 23:20:33 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:20:49 ip-172-30-2-86 etcd[32563]: apply entries took too long [13.208403ms for 1 entries]
Dec 09 23:20:49 ip-172-30-2-86 etcd[32563]: avoid queries with large range/delete range!
Dec 09 23:21:09 ip-172-30-2-86 etcd[32563]: start to snapshot (applied: 10651185, lastsnap: 10641184)
Dec 09 23:21:09 ip-172-30-2-86 etcd[32563]: saved snapshot at index 10651185
Dec 09 23:21:09 ip-172-30-2-86 etcd[32563]: compacted raft log at 10646185
Dec 09 23:21:23 ip-172-30-2-86 etcd[32563]: purged file /srv/etcd/member/snap/000000000000001d-0000000000a1c2dc.snap successfully
Dec 09 23:21:29 ip-172-30-2-86 etcd[32563]: apply entries took too long [13.671298ms for 1 entries]

Server 2/3 etcd logs:

Dec 09 23:19:54 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:19:56 ip-172-30-0-123 etcd[16048]: apply entries took too long [11.438076ms for 1 entries]
Dec 09 23:19:56 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:11 ip-172-30-0-123 etcd[16048]: apply entries took too long [11.860611ms for 1 entries]
Dec 09 23:20:11 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:16 ip-172-30-0-123 etcd[16048]: apply entries took too long [19.643459ms for 1 entries]
Dec 09 23:20:16 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:22 ip-172-30-0-123 etcd[16048]: apply entries took too long [17.38268ms for 1 entries]
Dec 09 23:20:22 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:29 ip-172-30-0-123 etcd[16048]: apply entries took too long [11.581141ms for 1 entries]
Dec 09 23:20:29 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:31 ip-172-30-0-123 etcd[16048]: apply entries took too long [10.472098ms for 1 entries]
Dec 09 23:20:31 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:37 ip-172-30-0-123 etcd[16048]: apply entries took too long [29.638966ms for 1 entries]
Dec 09 23:20:37 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:37 ip-172-30-0-123 etcd[16048]: apply entries took too long [11.9494ms for 1 entries]
Dec 09 23:20:37 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:41 ip-172-30-0-123 etcd[16048]: apply entries took too long [11.776336ms for 1 entries]
Dec 09 23:20:41 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:43 ip-172-30-0-123 etcd[16048]: apply entries took too long [13.208463ms for 1 entries]
Dec 09 23:20:43 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:50 ip-172-30-0-123 etcd[16048]: apply entries took too long [16.989491ms for 1 entries]
Dec 09 23:20:50 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:50 ip-172-30-0-123 etcd[16048]: apply entries took too long [12.737201ms for 1 entries]
Dec 09 23:20:50 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:20:51 ip-172-30-0-123 etcd[16048]: apply entries took too long [11.580143ms for 1 entries]
Dec 09 23:20:51 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:21:02 ip-172-30-0-123 etcd[16048]: apply entries took too long [15.476916ms for 1 entries]
Dec 09 23:21:02 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:21:07 ip-172-30-0-123 etcd[16048]: start to snapshot (applied: 10651128, lastsnap: 10641127)
Dec 09 23:21:07 ip-172-30-0-123 etcd[16048]: saved snapshot at index 10651128
Dec 09 23:21:07 ip-172-30-0-123 etcd[16048]: compacted raft log at 10646128
Dec 09 23:21:08 ip-172-30-0-123 etcd[16048]: apply entries took too long [13.548155ms for 1 entries]
Dec 09 23:21:08 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!
Dec 09 23:21:09 ip-172-30-0-123 etcd[16048]: apply entries took too long [11.168493ms for 1 entries]
Dec 09 23:21:09 ip-172-30-0-123 etcd[16048]: avoid queries with large range/delete range!

Server 1/3 etcd logs:

Dec 09 23:19:13 ip-10-42-12-114 etcd[10497]: avoid queries with large range/delete range!
Dec 09 23:20:32 ip-10-42-12-114 etcd[10497]: apply entries took too long [12.001082ms for 1 entries]
Dec 09 23:20:32 ip-10-42-12-114 etcd[10497]: avoid queries with large range/delete range!
Dec 09 23:21:06 ip-10-42-12-114 etcd[10497]: start to snapshot (applied: 10651085, lastsnap: 10641084)
Dec 09 23:21:06 ip-10-42-12-114 etcd[10497]: saved snapshot at index 10651085
Dec 09 23:21:06 ip-10-42-12-114 etcd[10497]: compacted raft log at 10646085
Dec 09 23:21:27 ip-10-42-12-114 etcd[10497]: purged file /srv/etcd/member/snap/000000000000001d-0000000000a1c278.snap successfully
Dec 09 23:21:32 ip-10-42-12-114 etcd[10497]: apply entries took too long [12.646203ms for 1 entries]
Dec 09 23:21:32 ip-10-42-12-114 etcd[10497]: avoid queries with large range/delete range!
Dec 09 23:22:29 ip-10-42-12-114 etcd[10497]: apply entries took too long [13.096274ms for 1 entries]

@immesys
Copy link

immesys commented Dec 10, 2016

For reference, the three servers are located in different EC2 regions. They have GP SSD drives. I haven't had time yet to work out why I am getting warnings about apply entries taking too long, I'm not an etcd expert. Not sure if this information was relevant.

@fanminshi
Copy link
Member

@immesys https://github.com/coreos/etcd/blob/master/Documentation/faq.md#what-does-the-etcd-warning-apply-entries-took-too-long-mean explains why you see apply entries took too long warning. I think the limit is set to 10 ms for the version that you are using right now. it will be increase to 100ms in the coming up release.

@fanminshi
Copy link
Member

@immesys what timezone are your other etcd servers live in? are they in same timezone? by default, etcd server side logging uses local timezone.
You client side logging indicate time in UTC and your server side logging might be using local zone. Could you double check that your previous logging pastes are time aligned correctly.

@fanminshi
Copy link
Member

@immesys could you possibly provide a simpler script that I can reproduce the issue locally?

@immesys
Copy link

immesys commented Dec 13, 2016

Sure I can try make one. I haven't had a chance to triple check my timezones but I usually keep all my servers in UTC so I would be surprised if the logs did not line up.

@heyitsanthony
Copy link
Contributor Author

heyitsanthony commented Dec 13, 2016

I was able to reproduce this with the stock 3-member goreman cluster on both 3.0.15 and master using tmpfs:

package main

import (
        "fmt"
        "github.com/coreos/etcd/clientv3"

        "golang.org/x/net/context"
)

func stress(s string) {
        cfg := clientv3.Config{Endpoints: []string{s}}
        cli, err := clientv3.New(cfg)
        if err != nil {
                fmt.Println(err)
                return
        }
        i := 0
        for {
                resp, gerr := cli.Grant(context.TODO(), 60)
                if gerr != nil {
                        panic(gerr)
                }
                _, kerr := cli.KeepAliveOnce(context.TODO(), resp.ID)
                if kerr != nil {
                        panic(kerr)
                }
                cli.Revoke(context.TODO(), resp.ID)
                fmt.Println(s, i)
                i++
        }
}

func main() {
        for i := 0; i < 10; i++ {
                go stress("http://localhost:2379")
        }
        stress("http://localhost:2379")
}

I could not reproduce it with a single node cluster.

@immesys
Copy link

immesys commented Dec 13, 2016

@heyitsanthony Do you know if I could switch to a different version in the meantime? Is this present in the 3.1 rc?

@heyitsanthony
Copy link
Contributor Author

@immesys nope, this case looks all around broken, sorry :(

Now, this isn't a true fix, but since the cause may take some time to figure out: is there a reason why that code must immediately call KeepAliveOnce? I think this is a race isolated to creating renew streams. Another way to structure the loop without the KeepAliveOnce:

kactx, kcancel := context.WithCancel()
defer kcancel()
if _, err := cli.KeepAlive(kactx, leaseId); err != nil { panic(err) }
for _, ev := range resp.Kvs { ....}
cli.Revoke(context.Background(), leaseId)

This is a lot cheaper because it'll use a single renew stream per client and it keeps a timer so it doesn't have to send a keep alive message for every loop iteration. Even if it doesn't patch over the problem (it seems to mask it in the stress test), it'll still save some bandwidth.

@immesys
Copy link

immesys commented Dec 13, 2016

@heyitsanthony Thanks! I'll change my code to do that.
EDIT: The reason I structured my code with KeepAliveOnce is that I wanted to protect against the case where the loop body deadlocks and doesn't progress. My understanding is that the lease will continue to be maintained in that case by the KeepAlive goroutine, stopping other servers from progressing. I can obviously work around this (especially if the KeepAlive stops when the context times out), but I thought I would mention why I structured it like that in the first place.

@fanminshi
Copy link
Member

I added some server side debugging for this issue by running @heyitsanthony's script.

The problem only occurs if the client talks to a follower not a leader. In that way, the follower must redirect Renew request to the leader. From the following log, you can see that the client Grant req returns before the leader stores the newly granted lease. Then immediately, client looks up the lease in the leader via redirect from the follower where leader hasn't store the lease yet, and then the leader couldn't find it. Thus, the leader returns requested lease not found error to client.

client (url: http://localhost:22379):

2016-12-13 13:25:41.9853106 grant lease id 4703544691928416115
2016-12-13 13:25:42.0485981 renew lease id 4703544691928416115

Server:
etcd1 is the leader

2016-12-13 13:25:41.985682 etcd2 | DEBUG EtcdServer.LeaseGrant() req {60 4703544691928416115} leaseID 4703544691928416115
2016-12-13 13:25:42.048048 etcd2 | DEBUG lessor.Grant() lease id 4703544691928416115
2016-12-13 13:25:42.048053 etcd2 | DEBUG lessor.Grant() id 4703544691928416115 updating le.leaseMap
2016-12-13 13:25:42.048059 etcd2 | DEBUG lessor.Grant() id 4703544691928416115 updating le.leaseMap finished

// EtcdServer.LeaseGrant() returns when etcd2 finishes its lessor.Grant() but does not wait for other nodes to finish their lessor.Grant(). 

2016-12-13 13:25:42.048119 etcd2 | DEBUG EtcdServer.LeaseGrant() done resp (header:<revision:1 > ID:4703544691928416115 TTL:60 )

// client starts to call LeaseRenew() at this point.

2016-12-13 13:25:42.048932 etcd2 | DEBUG EtcdServer.LeaseRenew() leaseID 4703544691928416115 I am not a leader
2016-12-13 13:25:42.048896 etcd2 | DEBUG lessor.Renew() I am not a primary lessor. Looking up lease id 4703544691928416115

// etcd follower redirects LeaseRenew() req to the leader

2016-12-13 13:25:42.061091 etcd1 | DEBUG lessor.Grant() lease id 4703544691928416115
2016-12-13 13:25:42.061171 etcd1 | DEBUG lessor.Renew() I am a primary lessor. Looking up lease id 4703544691928416115
2016-12-13 13:25:42.061179 etcd1 | DEBUG lessor.Renew() I am a primary lessor. Looking up lease id 4703544691928416115 not found

// lessor.Renew() could not find the lease because the original grant request has not being applied at etcd 1(leader) yet

2016-12-13 13:25:42.061295 etcd1 | DEBUG lessor.Grant() id 4703544691928416115 updating le.leaseMap
2016-12-13 13:25:42.061304 etcd1 | DEBUG lessor.Grant() id 4703544691928416115 updating le.leaseMap finished

@fanminshi
Copy link
Member

The issue does not just affect the KeepAliveOnce() but also TimeToLive(). I replace cli.KeepAliveOnce(context.TODO(), resp.ID) => cli.TimeToLive(context.TODO(), resp.ID) from @heyitsanthony's script. Same issue happens.

fanminshi added a commit to fanminshi/etcd that referenced this issue Dec 15, 2016
…erations

suppose a lease granting request from a follower goes through and followed by a lease look up or renewal, the leader might not apply the lease grant request locally. So the leader might not find the lease from the lease look up or renewal request which will result lease not found error. To fix this issue, we force the leader to apply its pending commited index before looking up lease.

FIX etcd-io#6978
fanminshi added a commit to fanminshi/etcd that referenced this issue Dec 15, 2016
…erations

suppose a lease granting request from a follower goes through and followed by a lease look up or renewal, the leader might not apply the lease grant request locally. So the leader might not find the lease from the lease look up or renewal request which will result lease not found error. To fix this issue, we force the leader to apply its pending commited index before looking up lease.

FIX etcd-io#6978
fanminshi added a commit to fanminshi/etcd that referenced this issue Dec 15, 2016
…erations

suppose a lease granting request from a follower goes through and followed by a lease look up or renewal, the leader might not apply the lease grant request locally. So the leader might not find the lease from the lease look up or renewal request which will result lease not found error. To fix this issue, we force the leader to apply its pending commited index before looking up lease.

FIX etcd-io#6978
fanminshi added a commit to fanminshi/etcd that referenced this issue Dec 16, 2016
…erations

suppose a lease granting request from a follower goes through and followed by a lease look up or renewal, the leader might not apply the lease grant request locally. So the leader might not find the lease from the lease look up or renewal request which will result lease not found error. To fix this issue, we force the leader to apply its pending commited index before looking up lease.

FIX etcd-io#6978
fanminshi added a commit to fanminshi/etcd that referenced this issue Dec 16, 2016
…erations

suppose a lease granting request from a follower goes through and followed by a lease look up or renewal, the leader might not apply the lease grant request locally. So the leader might not find the lease from the lease look up or renewal request which will result lease not found error. To fix this issue, we force the leader to apply its pending commited index before looking up lease.

FIX etcd-io#6978
fanminshi added a commit to fanminshi/etcd that referenced this issue Dec 16, 2016
…erations

suppose a lease granting request from a follower goes through and followed by a lease look up or renewal, the leader might not apply the lease grant request locally. So the leader might not find the lease from the lease look up or renewal request which will result lease not found error. To fix this issue, we force the leader to apply its pending commited index before looking up lease.

FIX etcd-io#6978
fanminshi added a commit to fanminshi/etcd that referenced this issue Dec 16, 2016
…erations

suppose a lease granting request from a follower goes through and followed by a lease look up or renewal, the leader might not apply the lease grant request locally. So the leader might not find the lease from the lease look up or renewal request which will result lease not found error. To fix this issue, we force the leader to apply its pending commited index before looking up lease.

FIX etcd-io#6978
fanminshi added a commit to fanminshi/etcd that referenced this issue Dec 22, 2016
…erations

suppose a lease granting request from a follower goes through and followed by a lease look up or renewal, the leader might not apply the lease grant request locally. So the leader might not find the lease from the lease look up or renewal request which will result lease not found error. To fix this issue, we force the leader to apply its pending commited index before looking up lease.

FIX etcd-io#6978
@fanminshi
Copy link
Member

@immesys I pushed out a fix for this issue. If you checkout the latest version from etcd master branch, it should solve this problem. Please reach out if this fix doesn't solve this problem on your side.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Development

Successfully merging a pull request may close this issue.

3 participants