Feature: combine_output to control stdout/stderr

This enables an often-requested feature to separate stderr
from stdout within function responses. New flag combine_output is on
by default to match existing behaviour. When combine_output is set
to false it redirects stderr to the container logs rather than
combining it into the function response.

Tested with unit tests for default behaviour and new behaviour.

Signed-off-by: Alex Ellis (VMware) <alexellis2@gmail.com>

watchdog/README.md

@@ -71,16 +71,16 @@ The watchdog can be configured through environmental variables. You must always
 
 | Option                 | Usage             |
 |------------------------|--------------|
-| `fprocess`             | The process to invoke for each function call (function process). This must be a UNIX binary and accept input via STDIN and output via STDOUT.  |
-| `cgi_headers`          | HTTP headers from request are made available through environmental variables - `Http_X_Served_By` etc. See section: *Handling headers* for more detail. Enabled by default. |
+| `fprocess`             | The process to invoke for each function call (function process). This must be a UNIX binary and accept input via STDIN and output via STDOUT  |
+| `cgi_headers`          | HTTP headers from request are made available through environmental variables - `Http_X_Served_By` etc. See section: *Handling headers* for more detail. Enabled by default |
 | `marshal_request`     | Instead of re-directing the raw HTTP body into your fprocess, it will first be marshalled into JSON. Use this if you need to work with HTTP headers and do not want to use environmental variables via the `cgi_headers` flag. |
-| `content_type`         | Force a specific Content-Type response for all responses. |
+| `content_type`         | Force a specific Content-Type response for all responses |
 | `write_timeout`        | HTTP timeout for writing a response body from your function (in seconds)  |
 | `read_timeout`         | HTTP timeout for reading the payload from the client caller (in seconds) |
 | `suppress_lock`        | The watchdog will attempt to write a lockfile to /tmp/ for swarm healthchecks - set this to true to disable behaviour. |
-| `exec_timeout`         | Hard timeout for process exec'd for each incoming request (in seconds). Disabled if set to 0. |
-| `write_debug`          | Write all output, error messages, and additional information to the logs. Default is false. |
- 
+| `exec_timeout`         | Hard timeout for process exec'd for each incoming request (in seconds). Disabled if set to 0 |
+| `write_debug`          | Write all output, error messages, and additional information to the logs. Default is false |
+| `combine_output`       | True by default - combines stdout/stderr in function response, when set to false `stderr` is written to the container logs and stdout is used for function response |
 
 ## Advanced / tuning
 

watchdog/main.go

@@ -133,11 +133,27 @@ func pipeRequest(config *WatchdogConfig, w http.ResponseWriter, r *http.Request,
 		writer.Close()
 	}()
 
+	if config.combineOutput {
 		// Read the output from stdout/stderr and combine into one variable for output.
 		go func() {
 			defer wg.Done()
+
 			out, err = targetCmd.CombinedOutput()
 		}()
+	} else {
+		go func() {
+			var b bytes.Buffer
+			targetCmd.Stderr = &b
+
+			defer wg.Done()
+
+			out, err = targetCmd.Output()
+			if b.Len() > 0 {
+				log.Printf("stderr: %s", b.Bytes())
+			}
+			b.Reset()
+		}()
+	}
 
 	wg.Wait()
 	if timer != nil {
@@ -181,9 +197,9 @@ func pipeRequest(config *WatchdogConfig, w http.ResponseWriter, r *http.Request,
 		}
 	}
 
-	execTime := time.Since(startTime).Seconds()
+	execDuration := time.Since(startTime).Seconds()
 	if ri.headerWritten == false {
-		w.Header().Set("X-Duration-Seconds", fmt.Sprintf("%f", execTime))
+		w.Header().Set("X-Duration-Seconds", fmt.Sprintf("%f", execDuration))
 		ri.headerWritten = true
 		w.WriteHeader(200)
 		w.Write(out)
@@ -195,9 +211,9 @@ func pipeRequest(config *WatchdogConfig, w http.ResponseWriter, r *http.Request,
 	}
 
 	if len(bytesWritten) > 0 {
-		log.Printf("%s - Duration: %f seconds", bytesWritten, execTime)
+		log.Printf("%s - Duration: %f seconds", bytesWritten, execDuration)
 	} else {
-		log.Printf("Duration: %f seconds", execTime)
+		log.Printf("Duration: %f seconds", execDuration)
 	}
 }
 

