From 80c692e88daae0d4681a2ee2fb908d658b7b4520 Mon Sep 17 00:00:00 2001 From: tstromberg Date: Fri, 17 May 2019 10:47:26 -0700 Subject: [PATCH 1/8] Add prehistoric system clock synchronization --- pkg/minikube/cluster/cluster.go | 44 ++++++++++++++++++++++++++++++--- 1 file changed, 40 insertions(+), 4 deletions(-) diff --git a/pkg/minikube/cluster/cluster.go b/pkg/minikube/cluster/cluster.go index a8c799e5db39..154369546870 100644 --- a/pkg/minikube/cluster/cluster.go +++ b/pkg/minikube/cluster/cluster.go @@ -23,6 +23,8 @@ import ( "net" "os/exec" "regexp" + "strconv" + "strings" "time" "github.com/docker/machine/libmachine" @@ -119,16 +121,15 @@ func StartHost(api libmachine.API, config cfg.MachineConfig) (*host.Host, error) e := engineOptions(config) glog.Infof("engine options: %+v", e) - err = waitForSSHAccess(h, e) + err = configureHost(h, e) if err != nil { return nil, err } - return h, nil } -func waitForSSHAccess(h *host.Host, e *engine.Options) error { - +// configureHost handles any post-powerup configuration required +func configureHost(h *host.Host, e *engine.Options) error { // Slightly counter-intuitive, but this is what DetectProvisioner & ConfigureAuth block on. console.OutStyle("waiting", "Waiting for SSH access ...") @@ -147,11 +148,46 @@ func waitForSSHAccess(h *host.Host, e *engine.Options) error { if err := h.ConfigureAuth(); err != nil { return &util.RetriableError{Err: errors.Wrap(err, "Error configuring auth on host")} } + if err := forciblyAdjustSystemClock(h); err != nil { + glog.Errorf("failed to adjust clock: %v", err) + } } return nil } +// forciblyAdjustSystemClock adjusts the guests system clock if it differs significantly from the host +func forciblyAdjustSystemClock(h *host.Host) error { + out, err := h.RunSSHCommand("date +%s") + if err != nil { + return errors.Wrap(err, "get clock") + } + clock, err := strconv.ParseInt(strings.TrimSpace(out), 10, 64) + if err != nil { + return errors.Wrap(err, "atoi") + } + glog.Infof("remote clock value: %d", clock) + + // At this point, we are hoping that the guest and the VM manager are synced + // and we have nothing to do. We only interfere when the desync can cause + // certificate issues to arise. + switch diff := time.Now().Unix() - clock; { + case diff < -1: + glog.Warningf("VM clock is %d seconds faster than host.", diff) + case diff > 1: + glog.Warningf("VM clock is %d seconds slower than host.", diff) + case diff > 3: + glog.Warningf("VM clock is running %d seconds faster than host: forcing sync.", diff) + // NOTE: This kind of barbarian one-shot time sync may cause applications to crash. + // However, proper approaches require access to an NTP service. + _, err := h.RunSSHCommand(fmt.Sprintf("sudo date -s @%d", time.Now().Unix())) + if err != nil { + return errors.Wrap(err, "set clock") + } + } + return nil +} + // trySSHPowerOff runs the poweroff command on the guest VM to speed up deletion func trySSHPowerOff(h *host.Host) { s, err := h.Driver.GetState() From 424be87071d3d9891088ba036a351789d3e4bae6 Mon Sep 17 00:00:00 2001 From: tstromberg Date: Fri, 17 May 2019 11:01:58 -0700 Subject: [PATCH 2/8] Improve log messages --- pkg/minikube/cluster/cluster.go | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/pkg/minikube/cluster/cluster.go b/pkg/minikube/cluster/cluster.go index 45af29922968..c70b3416451e 100644 --- a/pkg/minikube/cluster/cluster.go +++ b/pkg/minikube/cluster/cluster.go @@ -160,22 +160,22 @@ func forciblyAdjustSystemClock(h *host.Host) error { if err != nil { return errors.Wrap(err, "get clock") } - clock, err := strconv.ParseInt(strings.TrimSpace(out), 10, 64) + local := time.Now().Unix() + remote, err := strconv.ParseInt(strings.TrimSpace(out), 10, 64) if err != nil { return errors.Wrap(err, "atoi") } - glog.Infof("remote clock value: %d", clock) + diff := local - remote + glog.Infof("local clock: %d - remote clock: %d (diff: %d)", local, remote, diff) - // At this point, we are hoping that the guest and the VM manager are synced - // and we have nothing to do. We only interfere when the desync can cause - // certificate issues to arise. - switch diff := time.Now().Unix() - clock; { + // Only interfere if desync is large enough to cause certificate validation issues + switch { case diff < -1: - glog.Warningf("VM clock is %d seconds faster than host.", diff) + glog.Warningf("VM clock is %d seconds ahead of the host.", diff*-1) case diff > 1: - glog.Warningf("VM clock is %d seconds slower than host.", diff) - case diff > 3: - glog.Warningf("VM clock is running %d seconds faster than host: forcing sync.", diff) + glog.Warningf("VM clock is %d seconds behind the host.", diff) + case diff > 4: + glog.Errorf("VM clock is %d seconds behind the host: forcing sync.", diff) // NOTE: This kind of barbarian one-shot time sync may cause applications to crash. // However, proper approaches require access to an NTP service. _, err := h.RunSSHCommand(fmt.Sprintf("sudo date -s @%d", time.Now().Unix())) From b0d8d7feb343b6f2bc6eecb95eb3d4f6042c19a8 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Tue, 28 May 2019 18:58:56 -0700 Subject: [PATCH 3/8] Refactor for testability --- pkg/minikube/cluster/cluster.go | 70 ++++++++++++++++++++------------- 1 file changed, 42 insertions(+), 28 deletions(-) diff --git a/pkg/minikube/cluster/cluster.go b/pkg/minikube/cluster/cluster.go index c70b3416451e..806c37a12144 100644 --- a/pkg/minikube/cluster/cluster.go +++ b/pkg/minikube/cluster/cluster.go @@ -46,6 +46,13 @@ import ( pkgutil "k8s.io/minikube/pkg/util" ) +var ( + // The maximum the guest VM clock is allowed to be ahead and behind. This value is intentionally + // large to allow for inaccurate methodology, but still small enough so that certificates are likely valid. + maximumClockAhead = time.Duration(-2 * time.Millisecond) + maximumClockBehind = time.Duration(2 * time.Millisecond) +) + //This init function is used to set the logtostderr variable to false so that INFO level log info does not clutter the CLI //INFO lvl logging is displayed due to the kubernetes api calling flag.Set("logtostderr", "true") in its init() //see: https://github.com/kubernetes/kubernetes/blob/master/pkg/kubectl/util/logs/logs.go#L32-L34 @@ -146,44 +153,51 @@ func configureHost(h *host.Host, e *engine.Options) error { if err := h.ConfigureAuth(); err != nil { return &util.RetriableError{Err: errors.Wrap(err, "Error configuring auth on host")} } - if err := forciblyAdjustSystemClock(h); err != nil { - glog.Errorf("failed to adjust clock: %v", err) + d, err := guestClockDelta(h) + if err != nil { + glog.Warningf("Unable to measure system clock delta: %v", err) + return nil + } + if d > maximumClockBehind || d < maximumClockAhead { + glog.Infof("system clock delta is within tolerence: %s", d) + return nil + } + if err := adjustGuestClock(h, d); err != nil { + return errors.Wrap(err, "adjusting system clock") } } return nil } -// forciblyAdjustSystemClock adjusts the guests system clock if it differs significantly from the host -func forciblyAdjustSystemClock(h *host.Host) error { - out, err := h.RunSSHCommand("date +%s") +// systemClockDelta returns the approximate difference between the host and guest system clock +// NOTE: This does not currently take into account ssh latency. +func guestClockDelta(h *host.Host) (time.Duration, error) { + local := time.Now() + out, err := h.RunSSHCommand("date +%s.%N") if err != nil { - return errors.Wrap(err, "get clock") + return 0, errors.Wrap(err, "get clock") } - local := time.Now().Unix() - remote, err := strconv.ParseInt(strings.TrimSpace(out), 10, 64) + glog.Infof("guest clock: %s", out) + ns := strings.Split(strings.TrimSpace(out), ".") + secs, err := strconv.ParseInt(strings.TrimSpace(ns[0]), 10, 64) if err != nil { - return errors.Wrap(err, "atoi") - } - diff := local - remote - glog.Infof("local clock: %d - remote clock: %d (diff: %d)", local, remote, diff) - - // Only interfere if desync is large enough to cause certificate validation issues - switch { - case diff < -1: - glog.Warningf("VM clock is %d seconds ahead of the host.", diff*-1) - case diff > 1: - glog.Warningf("VM clock is %d seconds behind the host.", diff) - case diff > 4: - glog.Errorf("VM clock is %d seconds behind the host: forcing sync.", diff) - // NOTE: This kind of barbarian one-shot time sync may cause applications to crash. - // However, proper approaches require access to an NTP service. - _, err := h.RunSSHCommand(fmt.Sprintf("sudo date -s @%d", time.Now().Unix())) - if err != nil { - return errors.Wrap(err, "set clock") - } + return 0, errors.Wrap(err, "atoi") } - return nil + nsecs, err := strconv.ParseInt(strings.TrimSpace(ns[1]), 10, 64) + if err != nil { + return 0, errors.Wrap(err, "atoi") + } + // In a synced state, "remote" will be ahead of "local" by a few ms + remote := time.Unix(secs, nsecs) + return remote.Sub(local), nil +} + +// adjustSystemClock adjusts the guest system clock to be nearer to the host system clock +func adjustGuestClock(h *host.Host, d time.Duration) error { + glog.Infof("Adjusting guest system clock by %s", d) + _, err := h.RunSSHCommand(fmt.Sprintf("sudo date -s @%d", time.Now().Add(d).Unix())) + return err } // trySSHPowerOff runs the poweroff command on the guest VM to speed up deletion From 2bf84b1593b229c712df15efad88103188eef3ae Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Tue, 28 May 2019 19:10:09 -0700 Subject: [PATCH 4/8] Make maxClockDesyncSeconds a float for clarity & ease of calling math.Abs --- pkg/minikube/cluster/cluster.go | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/pkg/minikube/cluster/cluster.go b/pkg/minikube/cluster/cluster.go index 806c37a12144..58da0116f6c8 100644 --- a/pkg/minikube/cluster/cluster.go +++ b/pkg/minikube/cluster/cluster.go @@ -20,6 +20,7 @@ import ( "encoding/json" "flag" "fmt" + "math" "net" "os/exec" "regexp" @@ -49,8 +50,7 @@ import ( var ( // The maximum the guest VM clock is allowed to be ahead and behind. This value is intentionally // large to allow for inaccurate methodology, but still small enough so that certificates are likely valid. - maximumClockAhead = time.Duration(-2 * time.Millisecond) - maximumClockBehind = time.Duration(2 * time.Millisecond) + maxClockDesyncSeconds = 0.001 ) //This init function is used to set the logtostderr variable to false so that INFO level log info does not clutter the CLI @@ -158,8 +158,8 @@ func configureHost(h *host.Host, e *engine.Options) error { glog.Warningf("Unable to measure system clock delta: %v", err) return nil } - if d > maximumClockBehind || d < maximumClockAhead { - glog.Infof("system clock delta is within tolerence: %s", d) + if math.Abs(d.Seconds()) < maxClockDesyncSeconds { + glog.Infof("guest clock delta is within tolerance: %s", d) return nil } if err := adjustGuestClock(h, d); err != nil { @@ -188,7 +188,7 @@ func guestClockDelta(h *host.Host) (time.Duration, error) { if err != nil { return 0, errors.Wrap(err, "atoi") } - // In a synced state, "remote" will be ahead of "local" by a few ms + // NOTE: In a synced state, remote is a few hundred ms ahead of local remote := time.Unix(secs, nsecs) return remote.Sub(local), nil } From 5dd0890fc7f842c76b9e03d241020f931b46eabb Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Tue, 28 May 2019 19:12:00 -0700 Subject: [PATCH 5/8] Set a realistic desync value --- pkg/minikube/cluster/cluster.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/minikube/cluster/cluster.go b/pkg/minikube/cluster/cluster.go index 58da0116f6c8..c024e53437c5 100644 --- a/pkg/minikube/cluster/cluster.go +++ b/pkg/minikube/cluster/cluster.go @@ -50,7 +50,7 @@ import ( var ( // The maximum the guest VM clock is allowed to be ahead and behind. This value is intentionally // large to allow for inaccurate methodology, but still small enough so that certificates are likely valid. - maxClockDesyncSeconds = 0.001 + maxClockDesyncSeconds = 2.1 ) //This init function is used to set the logtostderr variable to false so that INFO level log info does not clutter the CLI From 035331b96b6f6b790818616ac3665b7797af7a57 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Tue, 28 May 2019 20:24:01 -0700 Subject: [PATCH 6/8] Add testing --- pkg/minikube/cluster/cluster.go | 12 ++++++++---- pkg/minikube/cluster/cluster_test.go | 19 +++++++++++++++++++ 2 files changed, 27 insertions(+), 4 deletions(-) diff --git a/pkg/minikube/cluster/cluster.go b/pkg/minikube/cluster/cluster.go index c024e53437c5..7eb83140bf7f 100644 --- a/pkg/minikube/cluster/cluster.go +++ b/pkg/minikube/cluster/cluster.go @@ -47,6 +47,11 @@ import ( pkgutil "k8s.io/minikube/pkg/util" ) +// hostRunner is a minimal host.Host based interface for running commands +type hostRunner interface { + RunSSHCommand(string) (string, error) +} + var ( // The maximum the guest VM clock is allowed to be ahead and behind. This value is intentionally // large to allow for inaccurate methodology, but still small enough so that certificates are likely valid. @@ -153,7 +158,7 @@ func configureHost(h *host.Host, e *engine.Options) error { if err := h.ConfigureAuth(); err != nil { return &util.RetriableError{Err: errors.Wrap(err, "Error configuring auth on host")} } - d, err := guestClockDelta(h) + d, err := guestClockDelta(h, time.Now()) if err != nil { glog.Warningf("Unable to measure system clock delta: %v", err) return nil @@ -172,8 +177,7 @@ func configureHost(h *host.Host, e *engine.Options) error { // systemClockDelta returns the approximate difference between the host and guest system clock // NOTE: This does not currently take into account ssh latency. -func guestClockDelta(h *host.Host) (time.Duration, error) { - local := time.Now() +func guestClockDelta(h hostRunner, local time.Time) (time.Duration, error) { out, err := h.RunSSHCommand("date +%s.%N") if err != nil { return 0, errors.Wrap(err, "get clock") @@ -194,7 +198,7 @@ func guestClockDelta(h *host.Host) (time.Duration, error) { } // adjustSystemClock adjusts the guest system clock to be nearer to the host system clock -func adjustGuestClock(h *host.Host, d time.Duration) error { +func adjustGuestClock(h hostRunner, d time.Duration) error { glog.Infof("Adjusting guest system clock by %s", d) _, err := h.RunSSHCommand(fmt.Sprintf("sudo date -s @%d", time.Now().Add(d).Unix())) return err diff --git a/pkg/minikube/cluster/cluster_test.go b/pkg/minikube/cluster/cluster_test.go index 68788f8ebcd1..10091a939ac4 100644 --- a/pkg/minikube/cluster/cluster_test.go +++ b/pkg/minikube/cluster/cluster_test.go @@ -17,8 +17,10 @@ limitations under the License. package cluster import ( + "fmt" "os" "testing" + "time" "github.com/docker/machine/libmachine/drivers" "github.com/docker/machine/libmachine/host" @@ -382,3 +384,20 @@ func TestCreateSSHShell(t *testing.T) { t.Fatalf("Expected ssh session to be run") } } + +func TestGuestClockDelta(t *testing.T) { + local := time.Now() + h := tests.NewMockHost() + // Truncate remote clock so that it is between 0 and 1 second behind + h.CommandOutput["date +%s.%N"] = fmt.Sprintf("%d.0000", local.Unix()) + got, err := guestClockDelta(h, local) + if err != nil { + t.Fatalf("guestClock: %v", err) + } + if got > time.Duration(time.Second*0) { + t.Errorf("unexpected positive delta (remote should be behind): %s", got) + } + if got < time.Duration(time.Second*-1) { + t.Errorf("unexpectedly negative delta (remote too far behind): %s", got) + } +} From 27dcd40983b83d6dbf9daf005caee8d76828d44b Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Tue, 28 May 2019 20:57:26 -0700 Subject: [PATCH 7/8] Pull logic out to ensureSyncedGuestClock --- pkg/minikube/cluster/cluster.go | 40 ++++++++++++++++++++------------- 1 file changed, 24 insertions(+), 16 deletions(-) diff --git a/pkg/minikube/cluster/cluster.go b/pkg/minikube/cluster/cluster.go index 7eb83140bf7f..fb0629bb3012 100644 --- a/pkg/minikube/cluster/cluster.go +++ b/pkg/minikube/cluster/cluster.go @@ -158,23 +158,29 @@ func configureHost(h *host.Host, e *engine.Options) error { if err := h.ConfigureAuth(); err != nil { return &util.RetriableError{Err: errors.Wrap(err, "Error configuring auth on host")} } - d, err := guestClockDelta(h, time.Now()) - if err != nil { - glog.Warningf("Unable to measure system clock delta: %v", err) - return nil - } - if math.Abs(d.Seconds()) < maxClockDesyncSeconds { - glog.Infof("guest clock delta is within tolerance: %s", d) - return nil - } - if err := adjustGuestClock(h, d); err != nil { - return errors.Wrap(err, "adjusting system clock") - } + return ensureSyncedGuestClock(h) } return nil } +// ensureGuestClockSync ensures that the guest system clock is relatively in-sync +func ensureSyncedGuestClock(h hostRunner) error { + d, err := guestClockDelta(h, time.Now()) + if err != nil { + glog.Warningf("Unable to measure system clock delta: %v", err) + return nil + } + if math.Abs(d.Seconds()) < maxClockDesyncSeconds { + glog.Infof("guest clock delta is within tolerance: %s", d) + return nil + } + if err := adjustGuestClock(h, time.Now()); err != nil { + return errors.Wrap(err, "adjusting system clock") + } + return nil +} + // systemClockDelta returns the approximate difference between the host and guest system clock // NOTE: This does not currently take into account ssh latency. func guestClockDelta(h hostRunner, local time.Time) (time.Duration, error) { @@ -194,13 +200,15 @@ func guestClockDelta(h hostRunner, local time.Time) (time.Duration, error) { } // NOTE: In a synced state, remote is a few hundred ms ahead of local remote := time.Unix(secs, nsecs) - return remote.Sub(local), nil + d := remote.Sub(local) + glog.Infof("Guest: %s Remote: %s (delta=%s)", remote, local, d) + return d, nil } // adjustSystemClock adjusts the guest system clock to be nearer to the host system clock -func adjustGuestClock(h hostRunner, d time.Duration) error { - glog.Infof("Adjusting guest system clock by %s", d) - _, err := h.RunSSHCommand(fmt.Sprintf("sudo date -s @%d", time.Now().Add(d).Unix())) +func adjustGuestClock(h hostRunner, t time.Time) error { + out, err := h.RunSSHCommand(fmt.Sprintf("sudo date -s @%d", t.Unix())) + glog.Infof("clock set: %s (err=%v)", out, err) return err } From 0afdce2d6d8efc4adfa4c6e8440e0efe96dab51d Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Tue, 28 May 2019 20:59:53 -0700 Subject: [PATCH 8/8] Address lint issue --- pkg/minikube/cluster/cluster_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pkg/minikube/cluster/cluster_test.go b/pkg/minikube/cluster/cluster_test.go index 10091a939ac4..db4b88441d88 100644 --- a/pkg/minikube/cluster/cluster_test.go +++ b/pkg/minikube/cluster/cluster_test.go @@ -394,10 +394,10 @@ func TestGuestClockDelta(t *testing.T) { if err != nil { t.Fatalf("guestClock: %v", err) } - if got > time.Duration(time.Second*0) { + if got > (0 * time.Second) { t.Errorf("unexpected positive delta (remote should be behind): %s", got) } - if got < time.Duration(time.Second*-1) { + if got < (-1 * time.Second) { t.Errorf("unexpectedly negative delta (remote too far behind): %s", got) } }