Capture output from stdlib log library. (letsencrypt#4665)

jsha · web-flow · commit 13a0bb32f12e · 2020-02-05T09:28:38.000-08:00
Some components, particularly net/http, occasionally output log lines via log.Print. We'd like to capture these and send them to rsyslog so all our log data goes to the same place, and so that we can attach log line checksums to them. This uses log.SetOutput to change the log output to an io.Pipe, then consumes that buffer line-by-line in a goroutine and sends it to our rsyslog logger. This seems to tickle an unrelated race condition in test/ocsp/helper.go, so I fixed that too. Also filters out a noisy and unimportant error from the grpcLog handler. Fixes letsencrypt#4664 Fixes letsencrypt#4628
diff --git a/cmd/shell.go b/cmd/shell.go
@@ -2,11 +2,13 @@
 package cmd
 
 import (
+	"bufio"
 	"encoding/json"
 	"encoding/pem"
 	"errors"
 	"expvar"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"log"
 	"log/syslog"
@@ -93,6 +95,9 @@ func (log grpcLogger) Error(args ...interface{}) {
 }
 func (log grpcLogger) Errorf(format string, args ...interface{}) {
 	output := fmt.Sprintf(format, args...)
+	if output == `ccResolverWrapper: error parsing service config: no JSON service config provided` {
+		return
+	}
 	if output == `grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"` {
 		return
 	}
@@ -129,6 +134,23 @@ func (log promLogger) Println(args ...interface{}) {
 	log.AuditErr(fmt.Sprintln(args...))
 }
 
+// captureStdlibLog captures the logs generated by log.Print*
+// and, instead of writing them to stdout, writes them to the provided logger
+// at "Info" level.
+func captureStdlibLog(logger blog.Logger) {
+	r, w := io.Pipe()
+	log.SetOutput(w)
+	go func() {
+		scanner := bufio.NewScanner(r)
+		for scanner.Scan() {
+			logger.Info(scanner.Text())
+		}
+		if err := scanner.Err(); err != nil {
+			logger.AuditErrf("reading stdlib log: %s", err)
+		}
+	}()
+}
+
 // StatsAndLogging constructs a prometheus registerer and an AuditLogger based
 // on its config parameters, and return them both. It also spawns off an HTTP
 // server on the provided port to report the stats and provide pprof profiling
@@ -167,6 +189,9 @@ func NewLogger(logConf SyslogConfig) blog.Logger {
 	cfsslLog.SetLogger(cfsslLogger{logger})
 	_ = mysql.SetLogger(mysqlLogger{logger})
 	grpclog.SetLoggerV2(grpcLogger{logger})
+
+	captureStdlibLog(logger)
+
 	return logger
 }
 
diff --git a/cmd/shell_test.go b/cmd/shell_test.go
@@ -3,8 +3,11 @@ package cmd
 import (
 	"encoding/json"
 	"fmt"
+	"log"
 	"runtime"
+	"strings"
 	"testing"
+	"time"
 
 	"github.com/letsencrypt/boulder/core"
 	blog "github.com/letsencrypt/boulder/log"
@@ -121,6 +124,20 @@ func TestCfsslLogger(t *testing.T) {
 	}
 }
 
+func TestCaptureStdlibLog(t *testing.T) {
+	logger := blog.UseMock()
+	captureStdlibLog(logger)
+	log.Print("thisisatest")
+	// Since the handler for captureStdlibLog runs in a goroutine, we have to wait
+	// for a bit to ensure it processed the log line we sent.
+	time.Sleep(250 * time.Millisecond)
+	results := logger.GetAllMatching("thisisatest")
+	if len(results) != 1 {
+		t.Fatalf("Expected logger to receive 'thisisatest', got: %s",
+			strings.Join(logger.GetAllMatching(".*"), "\n"))
+	}
+}
+
 func TestVersionString(t *testing.T) {
 	core.BuildID = "TestBuildID"
 	core.BuildTime = "RightNow!"
diff --git a/test/ocsp/helper/helper.go b/test/ocsp/helper/helper.go
@@ -127,8 +127,6 @@ func ReqDER(der []byte, expectStatus int) (*ocsp.Response, error) {
 		return nil, err
 	}
 
-	http.DefaultClient.Timeout = 5 * time.Second
-
 	httpResp, err := sendHTTPRequest(req, ocspURL)
 	if err != nil {
 		return nil, err
@@ -175,7 +173,11 @@ func sendHTTPRequest(req []byte, ocspURL *url.URL) (*http.Response, error) {
 	if *hostOverride != "" {
 		httpRequest.Host = *hostOverride
 	}
-	return http.DefaultClient.Do(httpRequest)
+	client := http.Client{
+		Timeout: 5 * time.Second,
+	}
+
+	return client.Do(httpRequest)
 }
 
 func getOCSPURL(cert *x509.Certificate) (*url.URL, error) {

Original file line number	Diff line number	Diff line change
`@@ -127,8 +127,6 @@ func ReqDER(der []byte, expectStatus int) (*ocsp.Response, error) {`
`127`	`127`	`return nil, err`
`128`	`128`	`}`
`129`	`129`
`130`		`- http.DefaultClient.Timeout = 5 * time.Second`
`131`		`-`
`132`	`130`	`httpResp, err := sendHTTPRequest(req, ocspURL)`
`133`	`131`	`if err != nil {`
`134`	`132`	`return nil, err`
`@@ -175,7 +173,11 @@ func sendHTTPRequest(req []byte, ocspURL url.URL) (http.Response, error) {`
`175`	`173`	`if *hostOverride != "" {`
`176`	`174`	`httpRequest.Host = *hostOverride`
`177`	`175`	`}`
`178`		`- return http.DefaultClient.Do(httpRequest)`
	`176`	`+ client := http.Client{`
	`177`	`+ Timeout: 5 * time.Second,`
	`178`	`+ }`
	`179`	`+`
	`180`	`+ return client.Do(httpRequest)`
`179`	`181`	`}`
`180`	`182`
`181`	`183`	`func getOCSPURL(cert x509.Certificate) (url.URL, error) {`