downloader improvements during outages

pkg/pillar/cmd/downloader/download.go

@@ -165,6 +165,7 @@ func objectMetadata(ctx *downloaderContext, trType zedUpload.SyncTransportType,
 		return sha256, errors.New("NewRequest failed")
 	}
 
+	// XXX add timer?
 	req = req.WithCancel(context.Background())
 	defer req.Cancel()
 

pkg/pillar/cmd/downloader/downloader.go

@@ -306,9 +306,15 @@ func maybeRetryDownload(ctx *downloaderContext,
 		return
 	}
 
-	// reset Error, to start download again
+	if status.RetryCount == 0 {
+		status.OrigError = status.Error
+	}
+	// Increment count; we defer clearing error until success
+	// to avoid confusing the user.
 	status.RetryCount++
-	status.ClearError()
+	errStr := fmt.Sprintf("Retry attempt %d after %s",
+		status.RetryCount, status.OrigError)
+	status.SetErrorNow(errStr)
 	publishDownloaderStatus(ctx, status)
 
 	doDownload(ctx, *config, status)
@@ -409,19 +415,17 @@ func doDownload(ctx *downloaderContext, config types.DownloaderConfig, status *t
 	if config.RefCount == 0 {
 		errStr := fmt.Sprintf("RefCount==0; download deferred for %s\n",
 			config.Name)
-		status.RetryCount++
-		status.HandleDownloadFail(errStr)
+		status.HandleDownloadFail(errStr, 0)
 		publishDownloaderStatus(ctx, status)
 		log.Errorf("doDownload(%s): deferred with %s", config.Name, errStr)
 		return
 	}
 
 	dst, err := utils.LookupDatastoreConfig(ctx.subDatastoreConfig, config.DatastoreID)
 	if dst == nil {
-		status.RetryCount++
-		// XXX can we have a faster retry in this case?
-		// React when DatastoreConfig changes?
-		status.HandleDownloadFail(err.Error())
+		errStr := fmt.Sprintf("Will retry when datastore available: %s",
+			err.Error())
+		status.HandleDownloadFail(errStr, 0)
 		publishDownloaderStatus(ctx, status)
 		log.Errorf("doDownload(%s): deferred with %v", config.Name, err)
 		return

pkg/pillar/cmd/downloader/resolveconfig.go

@@ -77,9 +77,15 @@ func maybeRetryResolve(ctx *downloaderContext, status *types.ResolveStatus) {
 		return
 	}
 
-	// reset Error, to start download again
+	if status.RetryCount == 0 {
+		status.OrigError = status.Error
+	}
+	// Increment count; we defer clearing error until success
+	// to avoid confusing the user.
 	status.RetryCount++
-	status.ClearError()
+	errStr := fmt.Sprintf("Retry attempt %d after %s",
+		status.RetryCount, status.OrigError)
+	status.SetErrorNow(errStr)
 	publishResolveStatus(ctx, status)
 
 	resolveTagsToHash(ctx, *config)
@@ -147,8 +153,6 @@ func resolveTagsToHash(ctx *downloaderContext, rc types.ResolveConfig) {
 			Counter:     rc.Counter,
 		}
 	}
-	rs.ClearError()
-
 	sha := maybeNameHasSha(rc.Name)
 	if sha != "" {
 		rs.ImageSha256 = sha
@@ -158,7 +162,9 @@ func resolveTagsToHash(ctx *downloaderContext, rc types.ResolveConfig) {
 
 	dst, err := utils.LookupDatastoreConfig(ctx.subDatastoreConfig, rc.DatastoreID)
 	if err != nil {
-		rs.SetErrorNow(err.Error())
+		errStr := fmt.Sprintf("Will retry when datastore available: %s",
+			err.Error())
+		rs.SetErrorNow(errStr)
 		publishResolveStatus(ctx, rs)
 		return
 	}
@@ -167,7 +173,8 @@ func resolveTagsToHash(ctx *downloaderContext, rc types.ResolveConfig) {
 	// construct the datastore context
 	dsCtx, err := constructDatastoreContext(ctx, rc.Name, false, *dst)
 	if err != nil {
-		errStr := fmt.Sprintf("%s, Datastore construction failed, %s", rc.Name, err)
+		errStr := fmt.Sprintf("Will retry in %v: %s failed: %s",
+			retryTime, rc.Name, err)
 		rs.SetErrorNow(errStr)
 		publishResolveStatus(ctx, rs)
 		return
@@ -182,10 +189,12 @@ func resolveTagsToHash(ctx *downloaderContext, rc types.ResolveConfig) {
 	log.Functionf("Have %d management port addresses for cost %d",
 		addrCount, downloadMaxPortCost)
 	if addrCount == 0 {
-		err := fmt.Errorf("No IP management port addresses for resolve with cost %d",
+		err := fmt.Errorf("No IP management port addresses with cost <= %d",
 			downloadMaxPortCost)
 		log.Error(err.Error())
-		rs.SetErrorNow(err.Error())
+		errStr := fmt.Sprintf("Will retry in %v: %s",
+			retryTime, err)
+		rs.SetErrorNow(errStr)
 		publishResolveStatus(ctx, rs)
 		return
 	}
@@ -214,6 +223,8 @@ func resolveTagsToHash(ctx *downloaderContext, rc types.ResolveConfig) {
 	// and return, but we will get to it later
 	if errStr != "" {
 		log.Errorf("Error preparing to download. All errors:%s", errStr)
+		errStr := fmt.Sprintf("Will retry in %v: %s",
+			retryTime, errStr)
 		rs.SetErrorNow(errStr)
 		publishResolveStatus(ctx, rs)
 		return
@@ -239,12 +250,15 @@ func resolveTagsToHash(ctx *downloaderContext, rc types.ResolveConfig) {
 			errStr = errStr + "\n" + err.Error()
 			continue
 		}
+		rs.ClearError()
 		rs.ImageSha256 = sha256
 		publishResolveStatus(ctx, rs)
 		return
 
 	}
 	log.Errorf("All source IP addresses failed. All errors:%s", errStr)
+	errStr = fmt.Sprintf("Will retry in %v: %s",
+		retryTime, errStr)
 	rs.SetErrorNow(errStr)
 	publishResolveStatus(ctx, rs)
 }

pkg/pillar/cmd/downloader/syncop.go

@@ -43,7 +43,8 @@ func handleSyncOp(ctx *downloaderContext, key string,
 	// construct the datastore context
 	dsCtx, err := constructDatastoreContext(ctx, config.Name, config.NameIsURL, *dst)
 	if err != nil {
-		errStr := fmt.Sprintf("%s, Datastore construction failed, %s", config.Name, err)
+		errStr := fmt.Sprintf("Will retry in %v: %s failed: %s",
+			retryTime, config.Name, err)
 		handleSyncOpResponse(ctx, config, status, locFilename, key, errStr)
 		return
 	}
@@ -74,7 +75,7 @@ func handleSyncOp(ctx *downloaderContext, key string,
 	addrCount := types.CountLocalAddrNoLinkLocalWithCost(ctx.deviceNetworkStatus,
 		downloadMaxPortCost)
 	if addrCount == 0 {
-		err := fmt.Errorf("No IP management port addresses for download with cost %d",
+		err := fmt.Errorf("No IP management port addresses with cost <= %d",
 			downloadMaxPortCost)
 		log.Error(err.Error())
 		handleSyncOpResponse(ctx, config, status, locFilename,
@@ -236,8 +237,7 @@ func handleSyncOpResponse(ctx *downloaderContext, config types.DownloaderConfig,
 	if errStr != "" {
 		// Delete file, and update the storage
 		doDelete(ctx, key, locFilename, status)
-		status.RetryCount++
-		status.HandleDownloadFail(errStr)
+		status.HandleDownloadFail(errStr, retryTime)
 		publishDownloaderStatus(ctx, status)
 		log.Errorf("handleSyncOpResponse(%s): failed with %s",
 			status.Name, errStr)
@@ -250,8 +250,7 @@ func handleSyncOpResponse(ctx *downloaderContext, config types.DownloaderConfig,
 		// error, so delete the file
 		doDelete(ctx, key, locFilename, status)
 		errStr := fmt.Sprintf("%v", err)
-		status.RetryCount++
-		status.HandleDownloadFail(errStr)
+		status.HandleDownloadFail(errStr, retryTime)
 		publishDownloaderStatus(ctx, status)
 		log.Errorf("handleSyncOpResponse(%s): failed with %s",
 			status.Name, errStr)
@@ -263,6 +262,7 @@ func handleSyncOpResponse(ctx *downloaderContext, config types.DownloaderConfig,
 	// We do not clear any status.RetryCount, Error, etc. The caller
 	// should look at State == DOWNLOADED to determine it is done.
 
+	status.ClearError()
 	status.ModTime = time.Now()
 	status.State = types.DOWNLOADED
 	status.Progress = 100 // Just in case

pkg/pillar/cmd/zedagent/handlemetrics.go

@@ -901,10 +901,13 @@ func PublishAppInfoToZedCloud(ctx *zedagentContext, uuid string,
 	ReportAppInfo.AppID = uuid
 	ReportAppInfo.SystemApp = false
 	ReportAppInfo.State = info.ZSwState_HALTED
+	var state types.SwState
+	var objErr bool
 	if aiStatus != nil {
 		ReportAppInfo.AppName = aiStatus.DisplayName
 		ReportAppInfo.State = aiStatus.State.ZSwState()
-
+		state = aiStatus.State
+		objErr = aiStatus.HasError()
 		if !aiStatus.ErrorTime.IsZero() {
 			errInfo := encodeErrorInfo(
 				aiStatus.ErrorAndTimeWithSource.ErrorAndTime())
@@ -1015,6 +1018,7 @@ func PublishAppInfoToZedCloud(ctx *zedagentContext, uuid string,
 		log.Fatal("malloc error")
 	}
 	size := int64(proto.Size(ReportInfo))
+	start := time.Now()
 	err = SendProtobuf(statusUrl, buf, size, iteration)
 	if err != nil {
 		log.Errorf("PublishAppInfoToZedCloud failed: %s", err)
@@ -1028,6 +1032,9 @@ func PublishAppInfoToZedCloud(ctx *zedagentContext, uuid string,
 			true)
 	} else {
 		writeSentAppInfoProtoMessage(data)
+
+		log.Functionf("sent app info %s state %s err %t took %v",
+			uuid, state.String(), objErr, time.Since(start))
 	}
 }
 
@@ -1050,10 +1057,13 @@ func PublishContentInfoToZedCloud(ctx *zedagentContext, uuid string,
 
 	ReportContentInfo.Uuid = uuid
 	ReportContentInfo.State = info.ZSwState_HALTED
+	var state types.SwState
+	var objErr bool
 	if ctStatus != nil {
 		ReportContentInfo.DisplayName = ctStatus.DisplayName
 		ReportContentInfo.State = ctStatus.State.ZSwState()
-
+		state = ctStatus.State
+		objErr = ctStatus.HasError()
 		if !ctStatus.ErrorTime.IsZero() {
 			errInfo := encodeErrorInfo(
 				ctStatus.ErrorAndTimeWithSource.ErrorAndTime())
@@ -1089,6 +1099,7 @@ func PublishContentInfoToZedCloud(ctx *zedagentContext, uuid string,
 		log.Fatal("malloc error")
 	}
 	size := int64(proto.Size(ReportInfo))
+	start := time.Now()
 	err = SendProtobuf(statusURL, buf, size, iteration)
 	if err != nil {
 		log.Errorf("PublishContentInfoToZedCloud failed: %s", err)
@@ -1100,6 +1111,9 @@ func PublishContentInfoToZedCloud(ctx *zedagentContext, uuid string,
 		}
 		zedcloud.SetDeferred(zedcloudCtx, uuid, buf, size, statusURL,
 			true)
+	} else {
+		log.Functionf("sent content info %s state %s err %t took %v",
+			uuid, state.String(), objErr, time.Since(start))
 	}
 }
 
@@ -1122,10 +1136,13 @@ func PublishVolumeToZedCloud(ctx *zedagentContext, uuid string,
 
 	ReportVolumeInfo.Uuid = uuid
 	ReportVolumeInfo.State = info.ZSwState_INITIAL
+	var state types.SwState
+	var objErr bool
 	if volStatus != nil {
 		ReportVolumeInfo.DisplayName = volStatus.DisplayName
 		ReportVolumeInfo.State = volStatus.State.ZSwState()
-
+		state = volStatus.State
+		objErr = volStatus.HasError()
 		if !volStatus.ErrorTime.IsZero() {
 			errInfo := encodeErrorInfo(
 				volStatus.ErrorAndTimeWithSource.ErrorAndTime())
@@ -1168,6 +1185,7 @@ func PublishVolumeToZedCloud(ctx *zedagentContext, uuid string,
 		log.Fatal("malloc error")
 	}
 	size := int64(proto.Size(ReportInfo))
+	start := time.Now()
 	err = SendProtobuf(statusURL, buf, size, iteration)
 	if err != nil {
 		log.Errorf("PublishVolumeToZedCloud failed: %s", err)
@@ -1179,7 +1197,11 @@ func PublishVolumeToZedCloud(ctx *zedagentContext, uuid string,
 		}
 		zedcloud.SetDeferred(zedcloudCtx, uuid, buf, size, statusURL,
 			true)
+	} else {
+		log.Functionf("sent vol info %s state %s err %t took %v",
+			uuid, state.String(), objErr, time.Since(start))
 	}
+
 }
 
 // PublishBlobInfoToZedCloud is called per change, hence needs to try over all management ports
@@ -1200,8 +1222,12 @@ func PublishBlobInfoToZedCloud(ctx *zedagentContext, blobSha string, blobStatus
 	ReportBlobInfo := new(info.ZInfoBlob)
 
 	ReportBlobInfo.Sha256 = blobSha
+	var state types.SwState
+	var objErr bool
 	if blobStatus != nil {
 		ReportBlobInfo.State = blobStatus.State.ZSwState()
+		state = blobStatus.State
+		objErr = blobStatus.HasError()
 		ReportBlobInfo.ProgressPercentage = blobStatus.GetDownloadedPercentage()
 		ReportBlobInfo.Usage = &info.UsageInfo{RefCount: uint32(blobStatus.RefCount)}
 		ReportBlobInfo.Resources = &info.ContentResources{CurSizeBytes: blobStatus.Size}
@@ -1227,6 +1253,7 @@ func PublishBlobInfoToZedCloud(ctx *zedagentContext, blobSha string, blobStatus
 		log.Fatal("malloc error")
 	}
 	size := int64(proto.Size(ReportInfo))
+	start := time.Now()
 	err = SendProtobuf(statusURL, buf, size, iteration)
 	if err != nil {
 		log.Errorf("PublishBlobInfoToZedCloud failed: %s", err)
@@ -1238,6 +1265,9 @@ func PublishBlobInfoToZedCloud(ctx *zedagentContext, blobSha string, blobStatus
 		}
 		zedcloud.SetDeferred(zedcloudCtx, blobSha, buf, size, statusURL,
 			true)
+	} else {
+		log.Functionf("sent blob info %s state %s err %t took %v",
+			blobSha, state.String(), objErr, time.Since(start))
 	}
 }
 

pkg/pillar/cmd/zedagent/reportinfo.go

@@ -521,6 +521,7 @@ func PublishDeviceInfoToZedCloud(ctx *zedagentContext) {
 		log.Fatal("malloc error")
 	}
 	size := int64(proto.Size(ReportInfo))
+	start := time.Now()
 	err = SendProtobuf(statusUrl, buf, size, iteration)
 	if err != nil {
 		log.Errorf("PublishDeviceInfoToZedCloud failed: %s", err)
@@ -534,6 +535,9 @@ func PublishDeviceInfoToZedCloud(ctx *zedagentContext) {
 			statusUrl, true)
 	} else {
 		writeSentDeviceInfoProtoMessage(data)
+
+		log.Functionf("sent device info %s took %v", deviceUUID,
+			time.Since(start))
 	}
 }
 

pkg/pillar/hypervisor/qmp.go

@@ -16,7 +16,7 @@ const sockTimeout = 10 * time.Second
 
 func execRawCmd(socket, cmd string) ([]byte, error) {
 	var retry = 3
-	logrus.Infof("executing QMP command: %s", cmd)
+	logrus.Debugf("executing QMP command: %s", cmd)
 	var err error
 	var monitor *qmp.SocketMonitor
 

pkg/pillar/types/downloadertypes.go

@@ -4,6 +4,7 @@
 package types
 
 import (
+	"fmt"
 	"time"
 
 	"github.com/google/go-cmp/cmp"
@@ -113,6 +114,8 @@ type DownloaderStatus struct {
 	// ErrorAndTime provides SetErrorNow() and ClearError()
 	ErrorAndTime
 	RetryCount int
+	// We save the original error when we do a retry
+	OrigError string
 }
 
 func (status DownloaderStatus) Key() string {
@@ -134,7 +137,11 @@ func (status *DownloaderStatus) ClearPendingStatus() {
 }
 
 // HandleDownloadFail : Do Failure specific tasks
-func (status *DownloaderStatus) HandleDownloadFail(errStr string) {
+func (status *DownloaderStatus) HandleDownloadFail(errStr string, retryTime time.Duration) {
+	if retryTime != 0 {
+		errStr = fmt.Sprintf("Will retry in %v: %s",
+			retryTime, errStr)
+	}
 	status.SetErrorNow(errStr)
 	status.ClearPendingStatus()
 }

pkg/pillar/types/resolvertypes.go

@@ -76,6 +76,8 @@ type ResolveStatus struct {
 	RetryCount  int
 	// ErrorAndTime provides SetErrorNow() and ClearError()
 	ErrorAndTime
+	// We save the original error when we do a retry
+	OrigError string
 }
 
 // Key : DatastoreID, name and sequence counter are used