Write-Warning from a library module does not show as a warning

OctopusSchaff · 3 June 2021 03:36

I have a module that can write out a warning. The code looks like this:

if ($isToVersionAlreadyMade) {
    Write-Warning "Version $toVersion already exists for $packageName in feed '$toFeed'.  NO PROMOTION will happen.  The existing version will be used."
    return;
}

When this writes to the log like this:

##octopus[stdout-warning]
Version 1.9.0 already exists for runtime/shipment-tracking-service in feed ‘application’. NO PROMOTION will happen. The existing version will be used.

Here is a screen shot (just to be clear):

From the added ##octopus[stdout-warning] it looks like octopus sees it was a warning, but the Task Summary screen does not show that there was a warning, and there is no highlighting to make the warning more visible.

How can I get this warning to show up as a warning?

Kenneth_Bates · 3 June 2021 04:46

Hi @OctopusSchaff,

Thanks for getting in touch! That certainly doesn’t look like the correct expected behavior. I ran through a couple attempts to reproduce this, however the warning is treated as a warning and the task summary correctly highlights it in yellow to make it stand out. Could you let me know which version of Octopus are you currently running?

Best regards,

Kenny

OctopusSchaff · 3 June 2021 17:05

Glad to hear it is not the normal behavior.

I am running Octopus Deploy 2020.6.4688

Kenneth_Bates · 4 June 2021 01:36

Hi @OctopusSchaff ,

Thanks for following up! Strangely I still haven’t had any luck reproducing this behavior, and I can’t see any changes between these versions that might explain this difference in behavior. Would you be willing to send the full code block you have in your module so I can run through a perfectly accurate test? Feel free to mark this thread as private, or email it to support@octopus.com if it’s in any way sensitive.

I look forward to getting to the bottom of this one!

Best regards,

Kenny

OctopusSchaff · 4 June 2021 19:01

This is the full code of the module:

function PromoteContainerImage() {

	param (
		[string] $packageName = $(throw "-packageName is required.  This is the namespace and image name.  For example: library/my-container-image"),
		[string] $fromFeed = $(throw "-fromFeed is required"),
		[string] $toFeed = $(throw "-toFeed is required"),
		[string] $fromVersion = $(throw "-fromVersion is required.  This is the current tag on the container in the fromFeed."),        
		[string] $comments = "Promoted by automation",
		[string] $apiKey = $(throw "-apiKey is required"),
		[string] $progetBaseUrl = $(throw "-progetBaseUrl is required")
	)
	
	$toVersion =  $fromVersion -replace '(\d+\.\d+\.\d+).*', '$1'

	# Check to see if the pre-release version has already been promoted or if the release version has already been made.
	$isToVersionAlreadyMade = CheckIfImageExists $packageName $toFeed $toVersion $apiKey $progetBaseUrl
	$isFromVersionAlreadyPromoted = CheckIfImageExists $packageName $toFeed $fromVersion $apiKey $progetBaseUrl

	if ($isToVersionAlreadyMade) {
		Write-Warning "Version $toVersion already exists for $packageName in feed '$toFeed'.  NO PROMOTION will happen.  The existing version will be used."
		return;
	}
	if ($isFromVersionAlreadyPromoted) {
		Write-Warning "Version $fromVersion already exists for $packageName in feed '$toFeed'.  A re-promotion will be attempted."    
	}


	Write-Host "Promoting $packageName from $fromVersion to $toVersion.  Copying from the '$fromFeed' Docker Feed to the '$toFeed' Docker Feed."

	$postBody = @{
		packageName="$packageName";
		groupName="";
		version="$fromVersion";
		fromFeed="$fromFeed";
		toFeed="$toFeed";
		comments="$comments"
	} 
	# Promote the Container Image
	$promoteResponse = Invoke-WebRequest -Uri "$progetBaseUrl/api/promotions/promote" -Method POST -Body $postBody -Headers @{"X-ApiKey"="$apiKey"}
	Write-Host "Promotion call returned a status of: $($promoteResponse.BaseResponse.StatusCode)"

	Try {
		# Retag the container image by downloading the manifest and then re-uploading it as the new version
		$manifestResponse = Invoke-WebRequest -Uri "$progetBaseUrl/v2/$toFeed/$packageName/manifests/$fromVersion" -Method GET -Headers @{"X-ApiKey"="$apiKey";"accept"="application/vnd.docker.distribution.manifest.v2+json"}
		Write-Host "Get Manifest call returned a status of: $($manifestResponse.BaseResponse.StatusCode)"
		
		$retagResponse = Invoke-WebRequest -Uri "$progetBaseUrl/v2/$toFeed/$packageName/manifests/$toVersion" -Method PUT -Body $manifestResponse.ToString() -Headers @{"X-ApiKey"="$apiKey";"content-type"="application/vnd.docker.distribution.manifest.v2+json"}
		Write-Host "Add Tag call returned a status of: $($retagResponse.BaseResponse.StatusCode)"
	} Catch {        
		if($_.ErrorDetails.Message) {
			Write-Error "Failed to retag the image $($_.ErrorDetails.Message)"
		} else {
			Write-Error "Failed to retag the image $_"
		}
	}
}

