[SERVER-1671] generate() stdout is written to puppetserver.log Created: 2016/11/29 Updated: 2017/08/28 Resolved: 2017/01/17
|Affects Version/s:||SERVER 2.7.1|
|Fix Version/s:||SERVER 2.8.0, SERVER 5.0.0|
|Reporter:||Matthias Hörmann||Assignee:||Jeremy Barlow|
|Remaining Estimate:||Not Specified|
|Time Spent:||Not Specified|
|Original Estimate:||Not Specified|
|Sprint:||SE 2017-01-11, SE 2017-01-25|
|Release Notes:||Bug Fix|
|Release Notes Summary:||
|QA Risk Assessment:||Needs Assessment|
It seems recent versions of Puppetserver log all stdout and stderr output in lines with
instead of just doing so for generate() calls that actually produce output on stderr.
My guess would be that this is related to
|Comment by Jeremy Barlow [ 2016/11/29 ]|
It does sound like this would be a consequence of the work done in
The problem would only happen in the case that the caller from Ruby code were using the Puppet::Util::Execution class and either not setting the :combine option - which specifies whether the stream output should be combined or not - or setting it to true. The code for the generate() function doesn't set the :combine option and so it gets the default behavior of having the streams combined.
I honestly don't know why the default behavior of the generate() function is to combine data from both streams but this has been the behavior for multiple major releases now, so it seems that we should continue with that. If it is desirable to have more control over that, might be worth filing a separate enhancement request to make this configurable with a future version of the generate() function.
Not sure exactly what the best way forward on this ticket is. For cases where streams are not being combined, I think the logic to log the content from stderr when not empty still makes sense. Seems like we should do something different for the cases where streams are being combined, though - like for the generate() function. Some options:
1) Just change the log message to indicate that content could come from either stream, e.g., "Executed an external process which logged to STDOUT and/or STDERR".
This would be simple to do but would still have the disadvantage of having a message logged when data went to stdout and not stderr, which may not be desirable.
2) Same as 1 but maybe drop the log level from "warn" to "debug".
Having the log level at "debug" could reduce the frequency at which the messages are written. Having to bump the log level up in the case that silent errors are happening might be inconvenient though.
3) Only log the message at warn level if the exit code is non-zero, else log at debug level.
This might reduce the frequency at which messages are logged - assuming many of the 'normal' cases involve a command returning a success (0) exit code and only data from stdout. This would miss any data being written to stderr in any cases which fall outside of these though, so this might not be a good option either.
4) Continue combining stream output when the :combine option is set like was done as a result of the work in
This seems like the most ideal option but would probably be the most complex to implement as well. Maybe we could do that by layering the stream that we pass as the stderr stream with a custom object that just sets a flag that we can query back onto to see if any data was written through that custom object on down to the combined stderr/stdout stream it is wrapping?
I'd probably opt for looking into option 4 but fall back to one of the simpler options like 1 or 2 as a shorter-term fix if that starts to look too involved.
Chris Price - WDYT about this one?
|Comment by Matthias Hörmann [ 2016/11/30 ]|
I made another ticket for a feature suggestion for Puppet to optionally fail (if a new flag is set or in a new variant of generate()) if there is any output in stderr ( https://tickets.puppetlabs.com/browse/PUP-6949 ). This would be easy to implement if you went with option 4 as well and would make some use cases of generate() more reliable (those where something will break when encountering the stderr output in e.g. a generated config file).
|Comment by Chris Price [ 2016/12/06 ]|
Jeremy Barlow your assessment seems accurate. I presume we've confirmed that in the old stack (webrick/passenger) that this warning is not logged?
On the surface, option 4 sounds doable, and I agree it'd be the best thing to look into. Might also take a peek at the old ruby execution code and see how it was handling this.
|Comment by Jeremy Barlow [ 2016/12/21 ]|
I ran a test with the generate() function on a WEBrick master running Puppet 4.8.1. Neither stdout nor stderr produced by the script that the generate() function executed was written into the log. To be backward compatible with the webrick/passenger stack, then, it would seem that we could just avoid writing stderr to the log at all. If we were to make that change in the ShellUtils code, however, this would affect pretty much every case in which Puppet Server might spawn an executable, including:
I definitely agree with the description in this ticket that we should avoid having Puppet Server log any stdout from spawned executables, as was the case before
|Comment by Jeremy Barlow [ 2016/12/22 ]|
To suppress these messages from the log in the interim, one could add a line to the /etc/puppetlabs/puppetserver/logback.xml file which turns logging off for messages in the ShellUtils namespace:
This would ensure that only ERROR-level messages from the ShellUtils namespace - not including the WARN-level at which the shell output is logged - end up in the log. Note that this workaround would suppress both STDOUT and STDERR that the spawned process may produce so this may not be desirable for those who still want to see the STDERR output appear in the log.
|Comment by Jeremy Barlow [ 2017/01/17 ]|
Merged to master at ad0c56. Pipeline is still green so I'm going to mark this resolved.
|Comment by Jeremy Barlow [ 2017/01/17 ]|
For posterity, the change we went with for this ticket was to preserve the work from