Time synchronization inside LCOW UVM (microsoft#1119)

Start time synchronization service in opengcs

Changes to the opengcs to start the chronyd service after UVM boots.

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* 

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* TimeSync service inside LCOW UVM.

Add test to verify both chronyd running & disabled cases. Minor fixes in chronyd startup
code.

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* Run Chronyd with restart monitor

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* Force chronyd to step update time if difference is big

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* Fixes after rebase

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* go mod vendor & tidy

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* Use backoff package instead of manually calculating backoffs

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* Rename gcs cmdline params, use io.ReadFull instead of io.Read

Minor other fixes.

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* go mod vendor

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* Ignore err if file doesn't exist

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* Use ioutil.ReadFile to read clock_name file

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* minor fix

Signed-off-by: Amit Barve <ambarve@microsoft.com>

* Remove incorrect usage of backoff.MaxElapsedTime

Signed-off-by: Amit Barve <ambarve@microsoft.com>

cmd/gcs/main.go

@@ -8,6 +8,8 @@ import (
 	"io"
 	"io/ioutil"
 	"os"
+	"os/exec"
+	"path/filepath"
 	"syscall"
 	"time"
 
@@ -17,9 +19,11 @@ import (
 	"github.com/Microsoft/hcsshim/internal/guest/runtime/runc"
 	"github.com/Microsoft/hcsshim/internal/guest/transport"
 	"github.com/Microsoft/hcsshim/internal/oc"
+	"github.com/cenkalti/backoff/v4"
 	"github.com/containerd/cgroups"
 	cgroupstats "github.com/containerd/cgroups/stats/v1"
 	oci "github.com/opencontainers/runtime-spec/specs-go"
+	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 	"go.opencensus.io/trace"
 )
@@ -81,6 +85,84 @@ func readMemoryEvents(startTime time.Time, efdFile *os.File, cgName string, thre
 	}
 }
 
+// runWithRestartMonitor starts a command with given args and waits for it to exit. If the
+// command exit code is non-zero the command is restarted with with some back off delay.
+// Any stdout or stderr of the command will be split into lines and written as a log with
+// logrus standard logger.  This function must be called in a separate goroutine.
+func runWithRestartMonitor(arg0 string, args ...string) {
+	backoffSettings := backoff.NewExponentialBackOff()
+	// After we hit 10 min retry interval keep retrying after every 10 mins instead of
+	// continuing to increase retry interval.
+	backoffSettings.MaxInterval = time.Minute * 10
+	for {
+		command := exec.Command(arg0, args...)
+		if err := command.Run(); err != nil {
+			logrus.WithFields(logrus.Fields{
+				"error":   err,
+				"command": command.Args,
+			}).Warn("restart monitor: run command returns error")
+		}
+		backOffTime := backoffSettings.NextBackOff()
+		// since backoffSettings.MaxElapsedTime is set to 0 we will never receive backoff.Stop.
+		time.Sleep(backOffTime)
+	}
+
+}
+
+// startTimeSyncService starts the `chronyd` deamon to keep the UVM time synchronized.  We
+// use a PTP device provided by the hypervisor as a source of correct time (instead of
+// using a network server). We need to create a configuration file that configures chronyd
+// to use the PTP device.  The system can have multiple PTP devices so we identify the
+// correct PTP device by verifying that the `clock_name` of that device is `hyperv`.
+func startTimeSyncService() error {
+	ptpClassDir, err := os.Open("/sys/class/ptp")
+	if err != nil {
+		return errors.Wrap(err, "failed to open PTP class directory")
+	}
+
+	ptpDirList, err := ptpClassDir.Readdirnames(-1)
+	if err != nil {
+		return errors.Wrap(err, "failed to list PTP class directory")
+	}
+
+	var ptpDirPath string
+	found := false
+	// The file ends with a new line
+	expectedClockName := "hyperv\n"
+	for _, ptpDirPath = range ptpDirList {
+		clockNameFilePath := filepath.Join(ptpClassDir.Name(), ptpDirPath, "clock_name")
+		buf, err := ioutil.ReadFile(clockNameFilePath)
+		if err != nil && !os.IsNotExist(err) {
+			return errors.Wrapf(err, "failed to read clock name file at %s", clockNameFilePath)
+		}
+
+		if string(buf) == expectedClockName {
+			found = true
+			break
+		}
+	}
+
+	if !found {
+		return errors.Errorf("no PTP device found with name \"%s\"", expectedClockName)
+	}
+
+	// create chronyd config file
+	ptpDevPath := filepath.Join("/dev", filepath.Base(ptpDirPath))
+	// chronyd config file take from: https://docs.microsoft.com/en-us/azure/virtual-machines/linux/time-sync
+	chronydConfigString := fmt.Sprintf("refclock PHC %s poll 3 dpoll -2 offset 0 stratum 2\nmakestep 0.1 -1\n", ptpDevPath)
+	chronydConfPath := "/tmp/chronyd.conf"
+	err = ioutil.WriteFile(chronydConfPath, []byte(chronydConfigString), 0644)
+	if err != nil {
+		return errors.Wrapf(err, "failed to create chronyd conf file %s", chronydConfPath)
+	}
+
+	// start chronyd. Do NOT start chronyd as daemon because creating a daemon
+	// involves double forking the restart monitor will attempt to restart chornyd
+	// after the first fork child exits.
+	go runWithRestartMonitor("chronyd", "-n", "-f", chronydConfPath)
+	return nil
+}
+
 func main() {
 	startTime := time.Now()
 	logLevel := flag.String("loglevel", "debug", "Logging Level: debug, info, warning, error, fatal, panic.")
@@ -92,6 +174,7 @@ func main() {
 	v4 := flag.Bool("v4", false, "enable the v4 protocol support and v2 schema")
 	rootMemReserveBytes := flag.Uint64("root-mem-reserve-bytes", 75*1024*1024, "the amount of memory reserved for the orchestration, the rest will be assigned to containers")
 	gcsMemLimitBytes := flag.Uint64("gcs-mem-limit-bytes", 50*1024*1024, "the maximum amount of memory the gcs can use")
+	disableTimeSync := flag.Bool("disable-time-sync", false, "If true do not run chronyd time synchronization service inside the UVM")
 
 	flag.Usage = func() {
 		fmt.Fprintf(os.Stderr, "\nUsage of %s:\n", os.Args[0])
@@ -248,6 +331,13 @@ func main() {
 	oomFile := os.NewFile(oom, "cefd")
 	defer oomFile.Close()
 
+	// time synchronization service
+	if !(*disableTimeSync) {
+		if err = startTimeSyncService(); err != nil {
+			logrus.WithError(err).Fatal("failed to start time synchronization service")
+		}
+	}
+
 	go readMemoryEvents(startTime, gefdFile, "/gcs", int64(*gcsMemLimitBytes), gcsControl)
 	go readMemoryEvents(startTime, oomFile, "/containers", containersLimit, containersControl)
 	err = b.ListenAndServe(bridgeIn, bridgeOut)
@@ -256,4 +346,5 @@ func main() {
 			logrus.ErrorKey: err,
 		}).Fatal("failed to serve gcs service")
 	}
+
 }

internal/oci/uvm.go

@@ -358,6 +358,7 @@ func SpecToUVMCreateOpts(ctx context.Context, s *specs.Spec, id, owner string) (
 		lopts.SecurityPolicy = parseAnnotationsString(s.Annotations, annotations.SecurityPolicy, lopts.SecurityPolicy)
 		lopts.KernelBootOptions = parseAnnotationsString(s.Annotations, annotations.KernelBootOptions, lopts.KernelBootOptions)
 		lopts.ProcessDumpLocation = parseAnnotationsString(s.Annotations, annotations.ContainerProcessDumpLocation, lopts.ProcessDumpLocation)
+		lopts.DisableTimeSyncService = parseAnnotationsBool(ctx, s.Annotations, annotations.DisableLCOWTimeSyncService, lopts.DisableTimeSyncService)
 		handleAnnotationPreferredRootFSType(ctx, s.Annotations, lopts)
 		handleAnnotationKernelDirectBoot(ctx, s.Annotations, lopts)
 

internal/uvm/create_lcow.go

@@ -103,6 +103,7 @@ type OptionsLCOW struct {
 	SecurityPolicyEnabled   bool                // Set when there is a security policy to apply on actual SNP hardware, use this rathen than checking the string length
 	UseGuestStateFile       bool                // Use a vmgs file that contains a kernel and initrd, required for SNP
 	GuestStateFile          string              // The vmgs file to load
+	DisableTimeSyncService  bool                // Disables the time synchronization service
 }
 
 // defaultLCOWOSBootFilesPath returns the default path used to locate the LCOW
@@ -152,6 +153,7 @@ func NewDefaultOptionsLCOW(id, owner string) *OptionsLCOW {
 		SecurityPolicyEnabled:   false,
 		SecurityPolicy:          "",
 		GuestStateFile:          "",
+		DisableTimeSyncService:  false,
 	}
 
 	if _, err := os.Stat(filepath.Join(opts.BootFilesPath, VhdFile)); err == nil {
@@ -651,6 +653,10 @@ func makeLCOWDoc(ctx context.Context, opts *OptionsLCOW, uvm *UtilityVM) (_ *hcs
 		initArgs += fmt.Sprintf(" -e %d", linuxLogVsockPort)
 	}
 
+	if opts.DisableTimeSyncService {
+		opts.ExecCommandLine = fmt.Sprintf("%s --disable-time-sync", opts.ExecCommandLine)
+	}
+
 	initArgs += " " + opts.ExecCommandLine
 
 	if opts.ProcessDumpLocation != "" {

pkg/annotations/annotations.go

@@ -257,4 +257,8 @@ const (
 
 	// GuestStateFile specifies the path of the vmgs file to use if required. Only applies in SNP mode.
 	GuestStateFile = "io.microsoft.virtualmachine.lcow.gueststatefile"
+
+	// AnnotationDisableLCOWTimeSyncService is used to disable the chronyd time
+	// synchronization service inside the LCOW UVM.
+	DisableLCOWTimeSyncService = "io.microsoft.virtualmachine.lcow.timesync.disable"
 )

test/cri-containerd/runpodsandbox_test.go

@@ -4,9 +4,10 @@ package cri_containerd
 
 import (
 	"bufio"
+	"bytes"
 	"context"
 	"fmt"
-	"github.com/Microsoft/hcsshim/pkg/annotations"
+	"io"
 	"io/ioutil"
 	"os"
 	"path/filepath"
@@ -19,8 +20,11 @@ import (
 	"github.com/Microsoft/hcsshim/internal/hcs"
 	"github.com/Microsoft/hcsshim/internal/lcow"
 	"github.com/Microsoft/hcsshim/internal/processorinfo"
+	"github.com/Microsoft/hcsshim/internal/shimdiag"
 	"github.com/Microsoft/hcsshim/osversion"
+	"github.com/Microsoft/hcsshim/pkg/annotations"
 	testutilities "github.com/Microsoft/hcsshim/test/functional/utilities"
+	"github.com/containerd/containerd/log"
 	runtime "k8s.io/cri-api/pkg/apis/runtime/v1alpha2"
 )
 
@@ -1050,6 +1054,14 @@ func Test_RunPodSandbox_CPUGroup(t *testing.T) {
 }
 
 func createExt4VHD(ctx context.Context, t *testing.T, path string) {
+	// UVM related functions called below produce a lot debug logs. Set the logger
+	// output to Discard if verbose flag is not set. This way we can still capture
+	// these logs in a wpr session.
+	if !testing.Verbose() {
+		origLogOut := log.L.Logger.Out
+		log.L.Logger.SetOutput(io.Discard)
+		defer log.L.Logger.SetOutput(origLogOut)
+	}
 	uvm := testutilities.CreateLCOWUVM(ctx, t, t.Name()+"-createExt4VHD")
 	defer uvm.Close()
 
@@ -1708,3 +1720,94 @@ func Test_RunPodSandbox_KernelOptions_LCOW(t *testing.T) {
 		t.Fatalf("Expected number of hugepages to be 10. Got output instead: %d", numOfHugePages)
 	}
 }
+
+func Test_RunPodSandbox_TimeSyncService(t *testing.T) {
+	requireFeatures(t, featureLCOW)
+
+	client := newTestRuntimeClient(t)
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	pullRequiredLCOWImages(t, []string{imageLcowK8sPause})
+
+	request := getRunPodSandboxRequest(
+		t,
+		lcowRuntimeHandler)
+
+	podID := runPodSandbox(t, client, ctx, request)
+	defer removePodSandbox(t, client, ctx, podID)
+	defer stopPodSandbox(t, client, ctx, podID)
+
+	shimName := fmt.Sprintf("k8s.io-%s", podID)
+
+	shim, err := shimdiag.GetShim(shimName)
+	if err != nil {
+		t.Fatalf("failed to find shim %s: %s", shimName, err)
+	}
+
+	psCmd := []string{"ps"}
+	shimClient := shimdiag.NewShimDiagClient(shim)
+	outBuf := bytes.Buffer{}
+	outw := bufio.NewWriter(&outBuf)
+	errBuf := bytes.Buffer{}
+	errw := bufio.NewWriter(&errBuf)
+	exitCode, err := execInHost(ctx, shimClient, psCmd, nil, outw, errw)
+	if err != nil {
+		t.Fatalf("failed to exec `%s` in the uvm with %s", psCmd[0], err)
+	}
+	if exitCode != 0 {
+		t.Fatalf("exec `%s` in the uvm failed with exit code: %d, std error: %s", psCmd[0], exitCode, errBuf.String())
+	}
+	if !strings.Contains(outBuf.String(), "chronyd") {
+		t.Logf("standard output of exec %s is: %s\n", psCmd[0], outBuf.String())
+		t.Fatalf("chronyd is not running inside the uvm")
+	}
+}
+
+func Test_RunPodSandbox_DisableTimeSyncService(t *testing.T) {
+	requireFeatures(t, featureLCOW)
+
+	client := newTestRuntimeClient(t)
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	pullRequiredLCOWImages(t, []string{imageLcowK8sPause})
+
+	request := getRunPodSandboxRequest(
+		t,
+		lcowRuntimeHandler,
+		WithSandboxAnnotations(
+			map[string]string{
+				annotations.DisableLCOWTimeSyncService: "true",
+			}),
+	)
+
+	podID := runPodSandbox(t, client, ctx, request)
+	defer removePodSandbox(t, client, ctx, podID)
+	defer stopPodSandbox(t, client, ctx, podID)
+
+	shimName := fmt.Sprintf("k8s.io-%s", podID)
+
+	shim, err := shimdiag.GetShim(shimName)
+	if err != nil {
+		t.Fatalf("failed to find shim %s: %s", shimName, err)
+	}
+
+	psCmd := []string{"ps"}
+	shimClient := shimdiag.NewShimDiagClient(shim)
+	outBuf := bytes.Buffer{}
+	outw := bufio.NewWriter(&outBuf)
+	errBuf := bytes.Buffer{}
+	errw := bufio.NewWriter(&errBuf)
+	exitCode, err := execInHost(ctx, shimClient, psCmd, nil, outw, errw)
+	if err != nil {
+		t.Fatalf("failed to exec `%s` in the uvm with %s", psCmd[0], err)
+	}
+	if exitCode != 0 {
+		t.Fatalf("exec `%s` in the uvm failed with exit code: %d, std error: %s", psCmd[0], exitCode, errBuf.String())
+	}
+	if strings.Contains(outBuf.String(), "chronyd") {
+		t.Logf("standard output of exec %s is: %s\n", psCmd[0], outBuf.String())
+		t.Fatalf("chronyd should not be running inside the uvm")
+	}
+}