function CheckIfImageExists(){

	param (
		[string] $packageName = $(throw "-packageName is required.  This is the namespace and image name.  For example: library/my-container-image"),
		[string] $feed = $(throw "-feed is required"),
		[string] $version = $(throw "-version is required."),
		[string] $apiKey = $(throw "-apiKey is required"),
		[string] $progetBaseUrl = $(throw "-progetBaseUrl is required")
	)

	Try {
		# Retag the container image by downloading the manifest and then re-uploading it as the new version
		$manifestResponse = Invoke-WebRequest -Uri "$progetBaseUrl/v2/$feed/$packageName/manifests/$version" -Method GET -Headers @{"X-ApiKey"="$apiKey";"accept"="application/vnd.docker.distribution.manifest.v2+json"}
		if ($manifestResponse.BaseResponse.StatusCode -eq 'OK') {
			return $true
		} else {
			Write-Error "Check 'if image exits' returned an status code: $($manifestResponse.BaseResponse.StatusCode)"
		}
	} Catch {        
		if($_.ErrorDetails.Message -and $_.ErrorDetails.Message -match 'MANIFEST_UNKNOWN') {
			return $false    
		} else {
			if($_.ErrorDetails.Message) {
				Write-Error "Check 'if image exits' returned an unexpected result: $($_.ErrorDetails.Message)"
			} else {
				Write-Error "Check 'if image exits' returned an unexpected result: $_"
			}
		}
	}
}

Kenneth_Bates · 7 June 2021 04:36

Hi,

Thanks for following up and sharing your code. That totally looks fine, though I’m still unable to reproduce this, so I’m left scratching my head. Could you let me know which version of Octopus you’re currently running (my tests so far have been in 2021.1.7274)? Would you be willing to enable verbose logging and send a resulting task log where this issue is occurring?

I look forward to hearing back!

Best regards,

Kenny

OctopusSchaff · 9 June 2021 00:19

I am currently running version: 2020.6.4688

I enabled the two settings you indicated. It now gives this warning when I run a deploy:

I sent the deployment log to support@octopus.com.

I am staring to notice this issue being more widespread. (I am getting similar issues from a Runbook I am working on that is using Write-Verbose)

OctopusSchaff · 11 June 2021 19:15

Kenneth,

I just wanted to let you know that we updated to Octopus Deploy Version 2021.1 (Build 7316) today and this issue is still present.

I can’t seem to nail down why one script will do it and another will not. (Though, it is usually in my most complex scripts.)

OctopusSchaff · 11 June 2021 20:05

OK, I dug into this some more and here is a stab and some steps to reproduce this issue:

Create a new Project (Mine is in my second space and was called (Testing Logging Bug")
Create a new RunBook (Mine was called “Testing”)
Add a Powershell Script step to the RunBook
Assign it to run only on the Worker
I assigned mine to run on a tentacle running in docker (my Default Worker has some issues).
Set its powershell script to be:

$catalogResponse = Invoke-WebRequest -Uri “https://www.google.com/”
Write-Warning “This Should Log as a Warning”

Save the RunBook
Run the RunBook on an Environment that is setup for the worker.

Result: This is printed to the log:

##octopus[stdout-warning]
This Should Log as a Warning

Please let me know if this allows you to reproduce this.

Kenneth_Bates · 14 June 2021 04:37

Hi @OctopusSchaff,

Thanks for following up! Unfortunately I still haven’t been able to reproduce this, so I’m left scratching my head. I’d be interested to hear if you see any difference in behavior when changing the execution location of the script. Is it possible to try this out by running directly on a deployment target, and on a worker that’s not running in Docker?

I’m hoping that additional information might help us narrow down where the issue might be.

Best regards,

Kenny

OctopusSchaff · 18 June 2021 13:56

I just wanted to drop a message saying I have not abandoned this. But I have gotten really busy and do not have the time to dig into it right now.

I hope in a week or so I can find more details about it.

OctopusSchaff · 29 June 2021 18:51

@Kenneth_Bates,

I switched the worker from my Docker based worker to the “Default Worker Pool” and the error went away.

I switched it back and forth several times. Each time I ran on a docker based worker (either running in Kubernetes or directly from Docker) it would reproduce the error. All my docker based workers are running on Linux.

But when I ran it from the “Default Worker Pool” (which is on a Windows Server), then the error was gone.

Could you try to reproduce the error using a Linux Docker image as the worker?

Kenneth_Bates · 2 July 2021 04:25

Hi @OctopusSchaff,

Thanks for keeping in touch! Firstly my sincere apologies for the delay in getting back to you on this one, as I was out sick over the last couple of days.

I was able to reproduce this issue after running the PS script step inside a Linux Docker container on a worker like you’ve mentioned, so looks like that was my missing piece! I appreciate the effort on your end to narrow this down.

Strangely after a number of attempts to try to further narrow down where the problem could be, I noticed some peculiarities that I raised internally to get some more thoughts on. Specifically, removing the variable definition from the invoke-webrequest line caused the write-warning to actually mark it as a warning. E.g.

Invoke-WebRequest -Uri "https://www.google.com/" -UseBasicParsing
Write-Warning "This should also log as a warning"

And changing it to something similar (just picked this up from Microsoft’s docs) also got the warning to work as expected.

$Response = Invoke-WebRequest -URI https://www.bing.com/search?q=how+many+feet+in+a+mile
$Response.InputFields | Where-Object {
    $_.name -like "* Value*"
} | Select-Object Name, Value
Write-Warning "This should also log as a warning"

I think it must be due to the captured output of the line $catalogResponse = Invoke-WebRequest -Uri “https://www.google.com/”. I can’t see how and why my changes are affecting this, though. I’m hoping to get some more thoughts internally, and I’ll certainly let you know of anything helpful coming from that conversation.

Best regards,

Kenny

Kenneth_Bates · 2 July 2021 05:27

Hi @OctopusSchaff,

Another idea brought to light by a colleague of mine and which worked in my local test is to use the $progressPreference variable like the following.

$ProgressPreference = 'SilentlyContinue'
$catalogResponse = Invoke-WebRequest -Uri "https://www.google.com/"
$ProgressPreference = 'Continue'
Write-Warning "This Should Log as a Warning"

I hope that helps, and please let us know how you go or if you have any further questions.

Best regards,

Kenny

OctopusSchaff · 12 July 2021 17:16

This workaround does work for me.

But now I am wondering, now that this is reproducible, will a bug fix will be released? Or do I need to go back and put this workaround into all my scripts every time I make a web call?

Kenneth_Bates · 13 July 2021 01:40

Hi,

Great to hear, but I see what you mean. I’m not 100% sure whether it will be classified a bug or not, so I’ll raise this internally and let you know one way or another.

I appreciate your help on this one, and let me know if we can try to help with anything in the meantime.

Best regards,

Kenny

OctopusSchaff · 26 July 2021 18:24

Just adding a comment to ensure that this issue does not auto close. (Waiting on reply)

Kenneth_Bates · 27 July 2021 01:26

Hi @OctopusSchaff,

Thank you for keeping in touch and pinging me about this one. My apologies we let this one slip through the cracks. I unfortunately don’t have a solid answer currently, so I raised this one again with the team, and hopefully we can get a path worked out for this. I’ll let you know, and please don’t hesitate to reach out with any questions.

Best regards,

Kenny

Kenneth_Bates · 27 July 2021 06:57

Hi @OctopusSchaff,

Thank you for your patience. Just a quick update that this is being treated as a bug, and we got it raised internally to further investigate.

Please let us know if you have any further questions or concerns!

Best regards,

Kenny

OctopusSchaff · 18 August 2021 17:37

Just curious if this has been given a release milestone?

If its priority is low enough that it will likely not get fixed, or will be a very long time till it will be fixed, please let me know and I will add the workaround as part of my standard scripting (and let this topic close).