watchdog/readconfig.go

@@ -59,6 +59,7 @@ func (ReadConfig) Read(hasEnv HasEnv) WatchdogConfig {
 	cfg := WatchdogConfig{
 		writeDebug:    false,
 		cgiHeaders:    true,
+		combineOutput: true,
 	}
 
 	cfg.faasProcess = hasEnv.Getenv("fprocess")
@@ -86,6 +87,10 @@ func (ReadConfig) Read(hasEnv HasEnv) WatchdogConfig {
 
 	cfg.contentType = hasEnv.Getenv("content_type")
 
+	if isBoolValueSet("combine_output") {
+		cfg.combineOutput = parseBoolValue(hasEnv.Getenv("combine_output"))
+	}
+
 	return cfg
 }
 
@@ -124,4 +129,7 @@ type WatchdogConfig struct {
 
 	// port for HTTP server
 	port int
+
+	// combineOutput combines stderr and stdout in response
+	combineOutput bool
 }

watchdog/requesthandler_test.go

@@ -7,8 +7,10 @@ import (
 	"bytes"
 	"fmt"
 	"io/ioutil"
+	"log"
 	"net/http"
 	"net/http/httptest"
+	"os"
 	"strings"
 	"testing"
 	"time"
@@ -101,6 +103,96 @@ func TestHandler_HasCustomHeaderInFunction_WithCgiMode_AndBody(t *testing.T) {
 	}
 }
 
+func TestHandler_StderrWritesToStderr_CombinedOutput_False(t *testing.T) {
+	rr := httptest.NewRecorder()
+
+	b := bytes.NewBuffer([]byte{})
+	log.SetOutput(b)
+
+	body := ""
+	req, err := http.NewRequest("POST", "/", bytes.NewBufferString(body))
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	config := WatchdogConfig{
+		faasProcess:   "man badtopic",
+		cgiHeaders:    true,
+		combineOutput: false,
+	}
+
+	handler := makeRequestHandler(&config)
+	handler(rr, req)
+
+	required := http.StatusInternalServerError
+
+	if status := rr.Code; status != required {
+		t.Errorf("handler returned wrong status code - got: %v, want: %v",
+			status, required)
+	}
+
+	log.SetOutput(os.Stderr)
+
+	stderrBytes, _ := ioutil.ReadAll(b)
+	stderrVal := string(stderrBytes)
+
+	if strings.Contains(stderrVal, "No manual entry for") == false {
+		t.Logf("Stderr should have contained error from function \"No manual entry for\", but was: %s", stderrVal)
+		t.Fail()
+	}
+}
+
+func TestHandler_StderrWritesToResponse_CombinedOutput_True(t *testing.T) {
+	rr := httptest.NewRecorder()
+
+	b := bytes.NewBuffer([]byte{})
+	log.SetOutput(b)
+
+	body := ""
+	req, err := http.NewRequest("POST", "/", bytes.NewBufferString(body))
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	config := WatchdogConfig{
+		faasProcess:   "man badtopic",
+		cgiHeaders:    true,
+		combineOutput: true,
+	}
+
+	handler := makeRequestHandler(&config)
+	handler(rr, req)
+
+	required := http.StatusInternalServerError
+
+	if status := rr.Code; status != required {
+		t.Errorf("handler returned wrong status code - got: %v, want: %v",
+			status, required)
+	}
+
+	log.SetOutput(os.Stderr)
+
+	stderrBytes, _ := ioutil.ReadAll(b)
+	stderrVal := string(stderrBytes)
+
+	if strings.Contains(stderrVal, "No manual entry for") {
+		t.Logf("stderr should have not included any function errors, but did")
+		t.Fail()
+	}
+
+	bodyBytes, _ := ioutil.ReadAll(rr.Body)
+	bodyStr := string(bodyBytes)
+	want := `exit status 1
+No manual entry for badtopic`
+	if strings.Contains(bodyStr, want) == false {
+		t.Logf("response want: %s, got: %s", want, bodyStr)
+		t.Fail()
+	}
+
+}
+
 func TestHandler_DoesntHaveCustomHeaderInFunction_WithoutCgi_Mode(t *testing.T) {
 	rr := httptest.NewRecorder()