[BUG]: SSH@0 seems to add extra new line for some or each command

avishnyakov commented 1 month 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

SSH@0

Task version

0.245.1

Issue Description

SSH tasks seems to add new lines for some or each command. This is not seen in Bash@3 task.

Example and how to replicate:


      - task: SSH@0
        displayName: "ssh bash"
        inputs:
          sshEndpoint: XXXX
          failOnStdErr: true
          readyTimeout: '80000'
          runOptions: inline
          inline: |
            echo '[1] workspace: check space'

            cd /tmp

            export build_agent_path_size="$(df -k /tmp | awk '{print $4}'|sed 's/\%//')"

            echo "[2] Build Agent Folder Size: $build_agent_path_size"

            if [ "$build_agent_path_size" -gt 95 ]; then
              echo "No enough space. "
              exit 1 
            fi

            echo "[3] line 3"
            rm -rf test.log   

            echo "[4] line 4" 
            rm -rf test.log   

            echo "[5] line 5" 

      - task:  Bash@3 
        displayName: "normal bash"
        inputs:  
          targetType: inline
          script: |
            echo '[1] workspace: check space'

            cd /tmp

            build_agent_path_size=1

            echo "[2] Build Agent Folder Size: $build_agent_path_size"

            if [ "$build_agent_path_size" -gt 95 ]; then
              echo "No enough space. "
              exit 1 
            fi

            echo "[3] line 3" 
            rm -rf test.log   

            echo "[4] line 4"
            rm -rf test.log   

            echo "[5] line 5"

Output

# ssh bash task

Successfully connected.
chmod +x ./sshscript_389faa83-a2ef-4ce1-90c8-683331a221da
./sshscript_389faa83-a2ef-4ce1-90c8-683331a221da
[1] workspace: check space

[2] Build Agent Folder Size: 59
[3] line 3

[4] line 4

[5] line 5

# normal bash task
========================== Starting Command Output ===========================
/usr/bin/bash /agent/_work/_temp/dcc43442-6b7e-4bb6-956b-233f8756e976.sh
[1] workspace: check space
[2] Build Agent Folder Size: 1
[3] line 3
[4] line 4
[5] line 5

Above example in screenshot

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

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

Azure DevOps Server type

dev.azure.com (formerly visualstudio.com)

Azure DevOps Server Version (if applicable)

No response

Operation system

n/a

Relevant log output

n/a

Full task logs with system.debug enabled

n/a

Repro steps

- task: SSH@0
        displayName: "ssh bash"
        inputs:
          sshEndpoint: XXXX
          failOnStdErr: true
          readyTimeout: '80000'
          runOptions: inline
          inline: |
            echo '[1] workspace: check space'

            cd /tmp

            export build_agent_path_size="$(df -k /tmp | awk '{print $4}'|sed 's/\%//')"

            echo "[2] Build Agent Folder Size: $build_agent_path_size"

            if [ "$build_agent_path_size" -gt 95 ]; then
              echo "No enough space. "
              exit 1 
            fi

            echo "[3] line 3"
            rm -rf test.log   

            echo "[4] line 4" 
            rm -rf test.log   

            echo "[5] line 5" 

      - task:  Bash@3 
        displayName: "normal bash"
        inputs:  
          targetType: inline
          script: |
            echo '[1] workspace: check space'

            cd /tmp

            build_agent_path_size=1

            echo "[2] Build Agent Folder Size: $build_agent_path_size"

            if [ "$build_agent_path_size" -gt 95 ]; then
              echo "No enough space. "
              exit 1 
            fi

            echo "[3] line 3" 
            rm -rf test.log   

            echo "[4] line 4"
            rm -rf test.log   

            echo "[5] line 5"

ivanduplenskikh commented 1 month ago

@avishnyakov, thanks for the heads-up. It seems there could be an issue with the ssh task's output during printing. I'll explore this issue and get back to you.

avishnyakov commented 1 month ago

Sounds good.

The above mystery with ssh task output happens with IBM AIX box + default Korn shell inside. Been trying various options, playing with env variables, term, shell, etc - still same line breaks in output.

