13647: Load one example value from old keepstore config.

[arvados.git] / lib / cloud / cloudtest / tester.go

diff --git a/lib/cloud/cloudtest/tester.go b/lib/cloud/cloudtest/tester.go
index dc5a4738aa25597e9ce640fde12bd1c4d54ce1d8..ad3f70f123d6d4147fc634ef6e121481d3d6cea6 100644 (file)
--- a/lib/cloud/cloudtest/tester.go
+++ b/lib/cloud/cloudtest/tester.go
@@ -69,17 +69,18 @@ func (t *tester) Run() bool {
                return false
        }
 
-       // Don't send the driver any filters the first time we get the
-       // instance list. This way we can log an instance count
-       // (N=...)  that includes all instances in this service
-       // account, even if they don't have the same InstanceSetID.
-       insts, err := t.getInstances(nil)
-       if err != nil {
-               t.Logger.WithError(err).Info("error getting initial list of instances")
-               return false
-       }
-
        for {
+               // Don't send the driver any filters when getting the
+               // initial instance list. This way we can log an
+               // instance count (N=...)  that includes all instances
+               // in this service account, even if they don't have
+               // the same InstanceSetID.
+               insts, err := t.getInstances(nil)
+               if err != nil {
+                       t.Logger.WithError(err).Info("error getting list of instances")
+                       return false
+               }
+
                foundExisting := false
                for _, i := range insts {
                        if i.Tags()[t.TagKeyPrefix+"InstanceSetID"] != string(t.SetID) {
@@ -92,7 +93,9 @@ func (t *tester) Run() bool {
                        foundExisting = true
                        if t.DestroyExisting {
                                lgr.Info("destroying existing instance with our InstanceSetID")
+                               t0 := time.Now()
                                err := i.Destroy()
+                               lgr := lgr.WithField("Duration", time.Since(t0))
                                if err != nil {
                                        lgr.WithError(err).Error("error destroying existing instance")
                                } else {
@@ -133,13 +136,15 @@ func (t *tester) Run() bool {
                "Tags":                 tags,
                "InitCommand":          initCommand,
        }).Info("creating instance")
+       t0 := time.Now()
        inst, err := t.is.Create(t.InstanceType, t.ImageID, tags, initCommand, t.SSHKey.PublicKey())
+       lgrC := t.Logger.WithField("Duration", time.Since(t0))
        if err != nil {
                // Create() might have failed due to a bug or network
                // error even though the creation was successful, so
                // it's safer to wait a bit for an instance to appear.
                deferredError = true
-               t.Logger.WithError(err).Error("error creating test instance")
+               lgrC.WithError(err).Error("error creating test instance")
                t.Logger.WithField("Deadline", bootDeadline).Info("waiting for instance to appear anyway, in case the Create response was incorrect")
                for err = t.refreshTestInstance(); err != nil; err = t.refreshTestInstance() {
                        if time.Now().After(bootDeadline) {
@@ -154,7 +159,7 @@ func (t *tester) Run() bool {
        } else {
                // Create() succeeded. Make sure the new instance
                // appears right away in the Instances() list.
-               t.Logger.WithField("Instance", inst.ID()).Info("created instance")
+               lgrC.WithField("Instance", inst.ID()).Info("created instance")
                t.testInstance = &worker.TagVerifier{inst, t.secret}
                t.showLoginInfo()
                err = t.refreshTestInstance()
@@ -247,11 +252,15 @@ func (t *tester) refreshTestInstance() error {
 func (t *tester) getInstances(tags cloud.InstanceTags) ([]cloud.Instance, error) {
        var ret []cloud.Instance
        t.Logger.WithField("FilterTags", tags).Info("getting instance list")
+       t0 := time.Now()
        insts, err := t.is.Instances(tags)
        if err != nil {
                return nil, err
        }
-       t.Logger.WithField("N", len(insts)).Info("got instance list")
+       t.Logger.WithFields(logrus.Fields{
+               "Duration": time.Since(t0),
+               "N":        len(insts),
+       }).Info("got instance list")
        for _, i := range insts {
                if i.Tags()[t.TagKeyPrefix+"InstanceSetID"] == string(t.SetID) {
                        ret = append(ret, i)
@@ -312,11 +321,13 @@ func (t *tester) runShellCommand(cmd string) error {
        t.Logger.WithFields(logrus.Fields{
                "Command": cmd,
        }).Info("executing remote command")
+       t0 := time.Now()
        stdout, stderr, err := t.executor.Execute(nil, cmd, nil)
        lgr := t.Logger.WithFields(logrus.Fields{
-               "Command": cmd,
-               "stdout":  string(stdout),
-               "stderr":  string(stderr),
+               "Duration": time.Since(t0),
+               "Command":  cmd,
+               "stdout":   string(stdout),
+               "stderr":   string(stderr),
        })
        if err != nil {
                lgr.WithError(err).Info("remote command failed")
@@ -332,20 +343,25 @@ func (t *tester) destroyTestInstance() bool {
                return true
        }
        for {
-               t.Logger.WithField("Instance", t.testInstance.ID()).Info("destroying instance")
+               lgr := t.Logger.WithField("Instance", t.testInstance.ID())
+               lgr.Info("destroying instance")
+               t0 := time.Now()
+
                err := t.testInstance.Destroy()
+               lgrDur := lgr.WithField("Duration", time.Since(t0))
                if err != nil {
-                       t.Logger.WithError(err).WithField("Instance", t.testInstance.ID()).Error("error destroying instance")
+                       lgrDur.WithError(err).Error("error destroying instance")
                } else {
-                       t.Logger.WithField("Instance", t.testInstance.ID()).Info("destroyed instance")
+                       lgrDur.Info("destroyed instance")
                }
+
                err = t.refreshTestInstance()
                if err == errTestInstanceNotFound {
-                       t.Logger.WithField("Instance", t.testInstance.ID()).Info("instance no longer appears in list")
+                       lgr.Info("instance no longer appears in list")
                        t.testInstance = nil
                        return true
                } else if err == nil {
-                       t.Logger.WithField("Instance", t.testInstance.ID()).Info("instance still exists after calling Destroy")
+                       lgr.Info("instance still exists after calling Destroy")
                        t.sleepSyncInterval()
                        continue
                } else {