logger.go

package logger

// Copyright 2017 Microsoft Corporation
//
//  Licensed under the Apache License, Version 2.0 (the "License");
//  you may not use this file except in compliance with the License.
//  You may obtain a copy of the License at
//
//      http://www.apache.org/licenses/LICENSE-2.0
//
//  Unless required by applicable law or agreed to in writing, software
//  distributed under the License is distributed on an "AS IS" BASIS,
//  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
//  See the License for the specific language governing permissions and
//  limitations under the License.

import (
	"bytes"
	"fmt"
	"io"
	"io/ioutil"
	"net/http"
	"net/url"
	"os"
	"strings"
	"sync"
	"time"
)

// LevelType tells a logger the minimum level to log. When code reports a log entry,
// the LogLevel indicates the level of the log entry. The logger only records entries
// whose level is at least the level it was told to log. See the Log* constants.
// For example, if a logger is configured with LogError, then LogError, LogPanic,
// and LogFatal entries will be logged; lower level entries are ignored.
type LevelType uint32

const (
	// LogNone tells a logger not to log any entries passed to it.
	LogNone LevelType = iota

	// LogFatal tells a logger to log all LogFatal entries passed to it.
	LogFatal

	// LogPanic tells a logger to log all LogPanic and LogFatal entries passed to it.
	LogPanic

	// LogError tells a logger to log all LogError, LogPanic and LogFatal entries passed to it.
	LogError

	// LogWarning tells a logger to log all LogWarning, LogError, LogPanic and LogFatal entries passed to it.
	LogWarning

	// LogInfo tells a logger to log all LogInfo, LogWarning, LogError, LogPanic and LogFatal entries passed to it.
	LogInfo

	// LogDebug tells a logger to log all LogDebug, LogInfo, LogWarning, LogError, LogPanic and LogFatal entries passed to it.
	LogDebug

	// LogAuth is a special case of LogDebug, it tells a logger to also log the body of an authentication request and response.
	// NOTE: this can disclose sensitive information, use with care.
	LogAuth
)

const (
	logNone    = "NONE"
	logFatal   = "FATAL"
	logPanic   = "PANIC"
	logError   = "ERROR"
	logWarning = "WARNING"
	logInfo    = "INFO"
	logDebug   = "DEBUG"
	logAuth    = "AUTH"
	logUnknown = "UNKNOWN"
)

// ParseLevel converts the specified string into the corresponding LevelType.
func ParseLevel(s string) (lt LevelType, err error) {
	switch strings.ToUpper(s) {
	case logFatal:
		lt = LogFatal
	case logPanic:
		lt = LogPanic
	case logError:
		lt = LogError
	case logWarning:
		lt = LogWarning
	case logInfo:
		lt = LogInfo
	case logDebug:
		lt = LogDebug
	case logAuth:
		lt = LogAuth
	default:
		err = fmt.Errorf("bad log level '%s'", s)
	}
	return
}

// String implements the stringer interface for LevelType.
func (lt LevelType) String() string {
	switch lt {
	case LogNone:
		return logNone
	case LogFatal:
		return logFatal
	case LogPanic:
		return logPanic
	case LogError:
		return logError
	case LogWarning:
		return logWarning
	case LogInfo:
		return logInfo
	case LogDebug:
		return logDebug
	case LogAuth:
		return logAuth
	default:
		return logUnknown
	}
}

// Filter defines functions for filtering HTTP request/response content.
type Filter struct {
	// URL returns a potentially modified string representation of a request URL.
	URL func(u *url.URL) string

	// Header returns a potentially modified set of values for the specified key.
	// To completely exclude the header key/values return false.
	Header func(key string, val []string) (bool, []string)

	// Body returns a potentially modified request/response body.
	Body func(b []byte) []byte
}

func (f Filter) processURL(u *url.URL) string {
	if f.URL == nil {
		return u.String()
	}
	return f.URL(u)
}

func (f Filter) processHeader(k string, val []string) (bool, []string) {
	if f.Header == nil {
		return true, val
	}
	return f.Header(k, val)
}

func (f Filter) processBody(b []byte) []byte {
	if f.Body == nil {
		return b
	}
	return f.Body(b)
}

// Writer defines methods for writing to a logging facility.
type Writer interface {
	// Writeln writes the specified message with the standard log entry header and new-line character.
	Writeln(level LevelType, message string)

	// Writef writes the specified format specifier with the standard log entry header and no new-line character.
	Writef(level LevelType, format string, a ...interface{})

	// WriteRequest writes the specified HTTP request to the logger if the log level is greater than
	// or equal to LogInfo.  The request body, if set, is logged at level LogDebug or higher.
	// Custom filters can be specified to exclude URL, header, and/or body content from the log.
	// By default no request content is excluded.
	WriteRequest(req *http.Request, filter Filter)

	// WriteResponse writes the specified HTTP response to the logger if the log level is greater than
	// or equal to LogInfo.  The response body, if set, is logged at level LogDebug or higher.
	// Custom filters can be specified to exclude URL, header, and/or body content from the log.
	// By default no response content is excluded.
	WriteResponse(resp *http.Response, filter Filter)
}

// Instance is the default log writer initialized during package init.
// This can be replaced with a custom implementation as required.
var Instance Writer

// default log level
var logLevel = LogNone

