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

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 #4664
Fixes #4628

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
 }
 

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!"

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) {