Azure-pipelines-tasks: Copy Files Over SSH: The task has timed out

[meriturva]

Question, Bug, or Feature?
Type: Bug

Enter Task Name: Copy files over SSH

Environment

• Server - Azure Pipelines

Issue Description

Just see tasks logs.

Task logs

2019-08-29T17:22:52.0779093Z ==============================================================================
2019-08-29T17:22:52.0779235Z Task : Copy files over SSH
2019-08-29T17:22:52.0779328Z Description : Copy files or build artifacts to a remote machine over SSH
2019-08-29T17:22:52.0779458Z Version : 0.151.1
2019-08-29T17:22:52.0779522Z Author : Microsoft Corporation
2019-08-29T17:22:52.0779643Z Help : https://docs.microsoft.com/azure/devops/pipelines/tasks/deploy/copy-files-over-ssh
2019-08-29T17:22:52.0779725Z ==============================================================================
2019-08-29T17:22:55.2414134Z ##[debug]agent.workFolder=/home/vsts/work
2019-08-29T17:22:55.2435987Z ##[debug]loading inputs and endpoints
2019-08-29T17:22:55.2445753Z ##[debug]loading INPUT_SSHENDPOINT
2019-08-29T17:22:55.2453350Z ##[debug]loading INPUT_SOURCEFOLDER
2019-08-29T17:22:55.2455679Z ##[debug]loading INPUT_CONTENTS
2019-08-29T17:22:55.2456750Z ##[debug]loading INPUT_TARGETFOLDER
2019-08-29T17:22:55.2458474Z ##[debug]loading INPUT_CLEANTARGETFOLDER
2019-08-29T17:22:55.2459097Z ##[debug]loading INPUT_OVERWRITE
2019-08-29T17:22:55.2461784Z ##[debug]loading INPUT_FAILONEMPTYSOURCE
2019-08-29T17:22:55.2462306Z ##[debug]loading INPUT_FLATTENFOLDERS
2019-08-29T17:22:55.2463432Z ##[debug]loading ENDPOINT_AUTH_30f39122-5901-4920-b479-8d88fc5cbb09
2019-08-29T17:22:55.2464567Z ##[debug]loading ENDPOINT_AUTH_SCHEME_30f39122-5901-4920-b479-8d88fc5cbb09
2019-08-29T17:22:55.2467164Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_30f39122-5901-4920-b479-8d88fc5cbb09_USERNAME
2019-08-29T17:22:55.2468010Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_30f39122-5901-4920-b479-8d88fc5cbb09_PASSWORD
2019-08-29T17:22:55.2468530Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2019-08-29T17:22:55.2469020Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2019-08-29T17:22:55.2475041Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN
2019-08-29T17:22:55.2475692Z ##[debug]loaded 15
2019-08-29T17:22:55.3938099Z ##[debug]check path : /home/vsts/work/_tasks/CopyFilesOverSSH_67cec91b-0351-4c2f-8465-d74b3d2a2d96/0.151.1/task.json
2019-08-29T17:22:55.3938618Z ##[debug]set resource file to: /home/vsts/work/_tasks/CopyFilesOverSSH_67cec91b-0351-4c2f-8465-d74b3d2a2d96/0.151.1/task.json
2019-08-29T17:22:55.3939385Z ##[debug]system.culture=en-US
2019-08-29T17:22:55.3957368Z ##[debug]sshEndpoint=30f39122-5901-4920-b479-8d88fc5cbb09
2019-08-29T17:22:55.3963891Z ##[debug]30f39122-5901-4920-b479-8d88fc5cbb09 auth param username = *
2019-08-29T17:22:55.3964352Z ##[debug]30f39122-5901-4920-b479-8d88fc5cbb09 auth param password =
2019-08-29T17:22:55.3966599Z ##[debug]30f39122-5901-4920-b479-8d88fc5cbb09 data host = linux.reditrice.it
2019-08-29T17:22:55.3966938Z ##[debug]30f39122-5901-4920-b479-8d88fc5cbb09 data port = 22
2019-08-29T17:22:55.3967133Z ##[debug]Using username and password for ssh connection.
2019-08-29T17:22:55.3968418Z ##[debug]contents=.tar
2019-08-29T17:22:55.3970739Z ##[debug]sourceFolder=/home/vsts/work/r1/a
2019-08-29T17:22:55.3971572Z ##[debug]check path : /home/vsts/work/r1/a
2019-08-29T17:22:55.3975458Z ##[debug]targetFolder=//dockerImages
2019-08-29T17:22:55.3975688Z ##[debug]cleanTargetFolder=true
2019-08-29T17:22:55.3975849Z ##[debug]overwrite=true
2019-08-29T17:22:55.3975963Z ##[debug]failOnEmptySource=true
2019-08-29T17:22:55.3976121Z ##[debug]flattenFolders=false
2019-08-29T17:22:55.3997086Z Setting up SSH service connection to remote host linux.reditrice.it.
2019-08-29T17:22:56.4822488Z Cleaning target folder //dockerImages on the remote machine
2019-08-29T17:22:56.4826067Z ##[debug]Options not passed to runCommandOnRemoteMachine, setting defaults.
2019-08-29T17:22:56.4828151Z ##[debug]cmdToRun = rm -rf "//dockerImages"/
2019-08-29T17:22:56.6381492Z ##[debug]code = 0, signal = undefined
2019-08-29T17:22:56.6391364Z ##[debug]include content pattern: .tar
2019-08-29T17:22:56.6393970Z ##[debug]find findPath=/home/vsts/work/r1/a, options=undefined
2019-08-29T17:22:56.6405303Z ##[debug] /home/vsts/work/r1/a
2019-08-29T17:22:56.6405560Z ##[debug] is a directory
2019-08-29T17:22:56.6408437Z ##[debug] /home/vsts/work/r1/a/artifacts_c
2019-08-29T17:22:56.6408670Z ##[debug] is a directory
2019-08-29T17:22:56.6408843Z ##[debug] /home/vsts/work/r1/a/artifacts_c/dockerImage
2019-08-29T17:22:56.6408965Z ##[debug] is a directory
2019-08-29T17:22:56.6415427Z ##[debug] /home/vsts/work/r1/a/artifacts_c/dockerImage/gruppo-r-c-1.1.220.tar
2019-08-29T17:22:56.6415661Z ##[debug] is a file
2019-08-29T17:22:56.6417948Z ##[debug] /home/vsts/work/r1/a/gruppo-r-c-1.1.220.tar
2019-08-29T17:22:56.6418177Z ##[debug] is a file
2019-08-29T17:22:56.6418332Z ##[debug]5 results
2019-08-29T17:22:56.6418498Z ##[debug]counted 2 files in the source tree
2019-08-29T17:22:56.6418671Z ##[debug]Include matching /home/vsts/work/r1/a/.tar
2019-08-29T17:22:56.6418841Z ##[debug]match patterns: /home/vsts/work/r1/a/.tar
2019-08-29T17:22:56.6419054Z ##[debug]match options: [object Object]
2019-08-29T17:22:56.6419181Z ##[debug]applying pattern: /home/vsts/work/r1/a/.tar
2019-08-29T17:22:56.6456036Z ##[debug]matched 1 items
2019-08-29T17:22:56.6457959Z ##[debug]Include matched 1 files
2019-08-29T17:22:56.6458136Z ##[debug]Number of files to copy = 1
2019-08-29T17:22:56.6459999Z ##[debug]filesToCopy = /home/vsts/work/r1/a/gruppo-r-c-1.1.220.tar
2019-08-29T17:22:56.6460101Z Found 1 files to copy to the remote machine.
2019-08-29T17:22:56.6461501Z ##[debug]fileToCopy = /home/vsts/work/r1/a/gruppo-r-c-1.1.220.tar
2019-08-29T17:22:56.6461861Z ##[debug]relativePath = gruppo-r-c-1.1.220.tar
2019-08-29T17:22:56.6462339Z Copying file /home/vsts/work/r1/a/gruppo-r-c-1.1.220.tar to //dockerImages/gruppo-r-c-1.1.220.tar on remote machine.
2019-08-29T17:22:56.6462881Z ##[debug]Upload /home/vsts/work/r1/a/gruppo-r-c-1.1.220.tar to /**/dockerImages/gruppo-r-c-1.1.220.tar on remote machine.
2019-08-29T17:27:52.4568014Z Completed copying 1 files to the remote machine.
2019-08-29T17:27:52.4569552Z ##[debug]Closing the client connection
2019-08-29T17:27:52.4570129Z ##[debug]Failed to close SFTP client.
2019-08-29T17:37:52.1006001Z ##[error]The task has timed out.