In some cases, we also have single line broken into 2-3 smaller lines. This happens randomly, can't see any pattern yet. Replicated only line breaks with above, so raised this ticket.

Don't have other ssh boxes handy to try, unfortunately. Still unclear what could be be - feeling is that it could be ssh agent config, locale, terminal, shell, shell/tty, encoding, something else or, as you said, task handling output during printing.

ivanduplenskikh commented 1 month ago

@avishnyakov, thank you for your example. I was able to reproduce the issue on my own configuration.

The output to console is generated from a stream that is translated from the ssh2 libary

When I added an additional log here

const wrapper = (err, stream) => {
  stream.on('data', (data) => console.log('[DEBUG] output from ssh2 module', Buffer.from(data)));
  cb(err, stream);
};

I got the following output:

2024-09-26T10:48:41.5461801Z echo "[3] line 3"
2024-09-26T10:48:41.6073966Z [DEBUG] output from ssh2 module <Buffer 22 5b 33 5d 20 6c 69 6e 65 20 33 22 0d 0a>
2024-09-26T10:48:41.6074677Z "[3] line 3"
2024-09-26T10:48:41.6074677Z
2024-09-26T10:48:41.6090183Z echo "[4] line 4"
2024-09-26T10:48:41.6705977Z [DEBUG] output from ssh2 module <Buffer 22 5b 34 5d 20 6c 69 6e 65 20 34 22 0d 0a>
2024-09-26T10:48:41.6707288Z "[4] line 4"
2024-09-26T10:48:41.6707288Z
2024-09-26T10:48:41.6719912Z echo "[5] line 5"
2024-09-26T10:48:41.7328125Z [DEBUG] output from ssh2 module <Buffer 22 5b 35 5d 20 6c 69 6e 65 20 35 22 0d 0a>
2024-09-26T10:48:41.7328693Z "[5] line 5"
2024-09-26T10:48:41.7328693Z

The final characters are 0d and 0a, where 0d represents CR the carriage return control code and 0d represents LF the line feed control code, which implies newlines in output.

This issue isn't directly connected to the SSH task, but rather to the SSH2 module.

avishnyakov commented 1 month ago

Right, interesting mystery.

I see this post surfacing exact same random line breaks in ssh0 task which we see. Pretty random, hard to reproduce.

https://stackoverflow.com/questions/58293147/nodejs-ssh2-module-data-returned-in-inconsistent-format

testing with this approach now, will share outcomes.

    steps:

      # https://learn.microsoft.com/en-us/azure/devops/pipelines/tasks/reference/ssh-v0?view=azure-pipelines
      - task: SSH@0
        displayName: "ssh bash"
        inputs:
          sshEndpoint: XXXXX
          failOnStdErr: true
          readyTimeout: '80000'
          runOptions: inline
          interpreterCommand: '/bin/ksh' 
          inline: |
            #!/bin/ksh

            # ksh 
            # > https://www.cyberciti.biz/faq/unix-for-loop-1-to-10/

            foreach_length=${{ parameters.foreach_length }}
            random_value_length=${{ parameters.random_value_length }}

            echo '[+] tracing'
            echo " foreach_length     : $foreach_length"
            echo " random_value_length: $random_value_length"

            i=1
            while [[ $i -lt foreach_length ]] ; do

              random_value="$(cat /dev/urandom | base64 -w 0  | head -c $random_value_length)"
              echo "[$i/$foreach_length] - value length: $random_value_length with value: $random_value"

              (( i += 1 ))
            done

            echo '[+] done'

      - task:  Bash@3 
        displayName: "normal bash"
        inputs:  
          targetType: inline
          script: |
            #!/bin/bash 

            foreach_length=${{ parameters.foreach_length }}
            random_value_length=${{ parameters.random_value_length }}

            echo '[+] tracing'
            echo " foreach_length     : $foreach_length"
            echo " random_value_length: $random_value_length"

            # POSIX syntax
            # > https://www.cyberciti.biz/faq/unix-for-loop-1-to-10/
            i=0
            while [ $i -ne $foreach_length ]
            do
              random_value="$(cat /dev/urandom | base64 -w 0  | head -c $random_value_length)"
              echo "[$i/$foreach_length] - value length: $random_value_length with value: $random_value" &

              i=$(($i+1))
            done

            echo '[+] done'

