/* * Copyright (c) 2016, Psiphon Inc. * All rights reserved. * * This program is free software: you can redistribute it and/or modify * it under the terms of the GNU General Public License as published by * the Free Software Foundation, either version 3 of the License, or * (at your option) any later version. * * This program is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * GNU General Public License for more details. * * You should have received a copy of the GNU General Public License * along with this program. If not, see . * */ package server import ( "encoding/json" "fmt" "io" "io/ioutil" go_log "log" "os" "sync" "github.com/Psiphon-Inc/rotate-safe-writer" "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common" "github.com/sirupsen/logrus" ) // MetricsSource is an object that provides metrics to be logged type MetricsSource interface { // GetMetrics returns a LogFields populated with // metrics from the MetricsSource GetMetrics() LogFields } // ContextLogger adds context logging functionality to the // underlying logging packages. type ContextLogger struct { *logrus.Logger } // LogFields is an alias for the field struct in the // underlying logging package. type LogFields logrus.Fields // WithContext 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 no fields. func (logger *ContextLogger) WithContext() *logrus.Entry { return logger.WithFields( logrus.Fields{ "context": common.GetParentContext(), "host_id": logHostID, "build_rev": logBuildRev, }) } 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.". func (logger *ContextLogger) WithContextFields(fields LogFields) *logrus.Entry { renameLogFields(fields) fields["context"] = common.GetParentContext() 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; 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.". 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), }) } type commonLogger struct { contextLogger *ContextLogger } func (logger *commonLogger) WithContext() common.LogContext { // Patch context to be correct parent return logger.contextLogger.WithContext().WithField("context", common.GetParentContext()) } func (logger *commonLogger) WithContextFields(fields common.LogFields) common.LogContext { // Patch context to be correct parent return logger.contextLogger.WithContextFields(LogFields(fields)).WithField("context", common.GetParentContext()) } func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) { fields["event_name"] = metric logger.contextLogger.LogRawFieldsWithTimestamp(LogFields(fields)) } // CommonLogger wraps a ContextLogger instance with an interface // that conforms to common.Logger. This is used to make the ContextLogger // available to other packages that don't import the "server" package. func CommonLogger(contextLogger *ContextLogger) *commonLogger { return &commonLogger{ contextLogger: contextLogger, } } // NewLogWriter returns an io.PipeWriter that can be used to write // to the global logger. Caller must Close() the writer. func NewLogWriter() *io.PipeWriter { return log.Writer() } // CustomJSONFormatter is a customized version of logrus.JSONFormatter type CustomJSONFormatter struct { } const customJSONFormatterLogRawFieldsWithTimestamp = "CustomJSONFormatter.LogRawFieldsWithTimestamp" // Format implements logrus.Formatter. This is a customized version // of the standard logrus.JSONFormatter adapted from: // https://github.com/Sirupsen/logrus/blob/f1addc29722ba9f7651bc42b4198d0944b66e7c4/json_formatter.go // // The changes are: // - "time" is renamed to "timestamp" // - there's an option to omit the standard "msg" and "level" fields // func (f *CustomJSONFormatter) Format(entry *logrus.Entry) ([]byte, error) { data := make(logrus.Fields, len(entry.Data)+3) for k, v := range entry.Data { switch v := v.(type) { case error: // Otherwise errors are ignored by `encoding/json` // https://github.com/Sirupsen/logrus/issues/137 data[k] = v.Error() default: data[k] = v } } if t, ok := data["timestamp"]; ok { data["fields.timestamp"] = t } data["timestamp"] = entry.Time.Format(logrus.DefaultTimestampFormat) if entry.Message != customJSONFormatterLogRawFieldsWithTimestamp { if m, ok := data["msg"]; ok { data["fields.msg"] = m } if l, ok := data["level"]; ok { data["fields.level"] = l } data["msg"] = entry.Message data["level"] = entry.Level.String() } serialized, err := json.Marshal(data) if err != nil { return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err) } return append(serialized, '\n'), nil } var log *ContextLogger var logHostID, logBuildRev string var initLogging sync.Once // InitLogging configures a logger according to the specified // config params. If not called, the default logger set by the // package init() is used. // Concurrency notes: this should only be called from the main // goroutine; InitLogging only has effect on the first call, as // the logging facilities it initializes may be in use by other // goroutines after that point. func InitLogging(config *Config) (retErr error) { initLogging.Do(func() { logHostID = config.HostID logBuildRev = common.GetBuildInfo().BuildRev level, err := logrus.ParseLevel(config.LogLevel) if err != nil { retErr = common.ContextError(err) return } var logWriter io.Writer if config.LogFilename != "" { logWriter, err = rotate.NewRotatableFileWriter(config.LogFilename, 0666) if err != nil { retErr = common.ContextError(err) return } if !config.SkipPanickingLogWriter { // Use PanickingLogWriter, which will intentionally // panic when a Write fails. Set SkipPanickingLogWriter // if this behavior is not desired. // // Note that NewRotatableFileWriter will first attempt // a retry when a Write fails. // // It is assumed that continuing operation while unable // to log is unacceptable; and that the psiphond service // is managed and will restart when it terminates. // // It is further assumed that panicking will result in // an error that is externally logged and reported to a // monitoring system. // // TODO: An orderly shutdown may be preferred, as some // data will be lost in a panic (e.g., server_tunnel logs). // It may be possible to perform an orderly shutdown first // and then panic, or perform an orderly shutdown and // simulate a panic message that will be reported. logWriter = NewPanickingLogWriter(config.LogFilename, logWriter) } } else { logWriter = os.Stderr } log = &ContextLogger{ &logrus.Logger{ Out: logWriter, Formatter: &CustomJSONFormatter{}, Level: level, }, } }) return retErr } func init() { // Suppress standard "log" package logging performed by other packages. // For example, "net/http" logs messages such as: // "http: TLS handshake error from :: [...]: i/o timeout" go_log.SetOutput(ioutil.Discard) log = &ContextLogger{ &logrus.Logger{ Out: os.Stderr, Formatter: &CustomJSONFormatter{}, Hooks: make(logrus.LevelHooks), Level: logrus.DebugLevel, }, } }