/* * 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" "sync/atomic" "time" "github.com/Psiphon-Inc/rotate-safe-writer" "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common" "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/buildinfo" "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/errors" "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/stacktrace" "github.com/sirupsen/logrus" ) // TraceLogger adds single frame stack trace information to the underlying // logging facilities. type TraceLogger struct { *logrus.Logger } // LogFields is an alias for the field struct in the underlying logging // package. type LogFields logrus.Fields // Add copies log fields from b to a, skipping fields which already exist, // regardless of value, in a. func (a LogFields) Add(b LogFields) { for name, value := range b { _, ok := a[name] if !ok { a[name] = value } } } // WithTrace adds a "trace" 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 *TraceLogger) WithTrace() *logrus.Entry { return logger.WithFields( logrus.Fields{ "trace": stacktrace.GetParentFunctionName(), "host_id": logHostID, "build_rev": logBuildRev, }) } func renameLogFields(fields LogFields) { if _, ok := fields["trace"]; ok { fields["fields.trace"] = fields["trace"] } 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"] } } // WithTraceFields adds a "trace" 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 "trace"/"host_id"/"build_rev" field will be // renamed to "field.". func (logger *TraceLogger) WithTraceFields(fields LogFields) *logrus.Entry { renameLogFields(fields) fields["trace"] = stacktrace.GetParentFunctionName() 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 "trace"/"host_id"/"build_rev" field will be renamed // to "field.". func (logger *TraceLogger) 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 *TraceLogger) LogPanicRecover(recoverValue interface{}, stack []byte) { log.LogRawFieldsWithTimestamp( LogFields{ "event_name": "panic", "recover_value": recoverValue, "stack": string(stack), }) } type commonLogger struct { traceLogger *TraceLogger } func (logger *commonLogger) WithTrace() common.LogTrace { // Patch trace to be correct parent return logger.traceLogger.WithTrace().WithField( "trace", stacktrace.GetParentFunctionName()) } func (logger *commonLogger) WithTraceFields(fields common.LogFields) common.LogTrace { // Patch trace to be correct parent return logger.traceLogger.WithTraceFields(LogFields(fields)).WithField( "trace", stacktrace.GetParentFunctionName()) } func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) { fields["event_name"] = metric logger.traceLogger.LogRawFieldsWithTimestamp(LogFields(fields)) } // CommonLogger wraps a TraceLogger instance with an interface that conforms // to common.Logger. This is used to make the TraceLogger available to other // packages that don't import the "server" package. func CommonLogger(traceLogger *TraceLogger) *commonLogger { return &commonLogger{ traceLogger: traceLogger, } } // 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 { } var ( useLogCallback int32 logCallback atomic.Value ) // setLogCallback sets a callback that is invoked with each JSON log message. // This facility is intended for use in testing only. func setLogCallback(callback func([]byte)) { if callback == nil { atomic.StoreInt32(&useLogCallback, 0) return } atomic.StoreInt32(&useLogCallback, 1) logCallback.Store(callback) } 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(time.RFC3339) 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) } if atomic.LoadInt32(&useLogCallback) == 1 { logCallback.Load().(func([]byte))(serialized) } return append(serialized, '\n'), nil } var log *TraceLogger 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 = buildinfo.GetBuildInfo().BuildRev level, err := logrus.ParseLevel(config.LogLevel) if err != nil { retErr = errors.Trace(err) return } var logWriter io.Writer if config.LogFilename != "" { retries, create, mode := config.GetLogFileReopenConfig() logWriter, err = rotate.NewRotatableFileWriter( config.LogFilename, retries, create, mode) if err != nil { retErr = errors.Trace(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 = &TraceLogger{ &logrus.Logger{ Out: logWriter, Formatter: &CustomJSONFormatter{}, Level: level, }, } }) return retErr } func IsLogLevelDebug() bool { return log.Logger.Level == logrus.DebugLevel } 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 = &TraceLogger{ &logrus.Logger{ Out: os.Stderr, Formatter: &CustomJSONFormatter{}, Hooks: make(logrus.LevelHooks), Level: logrus.DebugLevel, }, } }