SSH task

line breaks after each echo

cant replicate random line breaks yet


[+] tracing
foreach_length     : 256
random_value_length: 256

[1/256] - value length: 256 with value: jahWeHeg13iX63FMEYEjqtohVJN9BCcZ5dHn+MIHzfmdVEkLGprkRwcrSNXcW9993mCJ/WOofyQSNnLyi/stRhh6n3MZf3wG5LL3cV1oyG8m2p1EKhpxwRU5NpjQINrurpdnIYuh5jx3D4PSllsgzn3A+gnFS+odmy2yfxypN2ytrBBqQ4RfhlZhyiS4/oZSCO90cOlnVDNs6maatmLUZCNpCnrT/FeSrVRjJprIJaU/6jYKULj6XqEg6RVrCg+L

[2/256] - value length: 256 with value: tVp3pIwFv9hyGCZmQG2s29GgDi0QKP2k2sh7WDniKPNM2tLQRoyltQ5Yc/VW6cBPIrWlAgVrJZt/p8ovyStvhXS+brTplc2ju0sd2GtN7zbGIMsfkcyT+k2oBGH+aLbvWLYm060VgHJfHjjTPulKhupjolR8JO8CrYVSPpyicbVPmiWGuvi9i2FCALO3Rm5romlEgyj1qOYul2Uf5RC6Q5jKxO1BYpEXWtj3ZYkY2SEG63qy1smGU0lSoamw5LxH

[3/256] - value length: 256 with value: YYWP7BpBpJYPaWYBUsjv/BVqTzIGLqme6I4JcKQaW82Ft9cyxSVJDxMRMoT1CwgbspNLTO1j3jy1GR9uRKwZMnEZpzFOZ1uif5uiWmKqbPORjo7uqeANxVqyfGmiTcwK3qCoTHOnJsjG/SSPlfjJuS47uVOmqhEh2VIkqHeD7oYJvAX9aRakt/30BxmvDsBS+mgqKexUtw0VYNM5xc4akkneyNYPn+8LS7keVHW6Rj31fbH1SjiYfB06mTn2DEL7

[4/256] - value length: 256 with value: kME75HUTAc1io8jGKhqux0m97hdu+MpTEpVfemZgu2BPmChfLdiY6URg9cBhHPmhmO6Vu4O0lags6qCU3JdPd18EOl0iYqNFREUV9yxBHT1gXIasVkUimAFfOq8GlgvV0FukD2P5lYhdk3uWkysiQ8DmhY76asbQcf0AinL+6isz5QG0rOv7NoGri5NVHWq3WkRHSDjGVoUQptb4rc+PXYHEfrTwr92MIAPXxx2heWwDPT4du8FIR4M8NPLIZXOR


bash task
* no line breaks after echo
* all looks good

[+] tracing foreach_length : 256 random_value_length: 256 [0/256] - value length: 256 with value: 1VuwSgk2aVQOEbu1pyLB7Mysj5PHRP8JzEn32ENP2ZhFXkPAF2DWWgYJhsUHHa7m409xa74ujMkqqh+OBdCEXAS20hhPLSVwZcRZOG2xCiVpTUnrYdYNhssXEhGVAzxkEg1/NPIh2+5AC6hosViX76Ctor/mHPdI6hz+FkfyvEZb9Mx3+0QVAS81FX6/O4ADgfMR+Ythd/6oR9QlNReHk/jdWwjVJ8EBbmSU4iquplScvbtTUcU6LbyBsyfWC0rK [1/256] - value length: 256 with value: r1RraIwjYVyQ/pMbfdnUhd3n9j3hr3oxRZWL5vHmzbZLoIDqsI+RaFTpBskpoXJuhHI7HGqNjzj9vJNpcaxOBX/dBz+AsJRef2YClvXb6kMywWAygdDZGj6TclnggZp0P/rRvxYu0S4goZU/RdBWjDUI5CX6F05WGVy8ju4yhleRTxHi+BISYjpWS0U2OxqFf8yaK0WTmd05iUHHghMUhcqjNQDfyybf/OQoaPRoJFxt+MqsYgEKKkV/1lqaqBJE [2/256] - value length: 256 with value: m2/fIoZm0XTM4KVAxgSult8vEnFThfAa2+QVH7ylvUJiglG8fBMR/1Go73HWs8HxUPEsCVcdNG6gzXPJk2IV9cNB4mpSMTmwoQO5XRamvSnlWZvA28S/QFkaYtz3Ijf7PRzBbtVi4D2dm73XbCAqHdV03xWoonKx035mpil+f6xQDgeY41UnJLG+vGAlg9G//no/tg6zy9rulhty6cvU+j97+sdctwvLp4ka8EToauYg6HCC0TQFPdXclEmV6QEt

