diff --git a/etcdserver/server.go b/etcdserver/server.go index e34fafbdd5f..23e719ccf96 100644 --- a/etcdserver/server.go +++ b/etcdserver/server.go @@ -765,7 +765,10 @@ func (s *EtcdServer) applyAll(ep *etcdProgress, apply *apply) { } func (s *EtcdServer) applySnapshot(ep *etcdProgress, apply *apply) { + plog.Info("start applySnapshot") + if raft.IsEmptySnap(apply.snapshot) { + plog.Info("start applySnapshot raft.IsEmptySnap() returns true. exit") return } @@ -863,6 +866,7 @@ func (s *EtcdServer) applySnapshot(ep *etcdProgress, apply *apply) { ep.appliedi = apply.snapshot.Metadata.Index ep.snapi = ep.appliedi ep.confState = apply.snapshot.Metadata.ConfState + plog.Info("applySnapshot done") } func (s *EtcdServer) applyEntries(ep *etcdProgress, apply *apply) { diff --git a/pkg/netutil/isolate_linux.go b/pkg/netutil/isolate_linux.go index c0128a5a50b..845a74085ca 100644 --- a/pkg/netutil/isolate_linux.go +++ b/pkg/netutil/isolate_linux.go @@ -43,7 +43,9 @@ func RecoverPort(port int) error { // SetLatency adds latency in millisecond scale with random variations. func SetLatency(ms, rv int) error { + fmt.Printf("SetLatency ms %v rv %v\n", ms, rv) ifce, err := GetDefaultInterface() + fmt.Printf("SetLatency GetDefaultInterface() status: ifce %v, err (%v)\n", ifce, err) if err != nil { return err } @@ -52,24 +54,37 @@ func SetLatency(ms, rv int) error { rv = 1 } cmdStr := fmt.Sprintf("sudo tc qdisc add dev %s root netem delay %dms %dms distribution normal", ifce, ms, rv) + fmt.Printf("SetLatency cmd: %v\n", cmdStr) _, err = exec.Command("/bin/sh", "-c", cmdStr).Output() if err != nil { + fmt.Printf("SetLatency cmd: %v error (%v)\n", cmdStr, err) // the rule has already been added. Overwrite it. cmdStr = fmt.Sprintf("sudo tc qdisc change dev %s root netem delay %dms %dms distribution normal", ifce, ms, rv) + fmt.Printf("SetLatency cmd: %v\n", cmdStr) _, err = exec.Command("/bin/sh", "-c", cmdStr).Output() if err != nil { + fmt.Printf("SetLatency cmd: %v error (%v)\n", cmdStr, err) return err } } + fmt.Printf("SetLatency ms %v rv %v done\n", ms, rv) + return nil } // RemoveLatency resets latency configurations. func RemoveLatency() error { + fmt.Printf("RemoveLatency\n") ifce, err := GetDefaultInterface() + fmt.Printf("RemoveLatency GetDefaultInterface() status: ifce %v, err (%v)\n", ifce, err) if err != nil { return err } - _, err = exec.Command("/bin/sh", "-c", fmt.Sprintf("sudo tc qdisc del dev %s root netem", ifce)).Output() + cmdStr := fmt.Sprintf("sudo tc qdisc del dev %s root netem", ifce) + fmt.Printf("RemoveLatency cmd: %v\n", cmdStr) + _, err = exec.Command("/bin/sh", "-c", cmdStr).Output() + if err != nil { + fmt.Printf("RemoveLatency cmd: %v\n error (%v)\n", cmdStr, err) + } return err } diff --git a/raft/raft.go b/raft/raft.go index 288989d16c3..51b373f5c90 100644 --- a/raft/raft.go +++ b/raft/raft.go @@ -1102,10 +1102,14 @@ func (r *raft) handleSnapshot(m pb.Message) { r.logger.Infof("%x [commit: %d] restored snapshot [index: %d, term: %d]", r.id, r.raftLog.committed, sindex, sterm) r.send(pb.Message{To: m.From, Type: pb.MsgAppResp, Index: r.raftLog.lastIndex()}) + r.logger.Infof("%x [commit: %d] restored snapshot [index: %d, term: %d] sent MsgApp", + r.id, r.raftLog.committed, sindex, sterm) } else { r.logger.Infof("%x [commit: %d] ignored snapshot [index: %d, term: %d]", r.id, r.raftLog.committed, sindex, sterm) r.send(pb.Message{To: m.From, Type: pb.MsgAppResp, Index: r.raftLog.committed}) + r.logger.Infof("%x [commit: %d] ignored snapshot [index: %d, term: %d] sent MsgApp", + r.id, r.raftLog.committed, sindex, sterm) } } diff --git a/tools/functional-tester/etcd-tester/checks.go b/tools/functional-tester/etcd-tester/checks.go index a648d53bffb..e919b4eef93 100644 --- a/tools/functional-tester/etcd-tester/checks.go +++ b/tools/functional-tester/etcd-tester/checks.go @@ -80,15 +80,15 @@ func (hc *hashChecker) Check() error { type leaseChecker struct{ ls *leaseStresser } func (lc *leaseChecker) Check() error { - plog.Infof("checking revoked leases %v", lc.ls.revokedLeases.leases) + plog.Debugf("checking revoked leases %v", lc.ls.revokedLeases.leases) if err := lc.check(true, lc.ls.revokedLeases.leases); err != nil { return err } - plog.Infof("checking alive leases %v", lc.ls.aliveLeases.leases) + plog.Debugf("checking alive leases %v", lc.ls.aliveLeases.leases) if err := lc.check(false, lc.ls.aliveLeases.leases); err != nil { return err } - plog.Infof("checking short lived leases %v", lc.ls.shortLivedLeases.leases) + plog.Debugf("checking short lived leases %v", lc.ls.shortLivedLeases.leases) return lc.checkShortLivedLeases() } @@ -122,14 +122,14 @@ func (lc *leaseChecker) checkShortLivedLease(ctx context.Context, leaseID int64) return nil } if err != nil { - plog.Warningf("retry %d. failed to retrieve lease %v error (%v)", i, leaseID, err) + plog.Debugf("retry %d. failed to retrieve lease %v error (%v)", i, leaseID, err) continue } if resp.TTL > 0 { - plog.Warningf("lease %v is not expired. sleep for %d until it expires.", leaseID, resp.TTL) + plog.Debugf("lease %v is not expired. sleep for %d until it expires.", leaseID, resp.TTL) time.Sleep(time.Duration(resp.TTL) * time.Second) } else { - plog.Warningf("retry %d. lease %v is expired but not yet revoked", i, leaseID) + plog.Debugf("retry %d. lease %v is expired but not yet revoked", i, leaseID) time.Sleep(time.Second) } if err = lc.checkLease(ctx, false, leaseID); err != nil { diff --git a/tools/functional-tester/etcd-tester/failure_agent.go b/tools/functional-tester/etcd-tester/failure_agent.go index 5dddec5302f..d2545588822 100644 --- a/tools/functional-tester/etcd-tester/failure_agent.go +++ b/tools/functional-tester/etcd-tester/failure_agent.go @@ -98,18 +98,26 @@ func newFailureIsolateAll() failure { } func injectLatency(m *member) error { + plog.Printf("%v Injecting Latency", m.ClientURL) if err := m.Agent.SetLatency(slowNetworkLatency, randomVariation); err != nil { - m.Agent.RemoveLatency() + plog.Printf("%v Injecting Latency error (%v)", m.ClientURL, err) + rErr := m.Agent.RemoveLatency() + plog.Printf("%v Injecting Latency's Removing Latency status %v", m.ClientURL, rErr) return err } + plog.Printf("%v Injecting Latency done", m.ClientURL) return nil } func recoverLatency(m *member) error { + plog.Printf("%v recovering Latency", m.ClientURL) if err := m.Agent.RemoveLatency(); err != nil { + plog.Printf("%v recovering Latency error (%v)", m.ClientURL, err) return err } + plog.Printf("%v recovering Latency sleep for %v", m.ClientURL, waitRecover) time.Sleep(waitRecover) + plog.Printf("%v recovering Latency done", m.ClientURL) return nil } diff --git a/tools/functional-tester/etcd-tester/main.go b/tools/functional-tester/etcd-tester/main.go index 18ecfcb53f1..b2441e3a3f8 100644 --- a/tools/functional-tester/etcd-tester/main.go +++ b/tools/functional-tester/etcd-tester/main.go @@ -167,16 +167,23 @@ func makeFailures(types string, c *cluster) []failure { switch fails[i] { case "default": defaultFailures := []failure{ - newFailureKillAll(), - newFailureKillMajority(), - newFailureKillOne(), - newFailureKillLeader(), - newFailureKillOneForLongTime(), - newFailureKillLeaderForLongTime(), - newFailureIsolate(), - newFailureIsolateAll(), - newFailureSlowNetworkOneMember(), - newFailureSlowNetworkLeader(), + // newFailureKillAll(), + // newFailureKillMajority(), + // newFailureKillOne(), + // newFailureKillLeader(), + // newFailureKillOneForLongTime(), + // newFailureKillLeaderForLongTime(), + // newFailureIsolate(), + // newFailureIsolateAll(), + // newFailureSlowNetworkOneMember(), + // newFailureSlowNetworkLeader(), + newFailureSlowNetworkAll(), + newFailureSlowNetworkAll(), + newFailureSlowNetworkAll(), + newFailureSlowNetworkAll(), + newFailureSlowNetworkAll(), + newFailureSlowNetworkAll(), + newFailureSlowNetworkAll(), newFailureSlowNetworkAll(), } failures = append(failures, defaultFailures...)