[BUG]: AzureFileCopyV6 failed copy to azure vm

tomo-mae1 commented 2 months ago

New issue checklist

[x] I searched for existing GitHub issues
[x] I read pipeline troubleshooting guide
[x] I checked how to collect logs

Task name

AzureFileCopy

Task version

6.245.1

Issue Description

I'm testing the AzureFileCopyV6 task because I want to copy a file in a repository to a specific folder on an Azure VM. After resolving some errors, I was blocked by the following error that I don't know how to solve.

Error: Failed to perform Auto-login: PSContextCredentialGet-AzAccessToken: -REDACTED-;1mRun Connect-AzAccount to login.

I think task was probably using AzCopy.exe twice, but the error occurs the second time.

1. Use AzCopy.exe on the Agent to upload files to storage
1. Use AzCopy.exe on the VM to download files from storage

I installed Azure PowerShell on the target VM, but the issue persisted. Is this a bug? Or is there something missing in my settings?

Environment type (Please select at least one enviroment where you face this issue)

[ ] Self-Hosted
[x] Microsoft Hosted
[ ] VMSS Pool
[ ] Container

Azure DevOps Server type

dev.azure.com (formerly visualstudio.com)

Azure DevOps Server Version (if applicable)

No response

Operation system

Windows 11

Relevant log output

2024-09-12T01:48:39.9855702Z ##[debug]Evaluating condition for step: 'AzureFileCopy'
2024-09-12T01:48:39.9856668Z ##[debug]Evaluating: SucceededNode()
2024-09-12T01:48:39.9856995Z ##[debug]Evaluating SucceededNode:
2024-09-12T01:48:39.9857536Z ##[debug]=> True
2024-09-12T01:48:39.9857866Z ##[debug]Result: True
2024-09-12T01:48:39.9858191Z ##[section]Starting: AzureFileCopy
2024-09-12T01:48:39.9865614Z ==============================================================================
2024-09-12T01:48:39.9865795Z Task         : Azure file copy
2024-09-12T01:48:39.9865896Z Description  : Copy files to Azure Blob Storage or virtual machines
2024-09-12T01:48:39.9866155Z Version      : 6.245.1
2024-09-12T01:48:39.9866253Z Author       : Microsoft Corporation
2024-09-12T01:48:39.9866355Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/deploy/azure-file-copy
2024-09-12T01:48:39.9866517Z ==============================================================================

(Omitted)

