Merge pull request #336 from rod-hynes/master

Changes to support shipping more psiphond logs

psiphon/server/api.go

@@ -22,6 +22,7 @@ package server
 import (
 	"crypto/subtle"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"net"
 	"regexp"
@@ -97,9 +98,8 @@ func dispatchAPIRequestHandler(
 	// terminating in the case of a bug.
 	defer func() {
 		if e := recover(); e != nil {
-			reterr = common.ContextError(
-				fmt.Errorf(
-					"request handler panic: %s: %s", e, debug.Stack()))
+			log.LogPanicRecover(e, debug.Stack())
+			reterr = common.ContextError(errors.New("request handler panic"))
 		}
 	}()
 
@@ -620,8 +620,6 @@ func getRequestLogFields(
 	logFields := make(LogFields)
 
 	logFields["event_name"] = eventName
-	logFields["host_id"] = support.Config.HostID
-	logFields["build_rev"] = common.GetBuildInfo().BuildRev
 
 	// In psi_web, the space replacement was done to accommodate space
 	// delimited logging, which is no longer required; we retain the

psiphon/server/log.go

@@ -43,39 +43,72 @@ type ContextLogger struct {
 type LogFields logrus.Fields
 
 // WithContext adds a "context" field containing the caller's
-// function name and source file line number. Use this function
-// when the log has no fields.
+// function name and source file line number; and "host_id" and
+// "build_rev" fields identifying this server and build.
+// Use this function when the log has no fields.
 func (logger *ContextLogger) WithContext() *logrus.Entry {
-	return log.WithFields(
+	return logger.WithFields(
 		logrus.Fields{
-			"context": common.GetParentContext(),
+			"context":   common.GetParentContext(),
+			"host_id":   logHostID,
+			"build_rev": logBuildRev,
 		})
 }
 
-// WithContextFields adds a "context" field containing the caller's
-// function name and source file line number. Use this function
-// when the log has fields. Note that any existing "context" field
-// will be renamed to "field.context".
-func (logger *ContextLogger) WithContextFields(fields LogFields) *logrus.Entry {
-	_, ok := fields["context"]
-	if ok {
+func renameLogFields(fields LogFields) {
+	if _, ok := fields["context"]; ok {
 		fields["fields.context"] = fields["context"]
 	}
+	if _, ok := fields["host_id"]; ok {
+		fields["fields.host_id"] = fields["host_id"]
+	}
+	if _, ok := fields["build_rev"]; ok {
+		fields["fields.build_rev"] = fields["build_rev"]
+	}
+}
+
+// WithContextFields adds a "context" field containing the caller's
+// function name and source file line number; and "host_id" and
+// "build_rev" fields identifying this server and build.
+// Use this function when the log has fields.
+// Note that any existing "context"/"host_id"/"build_rev" field will
+// be renamed to "field.<name>".
+func (logger *ContextLogger) WithContextFields(fields LogFields) *logrus.Entry {
+	renameLogFields(fields)
 	fields["context"] = common.GetParentContext()
-	return log.WithFields(logrus.Fields(fields))
+	fields["host_id"] = logHostID
+	fields["build_rev"] = logBuildRev
+	return logger.WithFields(logrus.Fields(fields))
 }
 
 // LogRawFieldsWithTimestamp directly logs the supplied fields adding only
-// an additional "timestamp" field. The stock "msg" and "level" fields are
+// an additional "timestamp" field; and "host_id" and "build_rev" fields
+// identifying this server and build. The stock "msg" and "level" fields are
 // omitted. This log is emitted at the Error level. This function exists to
 // support API logs which have neither a natural message nor severity; and
 // omitting these values here makes it easier to ship these logs to existing
 // API log consumers.
+// Note that any existing "context"/"host_id"/"build_rev" field will
+// be renamed to "field.<name>".
 func (logger *ContextLogger) LogRawFieldsWithTimestamp(fields LogFields) {
+	renameLogFields(fields)
+	fields["host_id"] = logHostID
+	fields["build_rev"] = logBuildRev
 	logger.WithFields(logrus.Fields(fields)).Error(
 		customJSONFormatterLogRawFieldsWithTimestamp)
 }
 
+// LogPanicRecover calls LogRawFieldsWithTimestamp with standard fields
+// for logging recovered panics.
+func (logger *ContextLogger) LogPanicRecover(recoverValue interface{}, stack []byte) {
+	log.LogRawFieldsWithTimestamp(
+		LogFields{
+			"event_name":    "panic",
+			"recover_value": recoverValue,
+			"stack":         string(stack),
+		})
+}
+
 // NewLogWriter returns an io.PipeWriter that can be used to write
 // to the global logger. Caller must Close() the writer.
 func NewLogWriter() *io.PipeWriter {
@@ -139,6 +172,8 @@ func (f *CustomJSONFormatter) Format(entry *logrus.Entry) ([]byte, error) {
 
 var log *ContextLogger
 
+var logHostID, logBuildRev string
+
 // InitLogging configures a logger according to the specified
 // config params. If not called, the default logger set by the
 // package init() is used.
@@ -146,6 +181,9 @@ var log *ContextLogger
 // goroutine.
 func InitLogging(config *Config) error {
 
+	logHostID = config.HostID
+	logBuildRev = common.GetBuildInfo().BuildRev
+
 	level, err := logrus.ParseLevel(config.LogLevel)
 	if err != nil {
 		return common.ContextError(err)

psiphon/server/services.go

@@ -283,8 +283,6 @@ func logServerLoad(server *TunnelServer) {
 	runtime.ReadMemStats(&memStats)
 	fields := LogFields{
 		"event_name":    "server_load",
-		"build_rev":     common.GetBuildInfo().BuildRev,
-		"host_id":       server.sshServer.support.Config.HostID,
 		"num_goroutine": runtime.NumGoroutine(),
 		"mem_stats": map[string]interface{}{
 			"alloc":           memStats.Alloc,