Dogshell.wrap's buffer_outs option effected by I/O redirection

[ronindesign]

[INVALID] See #201

When using dogwrap console script to send event to datadog servers, including the -b (buffer_outs) option, and using I/O redirection (at least in one case) causes unsuccessful even transmission.

<?php
// tmp/test.php
fwrite(STDERR, 'Testing stderr');
echo 'Testing stdout';

Writing to both stdout,stderr
The following results in successful event transmission, and prints result to console.

dogwrap -n "Unicode Test" -k APIKEY -b --submit_mode all --tags=cron,whmcs,test "php -q tmp/test.php" 2>&1

Adding in null route >/dev/null, results in NO event transmission:

dogwrap -n "Unicode Test" -k APIKEY -b --submit_mode all --tags=cron,whmcs,test "php -q tmp/test.php" >/dev/null 2>&1

Finally, keeping null route and removing -b (buffer_outs), results in successful event transmission without output to console:

dogwrap -n "Unicode Test" -k APIKEY --submit_mode all --tags=cron,whmcs,test "php -q tmp/test.php" >/dev/null 2>&1

Writing only to stdout

The following results in successful event transmission, and prints result to console:

dogwrap -n "Buffer/Redirect Test" -k APIKEY -b --submit_mode all --tags=cron,whmcs,test "php -r 'echo \"Testing\";' 2>&1

Adding in null route >/dev/null, results in successful event transmission:

dogwrap -n "Buffer/Redirect Test" -k APIKEY -b --submit_mode all --tags=cron,whmcs,test "php -r 'echo \"Testing\";' >/dev/null 2>&1

Finally, keeping null route and removing -b (buffer_outs), results in successful event transmission without output to console:

dogwrap -n "Buffer/Redirect Test" -k APIKEY --submit_mode all --tags=cron,whmcs,test "php -r 'echo \"Testing\";' >/dev/null 2>&1

Commenting out the fwrite(STDERR, 'Testing stderr'); results in all three of the original test cases working normally.
Additionally, if either one of the two redirects is removed, the result is success. I.e. both work:

dogwrap -n "Buffer/Redirect Test" -k APIKEY -b --submit_mode all --tags=cron,whmcs,test "php -r 'echo \"Testing\";' 2>&1

dogwrap -n "Buffer/Redirect Test" -k APIKEY -b --submit_mode all --tags=cron,whmcs,test "php -r 'echo \"Testing\";' >/dev/null

This suggests there is an issue with multiple IO redirection, where the final redirection (or last) redirection is /dev/null. Specifically, redirecting to a file instead of /dev/null is successful in all cases above.

According to dogwrap --help:

-b, --buffer_outs     displays the stderr and stdout of the command only
                        once it has returned (the command outputs remains
                        buffered in dogwrap meanwhile)

In datadogpy.dogshell.wrap there is some reference to sys.stderr, sys.stdout:

try:
        proc = subprocess.Popen(u' '.join(cmd), stdout=subprocess.PIPE,
                                stderr=subprocess.PIPE, shell=True)
    except Exception:
        print >> sys.stderr, u"Failed to execute %s" % (repr(cmd))
        raise
    try:
        # Let's that the threads collecting the output from the command in the
        # background
        out_reader = OutputReader(proc.stdout, sys.stdout if not buffer_outs else None)
        err_reader = OutputReader(proc.stderr, sys.stderr if not buffer_outs else None)
        out_reader.start()
        err_reader.start()

        # Let's quietly wait from the program's completion here et get the exit
        # code when it finishes
        returncode = poll_proc(proc, proc_poll_interval, cmd_timeout)

        # Let's harvest the outputs collected by our background threads after
        # making sure they're done reading it.
        out_reader.join()
        err_reader.join()
        stdout = out_reader.content
        stderr = err_reader.content

Maybe some separation of proc.stdout/stderr vs sys.stdout/stderr is needed?
Or maybe try checking if IO redirection is present via sys.stdout.isatty()?
Example, shows IO redirection is checked:

# test.py
import sys;

stderr = ''
stdout = ''
try:
    print >> sys.stderr, stderr.strip()
    print >> sys.stdout, stdout.strip()
    print sys.stdout.isatty();
except:
    print 'ERRORED';

Then testing, we have:

$ python test.py     


True
$ python test.py > tmp.txt

$ cat tmp.txt

False

May be of use:
http://stackoverflow.com/questions/21953835/run-subprocess-and-print-output-to-logging

I'm not familiar enough with python yet to understand fully how it interacts with IO redirection, but I will test to try and find a solution.

[ronindesign]

After doing a little research and testing locally, I think I may have figured out why the event fails to send with multiple IO redirection. Take the example command:
dogwrap -n "Unicode Test" -k APIKEY -b --submit_mode all --tags=cron,whmcs,test "php -q tmp/test.php" >/dev/null 2>&1
This means, stdout is pointing at file descriptor for /dev/null, then stderr is pointing at the same file descriptor, which in itself is just fine / logical, but then issue arises (presumably) around this section of the code:

# datadogpy/dogshell/wrap.py
...
try:
        proc = subprocess.Popen(u' '.join(cmd), stdout=subprocess.PIPE,
                                stderr=subprocess.PIPE, shell=True)
    except Exception:
        print >> sys.stderr, u"Failed to execute %s" % (repr(cmd))
        raise
    try:
        # Let's that the threads collecting the output from the command in the
        # background
        out_reader = OutputReader(proc.stdout, sys.stdout if not buffer_outs else None)
        err_reader = OutputReader(proc.stderr, sys.stderr if not buffer_outs else None)
        out_reader.start()
        err_reader.start()
        
        # Let's quietly wait from the program's completion here et get the exit
        # code when it finishes
        returncode = poll_proc(proc, proc_poll_interval, cmd_timeout)

        # Let's harvest the outputs collected by our background threads after
        # making sure they're done reading it.
        out_reader.join()
        err_reader.join()
        stdout = out_reader.content
        stderr = err_reader.content

So when stdout, stderr are pointing to the same file descriptor, the internal logic in probably chokes when, essentially, calling the same method more than once in a few cases.

To test, I commented out the following lines, and immediately the events began to transmit successfully:

        out_reader = OutputReader(proc.stdout, sys.stdout if not buffer_outs else None)
        err_reader = OutputReader(proc.stderr, sys.stderr if not buffer_outs else None)
        out_reader.start()
        #err_reader.start()  # Removed for testing
        
        # Let's quietly wait from the program's completion here et get the exit
        # code when it finishes
        returncode = poll_proc(proc, proc_poll_interval, cmd_timeout)

        # Let's harvest the outputs collected by our background threads after
        # making sure they're done reading it.
        out_reader.join()
        #err_reader.join()  # Removed for testing
        stdout = out_reader.content
        #stderr = err_reader.content  # Removed for testing

There may be a lower, more accurate fix for this, but without personal knowledge and spending more time digging into where exactly the internal logic faults on duplicate actions, the simplest solution seems to split sys.stdout and sys.stderr into adjacent blocks, adding a check (probably for both) to see if duplicate or matching file descriptor is being used, and then just copy output string from one to the other in final step of logic.