// Level returns the value specified in AZURE_GO_SDK_LOG_LEVEL.
// If no value was specified the default value is LogNone.
// Custom loggers can call this to retrieve the configured log level.
func Level() LevelType {
	return logLevel
}

func init() {
	// separated for testing purposes
	initDefaultLogger()
}

func initDefaultLogger() {
	// init with nilLogger so callers don't have to do a nil check on Default
	Instance = nilLogger{}
	llStr := strings.ToLower(os.Getenv("AZURE_GO_SDK_LOG_LEVEL"))
	if llStr == "" {
		return
	}
	var err error
	logLevel, err = ParseLevel(llStr)
	if err != nil {
		fmt.Fprintf(os.Stderr, "go-autorest: failed to parse log level: %s\n", err.Error())
		return
	}
	if logLevel == LogNone {
		return
	}
	// default to stderr
	dest := os.Stderr
	lfStr := os.Getenv("AZURE_GO_SDK_LOG_FILE")
	if strings.EqualFold(lfStr, "stdout") {
		dest = os.Stdout
	} else if lfStr != "" {
		lf, err := os.Create(lfStr)
		if err == nil {
			dest = lf
		} else {
			fmt.Fprintf(os.Stderr, "go-autorest: failed to create log file, using stderr: %s\n", err.Error())
		}
	}
	Instance = fileLogger{
		logLevel: logLevel,
		mu:       &sync.Mutex{},
		logFile:  dest,
	}
}

// the nil logger does nothing
type nilLogger struct{}

func (nilLogger) Writeln(LevelType, string) {}

func (nilLogger) Writef(LevelType, string, ...interface{}) {}

func (nilLogger) WriteRequest(*http.Request, Filter) {}

func (nilLogger) WriteResponse(*http.Response, Filter) {}

// A File is used instead of a Logger so the stream can be flushed after every write.
type fileLogger struct {
	logLevel LevelType
	mu       *sync.Mutex // for synchronizing writes to logFile
	logFile  *os.File
}

func (fl fileLogger) Writeln(level LevelType, message string) {
	fl.Writef(level, "%s\n", message)
}

func (fl fileLogger) Writef(level LevelType, format string, a ...interface{}) {
	if fl.logLevel >= level {
		fl.mu.Lock()
		defer fl.mu.Unlock()
		fmt.Fprintf(fl.logFile, "%s %s", entryHeader(level), fmt.Sprintf(format, a...))
		fl.logFile.Sync()
	}
}

func (fl fileLogger) WriteRequest(req *http.Request, filter Filter) {
	if req == nil || fl.logLevel < LogInfo {
		return
	}
	b := &bytes.Buffer{}
	fmt.Fprintf(b, "%s REQUEST: %s %s\n", entryHeader(LogInfo), req.Method, filter.processURL(req.URL))
	// dump headers
	for k, v := range req.Header {
		if ok, mv := filter.processHeader(k, v); ok {
			fmt.Fprintf(b, "%s: %s\n", k, strings.Join(mv, ","))
		}
	}
	if fl.shouldLogBody(req.Header, req.Body) {
		// dump body
		body, err := ioutil.ReadAll(req.Body)
		if err == nil {
			fmt.Fprintln(b, string(filter.processBody(body)))
			if nc, ok := req.Body.(io.Seeker); ok {
				// rewind to the beginning
				nc.Seek(0, io.SeekStart)
			} else {
				// recreate the body
				req.Body = ioutil.NopCloser(bytes.NewReader(body))
			}
		} else {
			fmt.Fprintf(b, "failed to read body: %v\n", err)
		}
	}
	fl.mu.Lock()
	defer fl.mu.Unlock()
	fmt.Fprint(fl.logFile, b.String())
	fl.logFile.Sync()
}

func (fl fileLogger) WriteResponse(resp *http.Response, filter Filter) {
	if resp == nil || fl.logLevel < LogInfo {
		return
	}
	b := &bytes.Buffer{}
	fmt.Fprintf(b, "%s RESPONSE: %d %s\n", entryHeader(LogInfo), resp.StatusCode, filter.processURL(resp.Request.URL))
	// dump headers
	for k, v := range resp.Header {
		if ok, mv := filter.processHeader(k, v); ok {
			fmt.Fprintf(b, "%s: %s\n", k, strings.Join(mv, ","))
		}
	}
	if fl.shouldLogBody(resp.Header, resp.Body) {
		// dump body
		defer resp.Body.Close()
		body, err := ioutil.ReadAll(resp.Body)
		if err == nil {
			fmt.Fprintln(b, string(filter.processBody(body)))
			resp.Body = ioutil.NopCloser(bytes.NewReader(body))
		} else {
			fmt.Fprintf(b, "failed to read body: %v\n", err)
		}
	}
	fl.mu.Lock()
	defer fl.mu.Unlock()
	fmt.Fprint(fl.logFile, b.String())
	fl.logFile.Sync()
}

// returns true if the provided body should be included in the log
func (fl fileLogger) shouldLogBody(header http.Header, body io.ReadCloser) bool {
	ct := header.Get("Content-Type")
	return fl.logLevel >= LogDebug && body != nil && !strings.Contains(ct, "application/octet-stream")
}

// creates standard header for log entries, it contains a timestamp and the log level
func entryHeader(level LevelType) string {
	// this format provides a fixed number of digits so the size of the timestamp is constant
	return fmt.Sprintf("(%s) %s:", time.Now().Format("2006-01-02T15:04:05.0000000Z07:00"), level.String())
}