[SERVER-1671] generate() stdout is written to puppetserver.log Created: 2016/11/29  Updated: 2017/08/28  Resolved: 2017/01/17

Status: Closed
Project: Puppet Server
Component/s: Puppet Server
Affects Version/s: SERVER 2.7.1
Fix Version/s: SERVER 2.8.0, SERVER 5.0.0

Type: Bug Priority: Normal
Reporter: Matthias Hörmann Assignee: Jeremy Barlow
Resolution: Fixed Votes: 0
Labels: maintenance
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by SERVER-1698 Function generate() logs output to pu... Resolved
Relates
relates to SERVER-1571 The function generate() should merge ... Resolved
Template:
Team: Systems Engineering
Story Points: 2
Sprint: SE 2017-01-11, SE 2017-01-25
Release Notes: Bug Fix
Release Notes Summary: SERVER-1571 updated the generate() function to merge stdout and stderr and return the combined value, but this change had an unintended side effect of logging both stdout and stderr to the puppetserver log file. This has been fixed to preserve the behavior of returning both stderr and stdout from the generate() function call but only logging stderr to puppetserver.log. If a command invoked through generate() does not write to stderr then no log will be generated.
QA Risk Assessment: Needs Assessment

 Description   

It seems recent versions of Puppetserver log all stdout and stderr output in lines with

 [c.p.p.ShellUtils] Executed an external process which logged to STDERR:

instead of just doing so for generate() calls that actually produce output on stderr.

My guess would be that this is related to SERVER-1571 where stdout and stderr seem to be merged now in generate calls (not quite sure what the use case is for having error messages or warnings mixed into your output).



 Comments   
Comment by Jeremy Barlow [ 2016/11/29 ]

It does sound like this would be a consequence of the work done in SERVER-1571. The code that launches the process uses the same stream object for both stdout and stderr. There is a conditional which attempts to only output data to the log if data was sent through stderr. Because the streams have been combined together, though, data sent either to stdout or stderr would cause the message to be logged.

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 SERVER-1571 but figure out a way to only log the warn message when data is written to stderr specifically (not just stdout or stderr).

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 presume we've confirmed that in the old stack (webrick/passenger) that this warning is not logged?

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:

  • The versioned-code-service - used for computing code-ids and getting code content as part of the static catalogs feature.
  • Custom policy executables for autosigning in the Certificate Authority service
  • Any Ruby Puppet extension which uses the Puppet::Util::Execution module - including the generate() parser function mentioned in this ticket.

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 SERVER-1571 was done. I still see utility for troubleshooting in having stderr from spawned commands be logged at "warn" level although some may argue that even having stderr data written the log might pose a security risk in some scenarios (depending upon what data is being written). It would possible to control whether or not the logging is done even for stderr by introducing a new configuration option in Puppet Server but it's not clear to me that that would be necessary.

Eric Sorenson, Josh Cooper - would appreciate your thoughts on the stderr logging question.

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:

<configuration scan="true">
  ...
  <logger name="org.apache.http" level="INFO"/>
  <logger name="com.puppetlabs.puppetserver.ShellUtils" level="ERROR"/>
 
  <root level="info">
 
  ...
</configuration>

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 SERVER-1571 where stdout and stderr produced by the executable spawned by generate is still merged together but that only data written to stderr (and not data written to stdout) would be logged in the puppetserver log file. In the event that no data is written to stderr, no extra log message is written for the generate command.

Generated at Mon Sep 23 06:02:17 PDT 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.