diff --git a/pkg/pillar/cmd/downloader/download.go b/pkg/pillar/cmd/downloader/download.go index fa778677bcf..9d184281923 100644 --- a/pkg/pillar/cmd/downloader/download.go +++ b/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() diff --git a/pkg/pillar/cmd/downloader/downloader.go b/pkg/pillar/cmd/downloader/downloader.go index 635505e9fb9..357c1b83f30 100644 --- a/pkg/pillar/cmd/downloader/downloader.go +++ b/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,8 +415,7 @@ 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 @@ -418,10 +423,9 @@ func doDownload(ctx *downloaderContext, config types.DownloaderConfig, status *t 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 diff --git a/pkg/pillar/cmd/downloader/resolveconfig.go b/pkg/pillar/cmd/downloader/resolveconfig.go index 3cbae6b0782..d5a1b722b44 100644 --- a/pkg/pillar/cmd/downloader/resolveconfig.go +++ b/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) } diff --git a/pkg/pillar/cmd/downloader/syncop.go b/pkg/pillar/cmd/downloader/syncop.go index 6efe60aa428..7aeacfbcb7a 100644 --- a/pkg/pillar/cmd/downloader/syncop.go +++ b/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 diff --git a/pkg/pillar/cmd/zedagent/handlemetrics.go b/pkg/pillar/cmd/zedagent/handlemetrics.go index a305f5f169d..9a6590bf84b 100644 --- a/pkg/pillar/cmd/zedagent/handlemetrics.go +++ b/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)) } } diff --git a/pkg/pillar/cmd/zedagent/reportinfo.go b/pkg/pillar/cmd/zedagent/reportinfo.go index 103999ecf5a..d7220ceb29c 100644 --- a/pkg/pillar/cmd/zedagent/reportinfo.go +++ b/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)) } } diff --git a/pkg/pillar/hypervisor/qmp.go b/pkg/pillar/hypervisor/qmp.go index b1cd8af0af4..5b50abb2b32 100644 --- a/pkg/pillar/hypervisor/qmp.go +++ b/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 diff --git a/pkg/pillar/types/downloadertypes.go b/pkg/pillar/types/downloadertypes.go index 5c9b5119cf1..ed4ecf5049a 100644 --- a/pkg/pillar/types/downloadertypes.go +++ b/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() } diff --git a/pkg/pillar/types/resolvertypes.go b/pkg/pillar/types/resolvertypes.go index 529727ba5f0..bb316854207 100644 --- a/pkg/pillar/types/resolvertypes.go +++ b/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 diff --git a/pkg/pillar/types/zedroutertypes.go b/pkg/pillar/types/zedroutertypes.go index 5f09a27a2f1..0aec3d2db1b 100644 --- a/pkg/pillar/types/zedroutertypes.go +++ b/pkg/pillar/types/zedroutertypes.go @@ -1206,34 +1206,42 @@ func rotate(arr []string, amount int) []string { // rotation causes rotation/round-robin within each cost func GetMgmtPortsSortedCost(globalStatus DeviceNetworkStatus, rotation int) []string { return getMgmtPortsSortedCostImpl(globalStatus, rotation, - PortCostMax) + PortCostMax, false) +} + +// GetMgmtPortsSortedCostWithoutFailed returns all management ports sorted by +// port cost ignoring ports with failures. +// rotation causes rotation/round-robin within each cost +func GetMgmtPortsSortedCostWithoutFailed(globalStatus DeviceNetworkStatus, rotation int) []string { + return getMgmtPortsSortedCostImpl(globalStatus, rotation, + PortCostMax, true) } // getMgmtPortsSortedCostImpl returns all management ports sorted by port cost // up to and including the maxCost -func getMgmtPortsSortedCostImpl(globalStatus DeviceNetworkStatus, rotation int, maxCost uint8) []string { +func getMgmtPortsSortedCostImpl(globalStatus DeviceNetworkStatus, rotation int, maxCost uint8, dropFailed bool) []string { ifnameList := []string{} costList := getPortCostListImpl(globalStatus, maxCost) for _, cost := range costList { ifnameList = append(ifnameList, - getMgmtPortsImpl(globalStatus, rotation, true, cost)...) + getMgmtPortsImpl(globalStatus, rotation, true, cost, dropFailed)...) } return ifnameList } // GetMgmtPortsAny returns all management ports func GetMgmtPortsAny(globalStatus DeviceNetworkStatus, rotation int) []string { - return getMgmtPortsImpl(globalStatus, rotation, false, 0) + return getMgmtPortsImpl(globalStatus, rotation, false, 0, false) } // GetMgmtPortsByCost returns all management ports with a given port cost func GetMgmtPortsByCost(globalStatus DeviceNetworkStatus, cost uint8) []string { - return getMgmtPortsImpl(globalStatus, 0, true, cost) + return getMgmtPortsImpl(globalStatus, 0, true, cost, false) } // Returns the IfNames. func getMgmtPortsImpl(globalStatus DeviceNetworkStatus, rotation int, - matchCost bool, cost uint8) []string { + matchCost bool, cost uint8, dropFailed bool) []string { var ifnameList []string for _, us := range globalStatus.Ports { @@ -1244,6 +1252,9 @@ func getMgmtPortsImpl(globalStatus DeviceNetworkStatus, rotation int, !us.IsMgmt { continue } + if dropFailed && us.HasError() { + continue + } ifnameList = append(ifnameList, us.IfName) } return rotate(ifnameList, rotation) @@ -1451,7 +1462,7 @@ func getLocalAddrListImpl(globalStatus DeviceNetworkStatus, if phylabelOrIfname == "" { // Get interfaces in cost order ifnameList = getMgmtPortsSortedCostImpl(globalStatus, 0, - maxCost) + maxCost, false) } else { ifname := PhylabelToIfName(&globalStatus, phylabelOrIfname) us := GetPort(globalStatus, ifname) diff --git a/pkg/pillar/zedcloud/send.go b/pkg/pillar/zedcloud/send.go index 51d4adef6fb..2a02250a507 100644 --- a/pkg/pillar/zedcloud/send.go +++ b/pkg/pillar/zedcloud/send.go @@ -87,7 +87,13 @@ func SendOnAllIntf(ctx *ZedCloudContext, url string, reqlen int64, b *bytes.Buff var errorList []error remoteTemporaryFailure := types.SenderStatusNone - intfs := types.GetMgmtPortsSortedCost(*ctx.DeviceNetworkStatus, iteration) + intfs := types.GetMgmtPortsSortedCostWithoutFailed(*ctx.DeviceNetworkStatus, iteration) + if len(intfs) == 0 { + // This can happen during onboarding etc and the failed status + // might be updated infrequently by nim + log.Warnf("All management ports are marked failed; trying all") + intfs = types.GetMgmtPortsSortedCost(*ctx.DeviceNetworkStatus, iteration) + } if len(intfs) == 0 { err := fmt.Errorf("Can not connect to %s: No management interfaces", url)