Removes logs that cause flooding and fixes test extension issue

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)
 }

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) {

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

internal/immediateruncommand/immediateruncommand.go

@@ -44,23 +44,31 @@ 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 {
 			ctx.Log("error", errors.Wrapf(err, "could not process new immediate run command states because of an unexpected 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.Sprintf("Resuming wait for immediate goal states. New etag: %v. Old etag: %v", newProcessedETag, lastProcessedETag))
+			}
+
 			lastProcessedETag = newProcessedETag
 			time.Sleep(time.Second * time.Duration(constants.PolingIntervalInSeconds))
 		}
 	}
 }
 
 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

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
 	}