remote_exec: receive stdout and stderr in correct order
ClosedPublic

Authored by kparal on Feb 18 2016, 10:12 AM.

Details

Summary

This fixes stdout+stderr ordering when receiving output from a minion.
Before this patch, stdout and stderr were not printed out in their
chronological order, now they are. The downside is that we're no longer
able to handle the streams separately, so we can't e.g. save all stderr
output to a separate file. If we ever needed that, we would need to
reconsider this approach (and probably had to sacrifice chronological
ordering).

The receive buffer was increased for better performance.

Some details:
Here is a real-world example of the issue:

============================================================
holland-1.0.12-1.fc22 into f22-updates
========================[upgradepath:upgradepath.py:438] 2016-02-18 09:47:17 DEBUG   Checking: nspr-4.11.0-1.fc22
====================================

or

============================================================
nsp[upgradepath:upgradepath.py:438] 2016-02-18 09:47:17 DEBUG   Checking: nss-3.22.0-1.0.fc22
[upgradepath:upgradepath.py:438] 2016-02-18 09:47:18 DEBUG   Checking: nss-softokn-3.22.0-1.0.fc22
[upgradepath:upgradepath.py:438] 2016-02-18 09:47:18 DEBUG   Checking: nss-util-3.22.0-1.0.fc22
[upgradepath:upgradepath.py:438] 2016-02-18 09:47:19 DEBUG   Checking: oidentd-2.0.8-16.fc22
[upgradepath:upgradepath.py:438] 2016-02-18 09:47:20 DEBUG   Checking: poco-1.4.2p1-3.fc22
[upgradepath:upgradepath.py:438] 2016-02-18 09:47:21 DEBUG   Checking: pylast-1.5.1-1.fc22
r-4.11.0-1.fc22 into f22-updates
============================================================

https://taskotron-dev.fedoraproject.org/taskmaster/builders/x86_64/builds/136135/steps/runtask/logs/stdio
(I picked those where you can easily see it, but in worse cases it's
just a mess of characters and you have a tough time figuring which
stream is which).

This also makes debugging harder, when the debug log line is 50 lines
above or below the place where it should be.

I found the solution on stackoverflow here:
http://stackoverflow.com/a/8045735

There are other solutions available, like running the command with
"2>&1":
https://www.mail-archive.com/paramiko@lag.net/msg00270.html
However, I wanted something a bit more universal, and PTY solves that.

Paramiko also has "channel.set_combine_stderr(True)" method (see the
same thread), but according to my testing it is not good enough - it
slightly improves the state, but not much.

In paramiko documentation, they say this about get_pty():

It isn’t necessary (or desirable) to call this method if you’re
going to exectue a single command with exec_command.

http://docs.paramiko.org/en/1.16/api/channel.html#paramiko.channel.Channel.get_pty
I haven't found any reason for this claim, I suppose it has a slightly
higher set up overhead. I have verified that our file copy operations
are not affected by this (this only affects execution of a command), and
our task execution doesn't seem to be any slower either.

Test Plan

To test this, edit minion.py and replace this line:

self.exitcode = self.ssh.cmd(' '.join(task_cmd))

with this line:

self.exitcode = self.ssh.cmd('for i in {1..10}; do echo $i; echo "    $i" >&2; done')

Without the patch, the output looks like this:

1
2
3
4
5
6
7
8
9
10
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10

With the patch, it looks like this:

1
    1
2
    2
3
    3
4
    4
5
    5
6
    6
7
    7
8
    8
9
    9
10
    10

Diff Detail

Repository
rLTRN libtaskotron
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.
kparal retitled this revision from to remote_exec: receive stdout and stderr in correct order.Feb 18 2016, 10:12 AM
kparal updated this object.
kparal edited the test plan for this revision. (Show Details)
kparal added a reviewer: libtaskotron.
mkrizek accepted this revision.Feb 18 2016, 1:00 PM
mkrizek added a reviewer: mkrizek.
mkrizek added a subscriber: mkrizek.

LGTM

This revision is now accepted and ready to land.Feb 18 2016, 1:00 PM
This revision was automatically updated to reflect the committed changes.