search

microsoft / azure-pipelines-tasks

Tasks for Azure Pipelines
https://aka.ms/tfbuild
MIT License
3.47k stars 2.61k forks source link

AzureFileCopy@4 fails while copy is done #14884

Closed dsfrederic closed 3 years ago

dsfrederic commented 3 years ago

Question, Bug, or Feature?
Type: Bug

Enter Task Name: AzureFileCopy

list here (V# not needed):
https://github.com/microsoft/azure-pipelines-tasks/tree/master/Tasks/AzureFileCopyV4

Environment

Issue Description

AzureFileCopyV4 or V3 fail without reason. The files I want to copy are available in the storage account after this task has ran. Both for a "normal" and a storage accountwith hierrarchical namespace enabled this error occurs on the self-hosted agent.

YAML

          - task: AzureFileCopy@4
            inputs:
              sourcePath: '$(Pipeline.Workspace)/build/deliverykit/*'
              azureSubscription: ${{ parameters.service_connection }}
              destination: azureBlob
              storage: ${{ parameters.azure_data_lake_store_name }}
              containerName: shared
              blobPrefix: 'deliverykit/'

Task logs

PIPELINE OUTPUT

2021-05-26T08:30:40.2519514Z ##[debug]Processed: ##vso[telemetry.publish area=TaskEndpointId;feature=AzureFileCopy]{"endpointId":"81fd6590-afc1-425b-847d-f2ba19b2ce72"}
2021-05-26T08:30:40.2564343Z ##[debug]Validating installed azure powershell version is greater than or equal to AzureRM 1.1.0
2021-05-26T08:30:40.2575652Z ##[debug]Cannot verify the Microsoft .NET Framework version 4.5.2 because it is not included in the list of permitted versions.
2021-05-26T08:30:40.2608456Z ##[debug]Populating RepositorySourceLocation property for module AzureRM.
2021-05-26T08:30:40.2691287Z ##[debug]Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\AzureRM\6.9.0\AzureRM.psm1'.
2021-05-26T08:30:40.2901301Z ##[debug]Installed Azure PowerShell version: 6.9.0
2021-05-26T08:30:40.2902329Z ##[debug]Compare azure versions: 6.9.0, 1.1.0
2021-05-26T08:30:40.2998022Z ##[debug]Validated the required azure powershell version is greater than or equal to 1.1.0
2021-05-26T08:30:40.3284908Z ##[debug][Azure Call]Getting resource details for azure storage account resource: adlskrcgtst269 with resource type: Microsoft.Storage/storageAccounts
2021-05-26T08:30:41.5176139Z ##[debug][Azure Call]Retrieved resource details successfully for azure storage account resource: adlskrcgtst269 with resource type: Microsoft.Storage/storageAccounts
2021-05-26T08:30:41.5243689Z ##[debug][Azure Call]Retrieving storage key for the storage account: adlskrcgtst269 in resource group: 
2021-05-26T08:30:41.5467416Z ##[debug]Fetching Access Token
2021-05-26T08:30:41.5724280Z ##[debug]POST https://login.windows.net/***/oauth2/token with -1-byte payload
2021-05-26T08:30:41.8076581Z ##[debug]received 1450-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:41.8144863Z ##[debug]Fetching Access Token
2021-05-26T08:30:41.8163914Z ##[debug]POST https://login.windows.net/***/oauth2/token with -1-byte payload
2021-05-26T08:30:41.9711003Z ##[debug]received 1450-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:41.9787674Z ##[debug]GET https://management.azure.com//subscriptions/cc3a2c95-5465-48d4-aa21-66c07548ac70/resourceGroups/rg-krcg-tst-01?api-version=2016-02-01 with 0-byte payload
2021-05-26T08:30:42.0285190Z ##[debug]received 185-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:42.0340729Z ##[debug]POST https://management.azure.com//subscriptions/cc3a2c95-5465-48d4-aa21-66c07548ac70/resourceGroups/rg-krcg-tst-01/providers/Microsoft.Storage/storageAccounts/adlskrcgtst269/listKeys?api-version=2015-06-15 with 0-byte payload
2021-05-26T08:30:42.1156404Z ##[debug]received 197-byte response of content type application/json
2021-05-26T08:30:42.1204706Z ##[debug][Azure Call]Retrieved storage key successfully for the storage account: adlskrcgtst269 in resource group: rg-krcg-tst-01
2021-05-26T08:30:42.1265099Z ##[debug][Azure Call]Creating AzureStorageContext for storage account: adlskrcgtst269
2021-05-26T08:30:42.1473203Z ##[debug][Azure Call]Created AzureStorageContext for storage account: adlskrcgtst269
2021-05-26T08:30:42.1556120Z ##[debug][Azure Call]Getting resource details for azure storage account resource: adlskrcgtst269 with resource type: Microsoft.Storage/storageAccounts
2021-05-26T08:30:42.5865675Z ##[debug][Azure Call]Retrieved resource details successfully for azure storage account resource: adlskrcgtst269 with resource type: Microsoft.Storage/storageAccounts
2021-05-26T08:30:42.5910733Z ##[debug][Azure Call]Retrieving storage account type for the storage account: adlskrcgtst269 in resource group: rg-krcg-tst-01
2021-05-26T08:30:42.5983269Z ##[debug]Fetching Access Token
2021-05-26T08:30:42.6001219Z ##[debug]POST https://login.windows.net/***/oauth2/token with -1-byte payload
2021-05-26T08:30:42.7593801Z ##[debug]received 1450-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:42.7622942Z ##[debug]Fetching Access Token
2021-05-26T08:30:42.7647248Z ##[debug]POST https://login.windows.net/***/oauth2/token with -1-byte payload
2021-05-26T08:30:42.8995574Z ##[debug]received 1450-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:42.9030550Z ##[debug]GET https://management.azure.com//subscriptions/cc3a2c95-5465-48d4-aa21-66c07548ac70/resourceGroups/rg-krcg-tst-01?api-version=2016-02-01 with 0-byte payload
2021-05-26T08:30:42.9272882Z ##[debug]received 185-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:42.9293940Z ##[debug]GET https://management.azure.com//subscriptions/cc3a2c95-5465-48d4-aa21-66c07548ac70/resourceGroups/rg-krcg-tst-01/providers/Microsoft.Storage/storageAccounts/adlskrcgtst269?api-version=2016-01-01 with 0-byte payload
2021-05-26T08:30:42.9865441Z ##[debug]received 946-byte response of content type application/json
2021-05-26T08:30:42.9890868Z ##[debug]Constructing the storage account object
2021-05-26T08:30:43.0131080Z ##[debug][Azure Call]Retrieved storage account type successfully for the storage account: adlskrcgtst269 in resource group: rg-krcg-tst-01
2021-05-26T08:30:43.0174362Z ##[debug]Obtained Storage Account type: Standard
2021-05-26T08:30:43.0267115Z ##[debug][Azure Call]Getting container: shared in storage account: adlskrcgtst269
2021-05-26T08:30:43.3138985Z ##[debug][Azure Call]Getting resource details for azure storage account resource: adlskrcgtst269 with resource type: Microsoft.Storage/storageAccounts
2021-05-26T08:30:43.7854189Z ##[debug][Azure Call]Retrieved resource details successfully for azure storage account resource: adlskrcgtst269 with resource type: Microsoft.Storage/storageAccounts
2021-05-26T08:30:43.7880465Z ##[debug][Azure Call]Retrieving storage account endpoint for the storage account: adlskrcgtst269 in resource group: rg-krcg-tst-01
2021-05-26T08:30:43.7911296Z ##[debug]Fetching Access Token
2021-05-26T08:30:43.7942429Z ##[debug]POST https://login.windows.net/***/oauth2/token with -1-byte payload
2021-05-26T08:30:43.8799337Z ##[debug]received 1450-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:43.8828207Z ##[debug]Fetching Access Token
2021-05-26T08:30:43.8855672Z ##[debug]POST https://login.windows.net/***/oauth2/token with -1-byte payload
2021-05-26T08:30:43.9638426Z ##[debug]received 1450-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:43.9672187Z ##[debug]GET https://management.azure.com//subscriptions/cc3a2c95-5465-48d4-aa21-66c07548ac70/resourceGroups/rg-krcg-tst-01?api-version=2016-02-01 with 0-byte payload
2021-05-26T08:30:43.9910451Z ##[debug]received 185-byte response of content type application/json; charset=utf-8
2021-05-26T08:30:43.9932062Z ##[debug]GET https://management.azure.com//subscriptions/cc3a2c95-5465-48d4-aa21-66c07548ac70/resourceGroups/rg-krcg-tst-01/providers/Microsoft.Storage/storageAccounts/adlskrcgtst269?api-version=2016-01-01 with 0-byte payload
2021-05-26T08:30:44.0286956Z ##[debug]received 946-byte response of content type application/json
2021-05-26T08:30:44.0308586Z ##[debug]Constructing the storage account object
2021-05-26T08:30:44.0462293Z ##[debug][Azure Call]Retrieved storage account endpoint successfully for the storage account: adlskrcgtst269 in resource group: rg-krcg-tst-01
2021-05-26T08:30:44.0493206Z ##[debug]Using default AzCopy arguments for uploading to blob storage
2021-05-26T08:30:44.0519373Z ##[debug]Adding argument for recursive copy
2021-05-26T08:30:44.0861973Z ##[debug]AAD autority URL = https://login.windows.net/
2021-05-26T08:30:44.0940196Z ##[command] & "AzCopy\AzCopy.exe" login --service-principal --application-id "***" --tenant-id="***" --aad-endpoint "https://login.windows.net/"
2021-05-26T08:30:44.1261415Z INFO: If you set an environment variable by using the command line, that variable will be readable in your command line history. Consider clearing variables that contain credentials from your command line history.  To keep variables from appearing in your history, you can use a script to prompt the user for their credentials, and to set the environment variable.
2021-05-26T08:30:44.2217359Z INFO: AzCopy.exe: A newer version 10.10.0 is available to download
2021-05-26T08:30:44.2217905Z 
2021-05-26T08:30:44.4414102Z INFO: SPN Auth via secret succeeded.
2021-05-26T08:30:44.4913440Z INFO: AzCopy.exe: A newer version 10.10.0 is available to download
2021-05-26T08:30:44.4913769Z 
2021-05-26T08:30:44.5102397Z Uploading files from source path: 'C:\agents\agent-1\_work\1\build\deliverykit\*' to storage account: 'adlskrcgtst269' in container: 'shared' with blob prefix: 'deliverykit/'
2021-05-26T08:30:44.5217936Z ##[command] & "AzCopy\AzCopy.exe" copy "C:\agents\agent-1\_work\1\build\deliverykit\*" "https://adlskrcgtst269.blob.core.windows.net/shared/deliverykit"  --log-level=INFO --recursive
2021-05-26T08:30:44.5556391Z INFO: Scanning...
2021-05-26T08:30:44.5556769Z INFO: Authenticating to destination using Azure AD
2021-05-26T08:30:44.6577520Z INFO: AzCopy.exe: A newer version 10.10.0 is available to download
2021-05-26T08:30:44.6577809Z 
2021-05-26T08:30:44.9299298Z INFO: Any empty folders will not be processed, because source and/or destination doesn't have full folder support
2021-05-26T08:30:44.9684027Z 
2021-05-26T08:30:44.9688581Z Job 93826112-183f-e54c-5fe5-8152497c8fe1 has started
2021-05-26T08:30:44.9689214Z Log file is located at: C:\Windows\ServiceProfiles\NetworkService\.azcopy\93826112-183f-e54c-5fe5-8152497c8fe1.log
2021-05-26T08:30:44.9689977Z 
2021-05-26T08:30:44.9690102Z 
2021-05-26T08:30:46.9644494Z 0.0 %, 0 Done, 0 Failed, 6 Pending, 0 Skipped, 6 Total, 
2021-05-26T08:30:46.9645088Z 
2021-05-26T08:30:46.9645295Z 
2021-05-26T08:30:46.9645685Z Job 93826112-183f-e54c-5fe5-8152497c8fe1 summary
2021-05-26T08:30:46.9646111Z Elapsed Time (Minutes): 0.0334
2021-05-26T08:30:46.9646545Z Number of File Transfers: 6
2021-05-26T08:30:46.9646965Z Number of Folder Property Transfers: 0
2021-05-26T08:30:46.9647399Z Total Number of Transfers: 6
2021-05-26T08:30:46.9647817Z Number of Transfers Completed: 0
2021-05-26T08:30:46.9648342Z Number of Transfers Failed: 6
2021-05-26T08:30:46.9648867Z Number of Transfers Skipped: 0
2021-05-26T08:30:46.9649355Z TotalBytesTransferred: 0
2021-05-26T08:30:46.9649749Z Final Job Status: Failed
2021-05-26T08:30:46.9649982Z 
2021-05-26T08:30:46.9841617Z ##[debug]ExceptionMessage: AzCopy.exe exited with non-zero exit code while uploading files to blob storage.
2021-05-26T08:30:46.9992200Z ##[debug]Processed: ##vso[task.logissue type=error;code={"Task_Internal_Error":"BlobUploadFailed"};]
2021-05-26T08:30:47.0164061Z ##[command] & "AzCopy\AzCopy.exe" logout
2021-05-26T08:30:47.0459959Z INFO: Logout succeeded.
2021-05-26T08:30:47.1878780Z INFO: AzCopy.exe: A newer version 10.10.0 is available to download
2021-05-26T08:30:47.1879148Z 
2021-05-26T08:30:47.1889740Z INFO: AzCopy.exe: A newer version 10.10.0 is available to download
2021-05-26T08:30:47.1890932Z 
2021-05-26T08:30:47.2031834Z ##[debug]Trying to disconnect from Azure and clear context at process scope
2021-05-26T08:30:47.2245860Z ##[command]Disconnect-AzureRmAccount -Scope Process -ErrorAction Stop
2021-05-26T08:30:47.8289227Z ##[command]Clear-AzureRmContext -Scope Process -ErrorAction Stop
2021-05-26T08:30:48.4353164Z ##[debug]Caught exception from task script.
2021-05-26T08:30:48.4401198Z ##[debug]Error record:
2021-05-26T08:30:48.5364928Z ##[debug]Upload to container: 'shared' in storage account: 'adlskrcgtst269' with blob prefix: 'deliverykit/' failed with error: 'AzCopy.exe exited with non-zero exit code while uploading files to blob storage.' For more info please refer to https://aka.ms/azurefilecopyreadme
2021-05-26T08:30:48.5379176Z ##[debug]At C:\agents\agent-1\_work\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\4.185.0\Utility.ps1:109 char:5
2021-05-26T08:30:48.5389419Z ##[debug]+     throw "$errorMessage $helpMessage"
2021-05-26T08:30:48.5442655Z ##[debug]+     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2021-05-26T08:30:48.5453105Z ##[debug]    + CategoryInfo          : OperationStopped: (Upload to conta...efilecopyreadme:String) [], RuntimeException
2021-05-26T08:30:48.5463747Z ##[debug]    + FullyQualifiedErrorId : Upload to container: 'shared' in storage account: 'adlskrcgtst269' with blob prefix: 'de    liverykit/' failed with error: 'AzCopy.exe exited with non-zero exit code while uploading files to blob storage.'     For more info please refer to https://aka.ms/azurefilecopyreadme
2021-05-26T08:30:48.5473581Z ##[debug] 
2021-05-26T08:30:48.5492267Z ##[debug]Script stack trace:
2021-05-26T08:30:48.5533362Z ##[debug]at ThrowError, C:\agents\agent-1\_work\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\4.185.0\Utility.ps1: line 109
2021-05-26T08:30:48.5546321Z ##[debug]at Upload-FilesToAzureContainer, C:\agents\agent-1\_work\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\4.185.0\Utility.ps1: line 248
2021-05-26T08:30:48.5556910Z ##[debug]at <ScriptBlock>, C:\agents\agent-1\_work\_tasks\AzureFileCopy_eb72cb01-a7e5-427b-a8a1-1b31ccac8a43\4.185.0\AzureFileCopy.ps1: line 181
2021-05-26T08:30:48.5568206Z ##[debug]at <ScriptBlock>, <No file>: line 1
2021-05-26T08:30:48.5578738Z ##[debug]at <ScriptBlock>, <No file>: line 22
2021-05-26T08:30:48.5589194Z ##[debug]at <ScriptBlock>, <No file>: line 18
2021-05-26T08:30:48.5599405Z ##[debug]at <ScriptBlock>, <No file>: line 1
2021-05-26T08:30:48.5617902Z ##[debug]Exception:
2021-05-26T08:30:48.5655602Z ##[debug]System.Management.Automation.RuntimeException: Upload to container: 'shared' in storage account: 'adlskrcgtst269' with blob prefix: 'deliverykit/' failed with error: 'AzCopy.exe exited with non-zero exit code while uploading files to blob storage.' For more info please refer to https://aka.ms/azurefilecopyreadme
2021-05-26T08:30:48.5818811Z ##[error]Upload to container: 'shared' in storage account: 'adlskrcgtst269' with blob prefix: 'deliverykit/' failed with error: 'AzCopy.exe exited with non-zero exit code while uploading files to blob storage.' For more info please refer to https://aka.ms/azurefilecopyreadme
2021-05-26T08:30:48.5821673Z ##[debug]Processed: ##vso[task.logissue type=error]Upload to container: 'shared' in storage account: 'adlskrcgtst269' with blob prefix: 'deliverykit/' failed with error: 'AzCopy.exe exited with non-zero exit code while uploading files to blob storage.' For more info please refer to https://aka.ms/azurefilecopyreadme
2021-05-26T08:30:48.5856278Z ##[debug]Processed: ##vso[task.complete result=Failed]
2021-05-26T08:30:48.6342983Z ##[section]Finishing: AzureFileCopy

AzCopy log output 


   GET https://adlskrcgtst269.blob.core.windows.net/shared/deliverykit/Cegeka_Data_Platform_Delivery_Kit_Starnet_MasterData.xlsx?blocklisttype=all&comp=blocklist&timeout=31
   X-Ms-Request-Id: [90e50c99-701e-007b-0509-52a832000000]

2021/05/26 08:30:45 JobID=93826112-183f-e54c-5fe5-8152497c8fe1, Part#=0, TransfersDone=1 of 6
2021/05/26 08:30:45 ==> REQUEST/RESPONSE (Try=1/14.9996ms, OpTime=14.9996ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://adlskrcgtst269.blob.core.windows.net/shared/deliverykit/Cegeka_Data_Platform_Delivery_Kit_Tilroy_Sales.xlsx?blocklisttype=all&comp=blocklist&timeout=31
   X-Ms-Request-Id: [d8866698-d01e-00a9-6609-522bdc000000]

2021/05/26 08:30:45 JobID=93826112-183f-e54c-5fe5-8152497c8fe1, Part#=0, TransfersDone=2 of 6
2021/05/26 08:30:45 ==> REQUEST/RESPONSE (Try=1/14.999ms, OpTime=14.999ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://adlskrcgtst269.blob.core.windows.net/shared/deliverykit/Cegeka_Data_Platform_Delivery_Kit_Starnet_Access.xlsx?blocklisttype=all&comp=blocklist&timeout=31
   X-Ms-Request-Id: [f1df29a4-501e-007c-4f09-52c451000000]

2021/05/26 08:30:45 JobID=93826112-183f-e54c-5fe5-8152497c8fe1, Part#=0, TransfersDone=3 of 6
2021/05/26 08:30:45 ==> REQUEST/RESPONSE (Try=1/16.9985ms, OpTime=16.9985ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://adlskrcgtst269.blob.core.windows.net/shared/deliverykit/Cegeka_Data_Platform_Delivery_Kit_TicketMaster.xlsx?blocklisttype=all&comp=blocklist&timeout=31
   X-Ms-Request-Id: [e01926ee-301e-008e-7409-523c18000000]

2021/05/26 08:30:45 JobID=93826112-183f-e54c-5fe5-8152497c8fe1, Part#=0, TransfersDone=4 of 6
2021/05/26 08:30:45 ==> REQUEST/RESPONSE (Try=1/18.9999ms, OpTime=18.9999ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://adlskrcgtst269.blob.core.windows.net/shared/deliverykit/Cegeka_Data_Platform_Delivery_Kit_SportsAlliance_DWH.xlsx?blocklisttype=all&comp=blocklist&timeout=31
   X-Ms-Request-Id: [abda6335-801e-008b-1709-52eec3000000]

2021/05/26 08:30:45 JobID=93826112-183f-e54c-5fe5-8152497c8fe1, Part#=0, TransfersDone=5 of 6
2021/05/26 08:30:45 ==> REQUEST/RESPONSE (Try=1/20.0001ms, OpTime=20.0001ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://adlskrcgtst269.blob.core.windows.net/shared/deliverykit/Cegeka_Data_Platform_Delivery_Kit_Starnet_CashLess.xlsx?blocklisttype=all&comp=blocklist&timeout=31
   X-Ms-Request-Id: [68bf2dd9-f01e-0065-6509-5244ea000000]

2021/05/26 08:30:45 JobID=93826112-183f-e54c-5fe5-8152497c8fe1, Part#=0, TransfersDone=6 of 6
2021/05/26 08:30:45 all parts of entire Job 93826112-183f-e54c-5fe5-8152497c8fe1 successfully completed, cancelled or paused
2021/05/26 08:30:46 PERF: primary performance constraint is Unknown. States: X:  0, O:  0, M:  0, L:  0, R:  0, D:  0, W:  0, F:  0, B:  0, E:  0, T:  0, GRs: 32
2021/05/26 08:30:46 

Diagnostic stats:
IOPS: 4
End-to-end ms per request: 54
Network Errors: 0.00%
Server Busy: 0.00%

Job 93826112-183f-e54c-5fe5-8152497c8fe1 summary
Elapsed Time (Minutes): 0.0334
Number of File Transfers: 6
Number of Folder Property Transfers: 0
Total Number of Transfers: 6
Number of Transfers Completed: 0
Number of Transfers Failed: 6
Number of Transfers Skipped: 0
TotalBytesTransferred: 0
Final Job Status: Failed

Troubleshooting

I've checked:

chshrikh commented 3 years ago

can you attempt to change the blobPrefix inputblobPrefix: 'deliverykit/' to blobPrefix: 'deliverykit' and re-run the pipeline

dsfrederic commented 3 years ago

@chshrikh your proposed solution resulted in the exactly same output.

PS: Can I ask why you would remove the bug label without knowing if you're solution works? Pls reopen this. There'sm something here, especially since it worked perfectly on a MS hosted agent.

chshrikh commented 3 years ago

@dandancode 1) the labels used are here are for internal tracking purpose, we have not closed this issue 2) are you seeing this issue only when using private agent ? Are you saying this works fine with hosted agent ?

dsfrederic commented 3 years ago

@chshrikh I'm seeing this issue only when using private agent. This works fine on a hosted agent

AmrutaKawade commented 3 years ago

@dsfrederic which version of azcopy.exe installed on your agent?

AmrutaKawade commented 3 years ago

@dsfrederic any update?

chshrikh commented 3 years ago

closing due to lack of activity