As requested i link related issue:
https://github.com/microsoft/azure-pipelines-tasks/issues/7507

[damccorm]

@meriturva are you still seeing this issue? Is it happening consistently or intermittently?

[meriturva]

Task never works.

[damccorm]

@meriturva I'm not able to repro - would you mind sharing your yaml? Do you run into this issue if you only run this task, or does the issue only appear in conjunction with other steps?

[meriturva]

@damccorm here yaml produced by button: View YAML

steps:
- task: CopyFilesOverSSH@0
  displayName: 'Securely copy files to the remote machine'
  inputs:
    sshEndpoint: linux.xxxxx.it
    sourceFolder: '$(System.DefaultWorkingDirectory)'
    contents: '*.tar'
    targetFolder: /root/folderXXX
    cleanTargetFolder: true
    failOnEmptySource: true
  timeoutInMinutes: 15

[damccorm]

@meriturva is this on a Microsoft hosted agent or a self hosted agent?

[meriturva]

@damccorm Microsoft hosted agent

[AlexandrKravchuk]

@meriturva, I've tried to reproduce this issue using Linux Centos 7 based sftp server (created using instructions) and it works well for me.

Based on your logs I can see that the file is actually uploaded but then the process is hanged after sftp connection closing error.
I've tried to simulate the same situation by manually triggering error during sftp close but I was unable to exceed the timeout.