2024-09-12T01:50:00.2684618Z ##[debug]JobId: '2', JobState: 'running', ComputerName: '20.205.143.232'
2024-09-12T01:50:00.2693934Z ================================================ 20.205.143.232 ================================================
2024-09-12T01:50:00.2725596Z ##[debug]Agent environment resources - Disk: D:\ Available 12383.33 MB out of 14334.00 MB, Memory: Used 2429.00 MB out of 7167.00 MB, CPU: Usage 56.00%
2024-09-12T01:50:05.2866831Z ##[debug]JobId: '2', JobState: 'running', ComputerName: '20.205.143.232'
2024-09-12T01:50:05.2868829Z ================================================ 20.205.143.232 ================================================
2024-09-12T01:50:05.2974042Z ##[command]& 'C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe' -NoLogo -NoProfile -NonInteractive 
2024-09-12T01:50:05.2977818Z -ExecutionPolicy Unrestricted -Command ". 
2024-09-12T01:50:05.2981291Z 'C:\Users\<VMadminuserName>\AppData\Local\Temp\90a70d63-8e9d-480d-ad8d-e4a45045a426.ps1'"
2024-09-12T01:50:05.2982919Z 
2024-09-12T01:50:05.3107486Z VERBOSE: Using default AzCopy arguments for dowloading to VM
2024-09-12T01:50:05.3108112Z 
2024-09-12T01:50:05.3146598Z VERBOSE: ##[command] & azcopy copy 
2024-09-12T01:50:05.3146924Z 
2024-09-12T01:50:05.3169941Z "https://<storageName>.blob.core.windows.net/2065244c-6f26-4e53-862f-83a3e88b01f6" 
2024-09-12T01:50:05.3170482Z 
2024-09-12T01:50:05.3190677Z "c:\test\" --recursive --log-level=INFO
2024-09-12T01:50:05.3191120Z 
2024-09-12T01:50:05.3212587Z INFO: AzCopy.exe 10.25.1: A newer version 10.26.0 is available to download
2024-09-12T01:50:05.3213069Z 
2024-09-12T01:50:05.3234105Z 
2024-09-12T01:50:05.3234862Z 
2024-09-12T01:50:05.3254942Z INFO: Scanning...
2024-09-12T01:50:05.3255658Z 
2024-09-12T01:50:05.5598164Z ##[debug]Agent environment resources - Disk: D:\ Available 12383.33 MB out of 14334.00 MB, Memory: Used 2441.00 MB out of 7167.00 MB, CPU: Usage 10.00%
2024-09-12T01:50:10.3281955Z ##[debug]JobId: '2', JobState: 'completed', ComputerName: '20.205.143.232'
2024-09-12T01:50:10.3294195Z ================================================ 20.205.143.232 ================================================
2024-09-12T01:50:10.3318867Z 
2024-09-12T01:50:10.3319640Z 
2024-09-12T01:50:10.3346214Z Failed to perform Auto-login: PSContextCredential[31;1mGet-AzAccessToken: -REDACTED-;1mRun Connect-AzAccount to login.[0m
2024-09-12T01:50:10.3346535Z 
2024-09-12T01:50:10.3374675Z .
2024-09-12T01:50:10.3375072Z 
2024-09-12T01:50:10.3396903Z ##[debug][<azureVMName>]LASTEXITCODE is 1
2024-09-12T01:50:10.3397454Z 
2024-09-12T01:50:10.3473610Z ##[debug]Leaving Get-JobResults.
2024-09-12T01:50:10.3494264Z ##[debug]Leaving Run-RemoteScriptJobs.
2024-09-12T01:50:10.3580874Z ##[debug]Entering Publish-Telemetry.
2024-09-12T01:50:10.3610580Z ##[debug]SYSTEM_JOBID: '12f1170f-54f2-53f3-20dd-22fc7dff55f9'
2024-09-12T01:50:10.3752446Z ##[debug]Telemetry Data is: {    "TelemetryError":  "",    "JobId":  "12f1170f-54f2-53f3-20dd-22fc7dff55f9",    "IsAzureVm":  true,    "AzureSubscriptionId":  "3e797da5-b05f-4904-a0ba-bb6a7e8e9d5f",    "VmUuidHash":  "01172B5D5CE7D960BA41FD88A9A4E779972639434D1E11CF14BD4269CFEDF1AF112404411CC535D27DCB5BAA7CFD93030BF744F425F67CAFCF4104E835149666"}
2024-09-12T01:50:10.4151137Z ##[debug]Processed: ##vso[telemetry.publish area=TaskHub;feature=PowerShellOnTargetMachines]{    "TelemetryError":  "",    "JobId":  "12f1170f-54f2-53f3-20dd-22fc7dff55f9",    "IsAzureVm":  true,    "AzureSubscriptionId":  "3e797da5-b05f-4904-a0ba-bb6a7e8e9d5f",    "VmUuidHash":  "01172B5D5CE7D960BA41FD88A9A4E779972639434D1E11CF14BD4269CFEDF1AF112404411CC535D27DCB5BAA7CFD93030BF744F425F67CAFCF4104E835149666"}
2024-09-12T01:50:10.4152449Z ##[debug]Leaving Publish-Telemetry.
2024-09-12T01:50:10.4152924Z ##[debug]Entering Upload-TargetMachineLogs.
2024-09-12T01:50:10.4153442Z ##[debug] logsFolder: 'D:\a\_temp\29899e04-ea32-43f1-95b6-bb53766c79c7'
2024-09-12T01:50:10.4165367Z ##[debug]Processed: ##vso[task.uploadfile]D:\a\_temp\29899e04-ea32-43f1-95b6-bb53766c79c7\20.205.143.232.log
2024-09-12T01:50:10.4166194Z ##[debug]Leaving Upload-TargetMachineLogs.
2024-09-12T01:50:10.4193013Z ##[debug]Entering Set-TaskResult.
2024-09-12T01:50:10.4538787Z ##[debug]Remote script execution completed for machine: <azureVMName>
2024-09-12T01:50:10.4653695Z ##[debug]Leaving Set-TaskResult.
2024-09-12T01:50:10.4705380Z ##[debug]Entering Disconnect-WinRmConnectionToTargetMachines.
2024-09-12T01:50:10.4759216Z ##[debug]Entering Get-RemoteConnection.
2024-09-12T01:50:10.6491714Z ##[debug]Leaving Get-RemoteConnection.
2024-09-12T01:50:10.6514654Z ##[debug]Trying to disconnect pssession with name: 1569ce82-e358-41b1-8d9c-7e282899365e, computerName: 20.205.143.232
2024-09-12T01:50:10.6600478Z ##[debug]Successfully disconnected session: 1569ce82-e358-41b1-8d9c-7e282899365e on computer: 20.205.143.232
2024-09-12T01:50:10.6620247Z ##[debug]Leaving Disconnect-WinRmConnectionToTargetMachines.
2024-09-12T01:50:10.6638831Z ##[debug]Leaving Invoke-RemoteScript.
2024-09-12T01:50:10.6667348Z ##[debug]Parallel file copy: Invoke-RemoteScript threw exception
2024-09-12T01:50:10.6740679Z ##[debug]Microsoft.PowerShell.Commands.WriteErrorException: Non-Zero exit code: '1' for ComputerName: '<azureVMName>'
2024-09-12T01:50:10.6803308Z ##[debug]Processed: ##vso[task.logissue type=error;code={"Task_Internal_Error":"CopyingToAzureVMFailed"};]
2024-09-12T01:50:10.6862071Z ##[debug][Azure Call]Deleting container: 2065244c-6f26-4e53-862f-83a3e88b01f6 in storage account: <storageName>
2024-09-12T01:50:10.7826778Z ##[debug]Removed container '2065244c-6f26-4e53-862f-83a3e88b01f6' successfully.
2024-09-12T01:50:10.8101479Z ##[debug][Azure Call]Deleted container: 2065244c-6f26-4e53-862f-83a3e88b01f6 in storage account: <storageName>
2024-09-12T01:50:10.8133386Z ##[debug]Completed Azure File Copy Task for Azure VMs Destination
2024-09-12T01:50:10.8185521Z ##[debug]Leaving D:\a\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\6.245.1\AzureFileCopy.ps1.
2024-09-12T01:50:10.8221544Z ##[debug]Trying to disconnect from Azure and clear context at process scope
2024-09-12T01:50:10.8335373Z ##[debug]Cannot verify the Microsoft .NET Framework version 4.7.2 because it is not included in the list of permitted versions.
2024-09-12T01:50:10.8357806Z ##[debug]Populating RepositorySourceLocation property for module Az.Accounts.
2024-09-12T01:50:10.8384556Z ##[debug]Loading module from path 'C:\Modules\az_12.1.0\Az.Accounts\3.0.3\Az.Accounts.psm1'.
2024-09-12T01:50:10.8600981Z ##[debug]Agent environment resources - Disk: D:\ Available 12383.33 MB out of 14334.00 MB, Memory: Used 2331.00 MB out of 7167.00 MB, CPU: Usage 61.00%
2024-09-12T01:50:10.8926636Z ##[command]Disconnect-AzAccount -Scope Process -ErrorAction Stop
2024-09-12T01:50:10.9266427Z ##[command]Clear-AzContext -Scope Process -ErrorAction Stop
2024-09-12T01:50:10.9583052Z ##[debug]Caught exception from task script.
2024-09-12T01:50:10.9622566Z ##[debug]Error record:
2024-09-12T01:50:11.0348462Z ##[debug]Set-TaskResult : Non-Zero exit code: '1' for ComputerName: '<azureVMName>'
2024-09-12T01:50:11.0361952Z ##[debug]At D:\a\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\6.245.1\ps_modules\RemoteDeployer\RemoteDeployer.psm1:134 char:9
2024-09-12T01:50:11.0374345Z ##[debug]+         Set-TaskResult -jobResults $jobResults -machinesCount $target ...
2024-09-12T01:50:11.0386531Z ##[debug]+         ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2024-09-12T01:50:11.0398908Z ##[debug]    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
2024-09-12T01:50:11.0413261Z ##[debug]    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,Set-TaskResult
2024-09-12T01:50:11.0425722Z ##[debug] 
2024-09-12T01:50:11.0449220Z ##[debug]Script stack trace:
2024-09-12T01:50:11.0481524Z ##[debug]at Set-TaskResult, D:\a\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\6.245.1\ps_modules\RemoteDeployer\RemoteDeployer.Utility.ps1: line 138
2024-09-12T01:50:11.0494257Z ##[debug]at Invoke-RemoteScript, D:\a\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\6.245.1\ps_modules\RemoteDeployer\RemoteDeployer.psm1: line 134
2024-09-12T01:50:11.0507560Z ##[debug]at Copy-FilesParallellyToAzureVMs, D:\a\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\6.245.1\Utility.ps1: line 878
2024-09-12T01:50:11.0519890Z ##[debug]at Copy-FilesToAzureVMsFromStorageContainer, D:\a\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\6.245.1\Utility.ps1: line 1021
2024-09-12T01:50:11.0533400Z ##[debug]at <ScriptBlock>, D:\a\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\6.245.1\AzureFileCopy.ps1: line 225
2024-09-12T01:50:11.0546075Z ##[debug]at <ScriptBlock>, <No file>: line 1
2024-09-12T01:50:11.0558892Z ##[debug]at <ScriptBlock>, <No file>: line 22
2024-09-12T01:50:11.0571667Z ##[debug]at <ScriptBlock>, <No file>: line 18
2024-09-12T01:50:11.0584454Z ##[debug]at <ScriptBlock>, <No file>: line 1
2024-09-12T01:50:11.0604128Z ##[debug]Exception:
2024-09-12T01:50:11.0624068Z ##[debug]Microsoft.PowerShell.Commands.WriteErrorException: Non-Zero exit code: '1' for ComputerName: '<azureVMName>'
2024-09-12T01:50:11.0682030Z ##[error]Non-Zero exit code: '1' for ComputerName: '<azureVMName>'
2024-09-12T01:50:11.0683098Z ##[debug]Processed: ##vso[task.logissue type=error;source=TaskInternal;correlationId=d1c7beee-9334-4afb-8e2b-a756775854aa]Non-Zero exit code: '1' for ComputerName: '<azureVMName>'
2024-09-12T01:50:11.0704321Z ##[debug]Processed: ##vso[task.complete result=Failed]
2024-09-12T01:50:11.1680227Z ##[section]Finishing: AzureFileCopy

Full task logs with system.debug enabled

Azure-file-copy-v6.log

Repro steps

Repro step:
1. Add testing file to repository (test.txt)
2. Create New Azure VM (Target VM)
3. Create target folder to Target VM (c:\test\)
4. Run following command to enable WinRM on Target VM

Command: Enable-PSRemoting -SkipNetworkProfileCheck

5. Add inbound rule to NSG to allow Port 5986 
6. Install PowerShell 7.4.5 to Target VM
7. Install Azure PowerShell to Target VM
8. Run Pipeline

YAML:
trigger:
- main

pool: 
 vmImage: windows-latest

steps:
- task: AzureFileCopy@6
  inputs:
    SourcePath: 'test.txt'
    azureSubscription: '<ARMServiceConnectionName>' # use workload identity federation
    Destination: 'AzureVMs'
    storage: '<storageName>'
    resourceGroup: '<resourcegroupName>'
    MachineNames: '<azureVMName>'
    vmsAdminUserName: '<VMadminuserName>'
    vmsAdminPassword: '$(Admin-Pass)' # set variable in UI to right password.
    TargetPath: 'c:\test\'

tomo-mae1 commented 2 months ago

This issue doesn't occur with AzureFileCopyV5. I believe this is because V5 not use auto-login to authenticate AzCopy.exe.

v-schhabra commented 1 month ago

Hi @tomo-mae1 Could you install Get-AzContext module on your agent machine and check if still the error continues?

LeftTwixWand commented 1 month ago

Hey @tomo-mae1 do you use 1ES Hosted Pool or Azure Pipelines agent pool?

tomo-mae1 commented 1 month ago

Hello, @v-schhabra and @LeftTwixWand I used Azure Pipelines agent pool, that image is windows-latest. I believe microsoft hosted windows agent has all the azure powershell modules installed.

v-schhabra commented 1 month ago

@tomo-mae1 Yes, If you are using Microsoft hosted windows agent then the agent will have all the modules installed.

tomo-mae1 commented 1 month ago

Thank you. If so, I believe the agent machine has Get-AzContext module Installed.

UntiIted commented 3 days ago

Any updates on this issue? It occurs on the target machine, not the agent machine. Powershell 7 and required Az Modules had to be installed manually even though it's undocumented in the task prerequisites, and afterwards we run into the same issue.

microsoft / azure-pipelines-tasks