ivanduplenskikh commented 1 month ago

@avishnyakov, it appears that the issue is indeed related to the SSH module. I recommend submitting a ticket in the ssh2 module repository to ensure the right team looks into this issue.

ivanduplenskikh commented 1 month ago

I've submitted a pull request #20507 as a temporary fix for the SshV0 task, which includes trimming the task output.

Additionally, I've opened an issue in the ssh2 module to discuss whether this behavior is expected and explore potential solutions.

You can find the issue here: https://github.com/mscdex/ssh2/issues/1425

ivanduplenskikh commented 1 month ago

@avishnyakov, following our discussion with the ssh2 module's team, it has been clarified that the behavior observed with the echo command is standard.

To illustrate, here's an example demonstrating that the output from Nodejs also includes a trailing newline.

console.log(require("child_process").execSync('echo "Debug output"').toString('utf-8'));
// "Debug output"
//

To handle this behavior on Windows you can use

echo|set /p="Debug output"

On Ubuntu

echo -n "Debug output"

I'm closing the related pull request with a temporary solution and closing this issue for now. Feel free to reopen it if you need further clarification or have questions regarding this matter.

avishnyakov commented 1 month ago

Right, unsure why this is closed with assumption that echo -n will solve all the issues.

Can we agree on expectation that same bash script should produce same output under both (1) BASH and (2) SSH tasks? I think this is important definition of success here.

So first of all, let's consider same bash script which is run (1) under Bash task and (2) under SSH task - the output id different, and suggestion is to use echo for Bash taks and echo -n for SSH task? - that sounds just wrong.

Next, assumptions that (1) this is ONLY echo command problem and (2) echo -n fixed all problem is wrong.

We have same line breaks coming from SSH@0 task for other cases: • running cd or some other command – look like sub-shell evaluation creates new line breaks • running maven, ant, and other binaries and tooling – their output also comes with extra-line breaks (how do we control echo -n for these?)

Based on above data points, appears that we have more mystery to uncover.

ivanduplenskikh commented 1 month ago

@avishnyakov, I've reopened the pull request #20507.

Now, the output will be redirected to process.stdout in chunks, avoiding the use of console.log which adds newlines, as it mentioned in the documentation

avishnyakov commented 1 month ago

This is cool. Can't wait to test this work 🚀

ivanduplenskikh commented 4 weeks ago

@avishnyakov, we have deployed a new version of the task. Could you kindly verify the output in your pipeline by enabling the environment variable DistributedTask.Tasks.redirectTaskOutputToProcessStdout to true. This temporary adjustment is necessary to ensure the issue has been successfully addressed.

For example:

variables:
  DistributedTask.Tasks.redirectTaskOutputToProcessStdout: true

avishnyakov commented 3 weeks ago

Run a few quick tests, looks promising. This is awesome outcome, thanks for patience and considering our feedback.

No change - same behavior, line drops and breaks.

Added variable - SSH output looks great, no added line breaks. Need to test on a few more pipelines - will come back on Monday.

variables:
  DistributedTask.Tasks.redirectTaskOutputToProcessStdout: true

microsoft / azure-pipelines-tasks