As a way to further investigate this issue I've created a PR to get more information about the error you face.
Please, re-run your pipeline after the PR is merged and deployed. It's going to happen in about 3 weeks. I will remind you closer to the moment.

[AlexandrKravchuk]

Hi @meriturva
The updated version was deployed, please re-run your task pipeline with 'Enable system diagnostics' on and please attach the logs file to the answer! I hope it will help us to fix your problem asap.

[meriturva]

@AlexandrKravchuk Here log file with debug information.
4_Securely copy files to the remote machine.log

[AlexandrKravchuk]

@meriturva For some reason, you still have an old version of the Task. Let me find out why. I'll write you back.

[meriturva]

@AlexandrKravchuk Just to clarify, I'm on a release pipeline.

[leantk]

@meriturva we are still deploying the change out and it most likely hasn't reached your org yet. What is your org name and I can double check when it should get to you?

[meriturva]

@leantk here the name: https://dev.azure.com/gruppo-raffaello/

[leantk]

Thanks @meriturva! Yes, the change has not made it to you yet. Hopefully by tomorrow if all things go according to plan

[leantk]

@meriturva we are still blocked on our current deployment so my apologies, it's taking a few more days to get to you

[AlexandrKravchuk]

@meriturva It seems like we have the changes deployed. I'm sorry about this delay. Could you please run it again and share the logs. Thank you!

[meriturva]

@AlexandrKravchuk here new log file:
4_Securely copy files to the remote machine.log

[AlexandrKravchuk]

@meriturva The problem was fixed in #13084, these changes will be rolled out completely by the end of the current sprint, till 24, July
@anatolybolshakov fyi

[egor-bryzgalov]

Closing this issue since the fix is deployed. Please feel free to reopen the issue.

[meriturva]

I confirm that issue is fixed and my release pipeline is green for the first time!
Thanks!