Unable to redirect output from the "ml" script using stanard methods

[danielritchie]

Overview of the Issue

• Executing the script as a user at the terminal works as expected. However, exception output is not captured when executed programmatically.
• We discovered this issue when using Jenkins CI, as the same text which is not being redirected is also not showing up in Jenkin's console (unsure if for the same reason, but seems likely)
• We could figure out a way to redirect the output, but making the proposed changes seems a more complete solution

Example:

# ./ml bootstrap
ERROR: Missing environment for bootstrap
Usage: ml {env} bootstrap [options]

General options:
 -v, [--verbose]  # Verbose output

Bootstraps your application to the MarkLogic server in the given
environment.

--- VS: ---

# ./ml bootstrap > output.log 
# ls -s output.log
0 output.log

NOTES:

• No luck with different redirects/tee/etc.
• Setting verbose flag had no effect
• Interestingly, the -h flag does return the output (discussed in more detail under "Suggest a Fix") - UPDATE - Help works because it returns using "exit" instead of "exit!"

# ./ml bootstrap -h > output.log
# cat output.log
Usage: ml {env} bootstrap [options]

General options:
  -v, [--verbose]  # Verbose output

Bootstraps your application to the MarkLogic server in the given
environment.

Motivation for or Use Case

• When "ml" is executed programmatically output cannot be captured. This prevents things like automating deployments and implementing CI. It also means troubleshooting roxy has become my least favorite thing to do
• Full disclosure: I'm not familiar enough with roxy/ruby to be certain that I'm not overlooking a known setting that would enable the output to be captured...but haven't had any luck finding anything

Roxy Version

• 1.7.3-dev
• Also confirmed on 1.7.2

Ruby Version

• 1.9.3
• Also confirmed on 1.8.7

Operating System

• Centos 6.5

Suggest a Fix

UPDATE 2:

Pull Request: #546

UPDATE 1:

• The issue appears to be with the "exit!" statement at line 187 in deploy/lib/ml.rb
• While this does result in the expected return code of 1 (as I'm sure is intended), it also seems to have an unintended side effect of wiping out the messaging.
• Commenting out the "exit!" @ line 187 allows the redirect to be captured (I haven't tested with Jenkins yet), but introduces a new problem of returning 0.
• I don't know Ruby well enough to understand why this happens, but would guess there's some other shutdown procedure that is executed without the hard exit? Hopefully someone who knows this better can save me from crawling through the exit process, but I'll keep plugging away to try to understand what's happening :)

ORIGINAL TEXT:

• When using the -h flag output can be captured (and ./ml with a bogus argument also works)
  UPDATE: Help behaves as expected because it returns using "exit" instead of "exit!"
• All of the action seems to be happening in deploy/lib/ml.rb
  • Help results in output that can be redirected:
    • Help.doHelp(@logger, command)
    • Help.doHelp(@logger, :usage, "Unknown command #{command}!")
  • Problematic output occurs when an Exception is raised:
    • raise HelpException.new(command, "Missing environment for #{command}") if @properties["environment"].nil?

[danielritchie]

"Suggest a Fix" Update 1 - 2015/10/29 @ 18:20
There seems to be a problem with the way the code is exiting

[danielritchie]

"Suggest a Fix" Update 2:
Submitted Pull Request: #546

UPDATED to reference corrected PR submitted to dev branch

[dmcassel]

Interesting. When I do ml bootstrap > output on my Mac, I get the output dumped; I'm confident I'd seen errors in Jenkins logs as well. All the same, returning error codes is a reasonable thing to do and would help debugging.

@paxtonhare any reason to think this would be a problem?

[rlouapre]

Jenkins does not directly invoke Roxy commands. It invokes a bash script which invokes Roxy command:

#!/bin/bash
set -e
SCRIPT_PATH=$0
...
echo "Bootstrap = ${ROXY-OPTIONS}"
./ml ${ML_ENVIRONMENT} bootstrap ${ROXY_OPTIONS}

The same behavior can be reproduced in Windows / Cygwin.
PR provided by @danielritchie address the issue.

[danielritchie]

@dmcassel it is very strange. Our guess was that STDERR/STDOUT from the logger is dumped in a different way during a typical SystemExit, but the hard exit bypassed that dump. That still didn't explain why we couldn't capture it using a few different methods even though it appears to be returned (in any case the goal was not to capture the output but to see it in Jenkins).

Re: ./ml bootstrap > output we can capture output if successful. Even some failures will be returned. Aside from possible differences between the platforms we only saw the issue if an exception is thrown which specifically hits "exit!"

[danielritchie]

@paxtonhare As best I can tell this should be completely transparent as I didn't see anything else referencing specific return codes from ml.rb. The only potential concern we could speculate about was if you're handling normal exit behavior in some abstract way...which I'm guessing is not likely.

It is specifically SystemExit which is being bypassed. See: exit vs. exit!

[paxtonhare]

Thanks for digging in to this.

On Saturday, October 31, 2015, danielritchie notifications@github.com
wrote:

Have confirmed that the output is returned as expected when executing from
Jenkins as well

—
Reply to this email directly or view it on GitHub
#543 (comment).

[dmcassel]

Just to check -- have you tried directing stderr to your output file as well?

[danielritchie]

Yes, and we did find ways where we were able to redirect it.

There is another complication which @rlouapre also mentioned: Jenkins executes this VIA a script and is not capturing the output. Although this shouldn't make a difference, we have an additional need for this to show up in Jenkins' console (which typically captures stderr and stdout without any special handling).

I came across this article which explains that exit! is considered to be the dangerous version of exit. I thought there may be merit for the big hammer (bypassing SystemExit/at_exit/ensure/rescue/etc.), but I could not determine that there would be any functional change in behavior between the use of "exit!" and "exit 1".

As a result replacing the "exit!" calls with "exit" appeared to be the most straightforward way of addressing our issue. This also resolved all unexplained behavior. A bonus was that any impact appears to be positive (who doesn't like deterministic error codes?).

FWIW, I did find in the Ruby Language Reference Manual that exit! is "used to terminate sub-processes after calling fork". Past this I had difficulty finding instances where the use of "exit!" was favored over "exit"

We appreciate you guys taking the time to take a look at this. Thanks for making roxy available!

[dmcassel]

I accepted the PR onto the dev branch.