From 785012926341c0cbbc80022aa857f03e9b8d5106 Mon Sep 17 00:00:00 2001 From: Joseph Calev Date: Mon, 4 Aug 2025 13:03:39 -0700 Subject: [PATCH 1/2] Removes logs that cause flooding and fixes an issue preventing test extension IRC goal states --- internal/goalstate/goalstatefromvmsettings.go | 9 ++++++--- .../goalstate/goalstatefromvmsettings_test.go | 20 ++++++++++++++++++- internal/hostgacommunicator/vmsettings.go | 6 ++---- .../immediateruncommand.go | 14 ++++++++++--- internal/requesthelper/request.go | 2 +- 5 files changed, 39 insertions(+), 12 deletions(-) diff --git a/internal/goalstate/goalstatefromvmsettings.go b/internal/goalstate/goalstatefromvmsettings.go index 508fa4d..8c30147 100644 --- a/internal/goalstate/goalstatefromvmsettings.go +++ b/internal/goalstate/goalstatefromvmsettings.go @@ -1,6 +1,7 @@ package goalstate import ( + "fmt" "strings" "github.com/Azure/run-command-handler-linux/internal/constants" @@ -22,7 +23,7 @@ func GetImmediateRunCommandGoalStates(ctx *log.Context, communicator hostgacommu if responseData != nil && responseData.Modified { ctx.Log("message", "a new response was received with ETag: "+responseData.ETag) if responseData.VMSettings != nil { - return filterImmediateRunCommandGoalStates(responseData.VMSettings.ImmediateExtensionGoalStates), responseData.ETag, nil + return filterImmediateRunCommandGoalStates(ctx, responseData.VMSettings.ImmediateExtensionGoalStates), responseData.ETag, nil } else { return []hostgacommunicator.ImmediateExtensionGoalState{}, responseData.ETag, nil } @@ -31,16 +32,18 @@ func GetImmediateRunCommandGoalStates(ctx *log.Context, communicator hostgacommu return []hostgacommunicator.ImmediateExtensionGoalState{}, lastProcessedETag, nil } -func filterImmediateRunCommandGoalStates(extensionGoalStates []hostgacommunicator.ImmediateExtensionGoalState) []hostgacommunicator.ImmediateExtensionGoalState { +func filterImmediateRunCommandGoalStates(ctx *log.Context, extensionGoalStates []hostgacommunicator.ImmediateExtensionGoalState) []hostgacommunicator.ImmediateExtensionGoalState { var result []hostgacommunicator.ImmediateExtensionGoalState for _, element := range extensionGoalStates { if isRunCommandGoalState(element) { result = append(result, element) + } else { + ctx.Log("message", fmt.Sprintf("Ignoring goal state for %v", element.Name)) } } return result } func isRunCommandGoalState(goalState hostgacommunicator.ImmediateExtensionGoalState) bool { - return strings.EqualFold(goalState.Name, constants.RunCommandExtensionName) + return strings.EqualFold(goalState.Name, constants.RunCommandExtensionName) || strings.EqualFold(goalState.Name, constants.RunCommandTestExtensionName) } diff --git a/internal/goalstate/goalstatefromvmsettings_test.go b/internal/goalstate/goalstatefromvmsettings_test.go index 19ccc94..bc0b956 100644 --- a/internal/goalstate/goalstatefromvmsettings_test.go +++ b/internal/goalstate/goalstatefromvmsettings_test.go @@ -33,6 +33,23 @@ func (t *TestCommunicator) GetImmediateVMSettings(ctx *log.Context, eTag string) }, } + testExtensionGoalState := hostgacommunicator.ImmediateExtensionGoalState{ + Name: "Microsoft.Azure.Extensions.Edp.RunCommandHandlerLinuxTest", + Settings: []settings.SettingsCommon{ + { + PublicSettings: map[string]interface{}{ + "string": "string", + "int": 5, + }, + ProtectedSettingsBase64: "protectedsettings", + SettingsCertThumbprint: "thumprint", + SeqNo: &seqNum, + ExtensionName: &extName, + ExtensionState: &extName, + }, + }, + } + nonImmediateGoalState := hostgacommunicator.ImmediateExtensionGoalState{ Name: "Microsoft.CPlat.Core.NonRunCommandHandler", Settings: []settings.SettingsCommon{ @@ -55,6 +72,7 @@ func (t *TestCommunicator) GetImmediateVMSettings(ctx *log.Context, eTag string) immediateGoalState, immediateGoalState, immediateGoalState, + testExtensionGoalState, nonImmediateGoalState, nonImmediateGoalState, }, @@ -85,7 +103,7 @@ func Test_GetFilteredImmediateVMSettings(t *testing.T) { communicator := new(TestCommunicator) actualIRCGoalStates, _, err := goalstate.GetImmediateRunCommandGoalStates(ctx, communicator, "") require.Nil(t, err) - require.Equal(t, 3, len(actualIRCGoalStates)) + require.Equal(t, 4, len(actualIRCGoalStates)) } func Test_GetFilteredImmediateVMSettingsFailedToRetrieve(t *testing.T) { diff --git a/internal/hostgacommunicator/vmsettings.go b/internal/hostgacommunicator/vmsettings.go index dfd5a0d..8d5af31 100644 --- a/internal/hostgacommunicator/vmsettings.go +++ b/internal/hostgacommunicator/vmsettings.go @@ -49,7 +49,6 @@ func GetVMSettingsRequestManager(ctx *log.Context) (*requesthelper.RequestManage // Returns a new requestFactory object with the VMSettings API Uri set func newVMSettingsRequestFactory(ctx *log.Context) (*requestFactory, error) { - ctx.Log("message", "trying to create new request factory") url, err := getOperationUri(ctx, vmSettingsOperation) if err != nil { return nil, errors.Wrapf(err, "failed to obtain VMSettingsURI") @@ -60,14 +59,13 @@ func newVMSettingsRequestFactory(ctx *log.Context) (*requestFactory, error) { // GetRequest returns a new request with the provided url func (u requestFactory) GetRequest(ctx *log.Context, eTag string) (*http.Request, error) { - ctx.Log("message", fmt.Sprintf("performing make request to %v", u.url)) request, err := http.NewRequest("GET", u.url, nil) if err != nil { - return nil, errors.Wrap(err, "failed to create request") + errMsg := fmt.Sprintf("failed to create request to %v", u.url) + return nil, errors.Wrap(err, errMsg) } if eTag != "" { - ctx.Log("message", "setting request headers to include ETag "+eTag) request.Header.Set(constants.IfNoneMatchHeaderName, eTag) } return request, err diff --git a/internal/immediateruncommand/immediateruncommand.go b/internal/immediateruncommand/immediateruncommand.go index b86a820..6e0d575 100644 --- a/internal/immediateruncommand/immediateruncommand.go +++ b/internal/immediateruncommand/immediateruncommand.go @@ -44,7 +44,6 @@ func StartImmediateRunCommand(ctx *log.Context) error { ctx.Log("message", fmt.Sprintf("Polling for goal state every %v seconds", constants.PolingIntervalInSeconds)) for { - ctx.Log("message", "processing new immediate run command goal states. Last processed ETag: "+lastProcessedETag) newProcessedETag, err := processImmediateRunCommandGoalStates(ctx, communicator, lastProcessedETag) if err != nil { @@ -52,6 +51,10 @@ func StartImmediateRunCommand(ctx *log.Context) error { ctx.Log("message", "sleep for 5 seconds before retrying") time.Sleep(time.Second * time.Duration(5)) } else { + if lastProcessedETag != newProcessedETag { + ctx.Log("message", fmt.Sprint("Resuming wait for immediate goal states. New etag: %v. Old etag: %v", newProcessedETag, lastProcessedETag)) + } + lastProcessedETag = newProcessedETag time.Sleep(time.Second * time.Duration(constants.PolingIntervalInSeconds)) } @@ -59,8 +62,13 @@ func StartImmediateRunCommand(ctx *log.Context) error { } func processImmediateRunCommandGoalStates(ctx *log.Context, communicator hostgacommunicator.HostGACommunicator, lastProcessedETag string) (string, error) { - maxTasksToFetch := int(math.Max(float64(maxConcurrentTasks-executingTasks.Get()), 0)) - ctx.Log("message", fmt.Sprintf("concurrent tasks: %v out of max %v", executingTasks.Get(), maxConcurrentTasks)) + executingTaskCount := executingTasks.Get() + maxTasksToFetch := int(math.Max(float64(maxConcurrentTasks-executingTaskCount), 0)) + + if executingTaskCount > 0 { + ctx.Log("message", fmt.Sprintf("concurrent tasks: %v out of max %v", executingTaskCount, maxConcurrentTasks)) + } + if maxTasksToFetch == 0 { ctx.Log("warning", "will not fetch new tasks in this iteration as we have reached maximum capacity...") return lastProcessedETag, nil diff --git a/internal/requesthelper/request.go b/internal/requesthelper/request.go index c31c1a7..b3ef9e3 100644 --- a/internal/requesthelper/request.go +++ b/internal/requesthelper/request.go @@ -43,7 +43,7 @@ func (rm *RequestManager) MakeRequest(ctx *log.Context, eTag string) (*http.Resp return resp, err } - if resp.StatusCode == http.StatusOK || resp.StatusCode == http.StatusPartialContent { + if resp.StatusCode == http.StatusOK || resp.StatusCode == http.StatusPartialContent || resp.StatusCode == http.StatusNotModified { return resp, nil } From 12c57d2b1aae9b8e9452121a6ff955a908196706 Mon Sep 17 00:00:00 2001 From: Joseph Calev Date: Mon, 4 Aug 2025 13:07:15 -0700 Subject: [PATCH 2/2] Build break fix --- internal/immediateruncommand/immediateruncommand.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/immediateruncommand/immediateruncommand.go b/internal/immediateruncommand/immediateruncommand.go index 6e0d575..5725ed9 100644 --- a/internal/immediateruncommand/immediateruncommand.go +++ b/internal/immediateruncommand/immediateruncommand.go @@ -52,7 +52,7 @@ func StartImmediateRunCommand(ctx *log.Context) error { time.Sleep(time.Second * time.Duration(5)) } else { if lastProcessedETag != newProcessedETag { - ctx.Log("message", fmt.Sprint("Resuming wait for immediate goal states. New etag: %v. Old etag: %v", newProcessedETag, lastProcessedETag)) + ctx.Log("message", fmt.Sprintf("Resuming wait for immediate goal states. New etag: %v. Old etag: %v", newProcessedETag, lastProcessedETag)) } lastProcessedETag = newProcessedETag