dendrite/common/log.go

// Copyright 2017 Vector Creations Ltd
//
// 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.

package common

import (
	"fmt"
	"os"
	"path"
	"path/filepath"
	"runtime"
	"strings"

	"github.com/matrix-org/dendrite/common/config"
	"github.com/matrix-org/dugong"
	"github.com/sirupsen/logrus"
)

type utcFormatter struct {
	logrus.Formatter
}

func (f utcFormatter) Format(entry *logrus.Entry) ([]byte, error) {
	entry.Time = entry.Time.UTC()
	return f.Formatter.Format(entry)
}

// Logrus hook which wraps another hook and filters log entries according to their level.
// (Note that we cannot use solely logrus.SetLevel, because Dendrite supports multiple
// levels of logging at the same time.)
type logLevelHook struct {
	level logrus.Level
	logrus.Hook
}

// Levels returns all the levels supported by this hook.
func (h *logLevelHook) Levels() []logrus.Level {
	levels := make([]logrus.Level, 0)

	for _, level := range logrus.AllLevels {
		if level <= h.level {
			levels = append(levels, level)
		}
	}

	return levels
}

var (
	maxFilenameLength = 30
	maxFuncnameLength = 20
)

// callerPrettyfier is a function that given a runtime.Frame object, will
// extract the calling function's name and file, and return them with some
// formatting to cut them down slightly (to make logs nicer to read)
func callerPrettyfier2(f *runtime.Frame) (string, string) {
	// Get just the name of the calling function
	funcsplit := strings.Split(f.Function, ".")
	funcname := funcsplit[len(funcsplit)-1]

	// If in debug mode, print the full path to the calling file
	var filename string
	if false { // debug
		filename = fmt.Sprintf("[%s:%d]", f.File, f.Line)
	} else {
		// Otherwise compress and truncate it
		compressedFilepath := truncateDirectoryNames(f.File)

		// Add the line number to the end
		filename = fmt.Sprintf("%s:%d", compressedFilepath, f.Line)

		// Truncate/pad the resulting string to fit it into a certain number of
		// characters
		filename = padWithLength(filename, maxFilenameLength, true)
	}

	// Truncate/pad filename lengths if necessary
	funcname = padWithLength(funcname, maxFuncnameLength, false)
	return funcname, " " + filename
}

func callerPrettyfier(f *runtime.Frame) (string, string) {
	s := strings.Split(f.Function, ".")
	funcname := s[len(s)-1]
	return funcname + "\n\t", fmt.Sprintf(" [%s:%d]", f.File, f.Line)
}

// truncateDirectoryNames is a function that takes in a filepath, then returns
// the same path but with all directory names truncated to one character.
// So ex. /home/user/music/mysong.mp3 -> /h/u/m/mysong.mp3
// Intended for use only with absolute paths
func truncateDirectoryNames(filepath string) string {
	// Split the filepath into a slice
	pathComponents := strings.Split(filepath, "/")[1:] // cut off " " generated by first "/"
	// Create a slice for holding the 1 char dir names
	truncatedComponents := make([]string, 0, len(pathComponents))

	// Iterate through each directory name and get the first character of each
	for _, directory := range pathComponents[:len(pathComponents)-1] {
		// Save each character
		character := string([]rune(directory)[0])
		truncatedComponents = append(truncatedComponents, character)
	}

	// Add the filename to the end of the array
	truncatedComponents = append(truncatedComponents, pathComponents[len(pathComponents)-1])

	// Join everything by `/` and return
	return "/" + strings.Join(truncatedComponents, "/")
}

func padWithLength(content string, length int, reverseTruncate bool) (ret string) {
	fmt.Printf("Got: %s\n", content)
	// Create an empty slice with the length of the content
	slice := make([]string, length, length)
	for index := range slice {
		slice[index] = " "
	}

	// Insert each character from `content` into the string slice, prepending and
	// appending with square brackets
	// TODO: Insert ellipses
	slice[0] = "["
	var setEnd = false
	if reverseTruncate {
		if len(content) >= length {
			slice[length-1] = "]"
		}
		for i := length - 2; i > 0; i-- {
			if i < len(content) {
				slice[i] = string([]rune(content)[len(content)-(length-i)+1])
			} else if i == len(content) {
				slice[i] = "]"
			}
		}
	} else {
		for i := 1; i < length; i++ {
			if i <= len(content) {
				slice[i] = string([]rune(content)[i-1])
			} else if i == len(content)+1 {
				slice[i] = "]"
				setEnd = true
			}

			if i == length-1 && !setEnd {
				slice[i] = "]"
			}
		}
	}

	// Convert slice to a string
	for _, char := range slice {
		ret += char
	}
	return
}

// SetupStdLogging configures the logging format to standard output. Typically, it is called when the config is not yet loaded.
func SetupStdLogging() {
	logrus.SetReportCaller(true)
	logrus.SetFormatter(&utcFormatter{
		&logrus.TextFormatter{
			TimestampFormat:  "2006-01-02T15:04:05.000000000Z07:00",
			FullTimestamp:    true,
			DisableColors:    false,
			DisableTimestamp: false,
			QuoteEmptyFields: true,
			CallerPrettyfier: callerPrettyfier,
		},
	})
}

// SetupHookLogging configures the logging hooks defined in the configuration.
// If something fails here it means that the logging was improperly configured,
// so we just exit with the error
func SetupHookLogging(hooks []config.LogrusHook, componentName string) {
	logrus.SetReportCaller(true)
	for _, hook := range hooks {

		// Check we received a proper logging level
		level, err := logrus.ParseLevel(hook.Level)
		if err != nil {
			logrus.Fatalf("Unrecognised logging level %s: %q", hook.Level, err)
		}

		// Perform a first filter on the logs according to the lowest level of all
		// (Eg: If we have hook for info and above, prevent logrus from processing debug logs)
		if logrus.GetLevel() < level {
			logrus.SetLevel(level)
		}

		switch hook.Type {
		case "file":
			checkFileHookParams(hook.Params)
			setupFileHook(hook, level, componentName)
		default:
			logrus.Fatalf("Unrecognised logging hook type: %s", hook.Type)
		}
	}
}

// File type hooks should be provided a path to a directory to store log files
func checkFileHookParams(params map[string]interface{}) {
	path, ok := params["path"]
	if !ok {
		logrus.Fatalf("Expecting a parameter \"path\" for logging hook of type \"file\"")
	}

	if _, ok := path.(string); !ok {
		logrus.Fatalf("Parameter \"path\" for logging hook of type \"file\" should be a string")
	}
}

// Add a new FSHook to the logger. Each component will log in its own file
func setupFileHook(hook config.LogrusHook, level logrus.Level, componentName string) {
	dirPath := (hook.Params["path"]).(string)
	fullPath := filepath.Join(dirPath, componentName+".log")

	if err := os.MkdirAll(path.Dir(fullPath), os.ModePerm); err != nil {
		logrus.Fatalf("Couldn't create directory %s: %q", path.Dir(fullPath), err)
	}

	logrus.AddHook(&logLevelHook{
		level,
		dugong.NewFSHook(
			fullPath,
			&utcFormatter{
				&logrus.TextFormatter{
					TimestampFormat:  "2006-01-02T15:04:05.000000000Z07:00",
					DisableColors:    true,
					DisableTimestamp: false,
					DisableSorting:   false,
					QuoteEmptyFields: true,
				},
			},
			&dugong.DailyRotationSchedule{GZip: true},
		),
	})
}