log.go

Documentation: kubevirt.io/client-go/log

     1  /*
     2   * This file is part of the KubeVirt project
     3   *
     4   * Licensed under the Apache License, Version 2.0 (the "License");
     5   * you may not use this file except in compliance with the License.
     6   * You may obtain a copy of the License at
     7   *
     8   *     http://www.apache.org/licenses/LICENSE-2.0
     9   *
    10   * Unless required by applicable law or agreed to in writing, software
    11   * distributed under the License is distributed on an "AS IS" BASIS,
    12   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    13   * See the License for the specific language governing permissions and
    14   * limitations under the License.
    15   *
    16   * Copyright 2017 Red Hat, Inc.
    17   *
    18   */
    19  
    20  package log
    21  
    22  import (
    23  	"errors"
    24  	goflag "flag"
    25  	"fmt"
    26  	"io"
    27  	"os"
    28  	"path/filepath"
    29  	"runtime"
    30  	"strconv"
    31  	"strings"
    32  	"sync"
    33  	"time"
    34  
    35  	klog "github.com/go-kit/kit/log"
    36  	"github.com/golang/glog"
    37  	flag "github.com/spf13/pflag"
    38  	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
    39  	k8sruntime "k8s.io/apimachinery/pkg/runtime"
    40  )
    41  
    42  const (
    43  	libvirtTimestampFormat = "2006-01-02 15:04:05.999-0700"
    44  	logTimestampFormat     = "2006-01-02T15:04:05.000000Z"
    45  )
    46  
    47  type LogLevel int32
    48  
    49  const (
    50  	INFO LogLevel = iota
    51  	WARNING
    52  	ERROR
    53  	FATAL
    54  )
    55  
    56  var LogLevelNames = map[LogLevel]string{
    57  	INFO:    "info",
    58  	WARNING: "warning",
    59  	ERROR:   "error",
    60  	FATAL:   "fatal",
    61  }
    62  
    63  var lock sync.Mutex
    64  
    65  type LoggableObject interface {
    66  	metav1.ObjectMetaAccessor
    67  	k8sruntime.Object
    68  }
    69  
    70  type FilteredVerbosityLogger struct {
    71  	filteredLogger FilteredLogger
    72  }
    73  
    74  type FilteredLogger struct {
    75  	logger                klog.Logger
    76  	component             string
    77  	filterLevel           LogLevel
    78  	currentLogLevel       LogLevel
    79  	verbosityLevel        int
    80  	currentVerbosityLevel int
    81  	err                   error
    82  }
    83  
    84  var Log = DefaultLogger()
    85  
    86  func InitializeLogging(comp string) {
    87  	defaultComponent = comp
    88  	Log = DefaultLogger()
    89  	glog.CopyStandardLogTo(LogLevelNames[INFO])
    90  	goflag.CommandLine.Set("component", comp)
    91  	goflag.CommandLine.Set("logtostderr", "true")
    92  }
    93  
    94  func getDefaultVerbosity() int {
    95  	if verbosityFlag := flag.Lookup("v"); verbosityFlag != nil {
    96  		defaultVerbosity, _ := strconv.Atoi(verbosityFlag.Value.String())
    97  		return defaultVerbosity
    98  	} else {
    99  		// "the practical default level is V(2)"
   100  		// see https://github.com/kubernetes/community/blob/master/contributors/devel/logging.md
   101  		return 2
   102  	}
   103  }
   104  
   105  // Wrap a go-kit logger in a FilteredLogger. Not cached
   106  func MakeLogger(logger klog.Logger) *FilteredLogger {
   107  	defaultLogLevel := INFO
   108  
   109  	defaultVerbosity = getDefaultVerbosity()
   110  	// This verbosity will be used for info logs without setting a custom verbosity level
   111  	defaultCurrentVerbosity := 2
   112  
   113  	return &FilteredLogger{
   114  		logger:                logger,
   115  		component:             defaultComponent,
   116  		filterLevel:           defaultLogLevel,
   117  		currentLogLevel:       defaultLogLevel,
   118  		verbosityLevel:        defaultVerbosity,
   119  		currentVerbosityLevel: defaultCurrentVerbosity,
   120  	}
   121  }
   122  
   123  type NullLogger struct{}
   124  
   125  func (n NullLogger) Log(params ...interface{}) error { return nil }
   126  
   127  var loggers = make(map[string]*FilteredLogger)
   128  var defaultComponent = ""
   129  var defaultVerbosity = 0
   130  
   131  func createLogger(component string) {
   132  	lock.Lock()
   133  	defer lock.Unlock()
   134  	_, ok := loggers[component]
   135  	if ok == false {
   136  		logger := klog.NewJSONLogger(os.Stderr)
   137  		log := MakeLogger(logger)
   138  		log.component = component
   139  		loggers[component] = log
   140  	}
   141  }
   142  
   143  func Logger(component string) *FilteredLogger {
   144  	_, ok := loggers[component]
   145  	if ok == false {
   146  		createLogger(component)
   147  	}
   148  	return loggers[component]
   149  }
   150  
   151  func DefaultLogger() *FilteredLogger {
   152  	return Logger(defaultComponent)
   153  }
   154  
   155  // SetIOWriter is meant to be used for testing. "log" and "glog" logs are sent to /dev/nil.
   156  // KubeVirt related log messages will be sent to this writer
   157  func (l *FilteredLogger) SetIOWriter(w io.Writer) {
   158  	l.logger = klog.NewJSONLogger(w)
   159  	goflag.CommandLine.Set("logtostderr", "false")
   160  }
   161  
   162  func (l *FilteredLogger) SetLogger(logger klog.Logger) *FilteredLogger {
   163  	l.logger = logger
   164  	return l
   165  }
   166  
   167  type LogError struct {
   168  	message string
   169  }
   170  
   171  func (e LogError) Error() string {
   172  	return e.message
   173  }
   174  
   175  func (l FilteredLogger) msg(msg interface{}) {
   176  	l.log(3, "msg", msg)
   177  }
   178  
   179  func (l FilteredLogger) msgf(msg string, args ...interface{}) {
   180  	l.log(3, "msg", fmt.Sprintf(msg, args...))
   181  }
   182  
   183  func (l FilteredLogger) Log(params ...interface{}) error {
   184  	return l.log(2, params...)
   185  }
   186  
   187  func (l FilteredLogger) log(skipFrames int, params ...interface{}) error {
   188  	// messages should be logged if any of these conditions are met:
   189  	// The log filtering level is info and verbosity checks match
   190  	// The log message priority is warning or higher
   191  	if l.currentLogLevel >= WARNING || (l.filterLevel == INFO &&
   192  		(l.currentLogLevel == l.filterLevel) &&
   193  		(l.currentVerbosityLevel <= l.verbosityLevel)) {
   194  		now := time.Now().UTC()
   195  		_, fileName, lineNumber, _ := runtime.Caller(skipFrames)
   196  		logParams := make([]interface{}, 0, 8)
   197  
   198  		logParams = append(logParams,
   199  			"level", LogLevelNames[l.currentLogLevel],
   200  			"timestamp", now.Format(logTimestampFormat),
   201  			"pos", fmt.Sprintf("%s:%d", filepath.Base(fileName), lineNumber),
   202  			"component", l.component,
   203  		)
   204  		if l.err != nil {
   205  			l.logger = klog.With(l.logger, "reason", l.err)
   206  		}
   207  		return klog.WithPrefix(l.logger, logParams...).Log(params...)
   208  	}
   209  	return nil
   210  }
   211  
   212  func (l FilteredVerbosityLogger) Log(params ...interface{}) error {
   213  	return l.filteredLogger.log(2, params...)
   214  }
   215  
   216  func (l FilteredVerbosityLogger) V(level int) *FilteredVerbosityLogger {
   217  	if level >= 0 {
   218  		l.filteredLogger.currentVerbosityLevel = level
   219  	}
   220  	return &l
   221  }
   222  
   223  func (l FilteredVerbosityLogger) Info(msg string) {
   224  	l.filteredLogger.Level(INFO).log(2, "msg", msg)
   225  }
   226  
   227  func (l FilteredVerbosityLogger) Infof(msg string, args ...interface{}) {
   228  	l.filteredLogger.log(2, "msg", fmt.Sprintf(msg, args...))
   229  }
   230  
   231  func (l FilteredVerbosityLogger) Object(obj LoggableObject) *FilteredVerbosityLogger {
   232  	l.filteredLogger.Object(obj)
   233  	return &l
   234  }
   235  
   236  func (l FilteredVerbosityLogger) Reason(err error) *FilteredVerbosityLogger {
   237  	l.filteredLogger.err = err
   238  	return &l
   239  }
   240  
   241  func (l FilteredVerbosityLogger) Verbosity(level int) bool {
   242  	return l.filteredLogger.Verbosity(level)
   243  }
   244  
   245  func (l FilteredLogger) Object(obj LoggableObject) *FilteredLogger {
   246  
   247  	name := obj.GetObjectMeta().GetName()
   248  	namespace := obj.GetObjectMeta().GetNamespace()
   249  	uid := obj.GetObjectMeta().GetUID()
   250  	kind := obj.GetObjectKind().GroupVersionKind().Kind
   251  
   252  	logParams := make([]interface{}, 0)
   253  	if namespace != "" {
   254  		logParams = append(logParams, "namespace", namespace)
   255  	}
   256  	logParams = append(logParams, "name", name)
   257  	logParams = append(logParams, "kind", kind)
   258  	logParams = append(logParams, "uid", uid)
   259  
   260  	l.with(logParams...)
   261  	return &l
   262  }
   263  
   264  func (l FilteredLogger) With(obj ...interface{}) *FilteredLogger {
   265  	l.logger = klog.With(l.logger, obj...)
   266  	return &l
   267  }
   268  
   269  func (l *FilteredLogger) with(obj ...interface{}) *FilteredLogger {
   270  	l.logger = klog.With(l.logger, obj...)
   271  	return l
   272  }
   273  
   274  func (l *FilteredLogger) SetLogLevel(filterLevel LogLevel) error {
   275  	if (filterLevel >= INFO) && (filterLevel <= FATAL) {
   276  		l.filterLevel = filterLevel
   277  		return nil
   278  	}
   279  	return fmt.Errorf("Log level %d does not exist", filterLevel)
   280  }
   281  
   282  func (l *FilteredLogger) SetVerbosityLevel(level int) error {
   283  	if level >= 0 {
   284  		l.verbosityLevel = level
   285  	} else {
   286  		return errors.New("Verbosity setting must not be negative")
   287  	}
   288  	return nil
   289  }
   290  
   291  // It would be consistent to return an error from this function, but
   292  // a multi-value function would break the primary use case: log.V(2).Info()....
   293  func (l FilteredLogger) V(level int) *FilteredVerbosityLogger {
   294  	if level >= 0 {
   295  		l.currentVerbosityLevel = level
   296  	}
   297  	return &FilteredVerbosityLogger{
   298  		filteredLogger: l,
   299  	}
   300  }
   301  
   302  func (l FilteredLogger) Verbosity(level int) bool {
   303  	return l.currentVerbosityLevel >= level
   304  }
   305  
   306  func (l FilteredLogger) Reason(err error) *FilteredLogger {
   307  	l.err = err
   308  	return &l
   309  }
   310  
   311  func (l FilteredLogger) Level(level LogLevel) *FilteredLogger {
   312  	l.currentLogLevel = level
   313  	return &l
   314  }
   315  
   316  func (l FilteredLogger) Info(msg string) {
   317  	l.Level(INFO).msg(msg)
   318  }
   319  
   320  func (l FilteredLogger) Infof(msg string, args ...interface{}) {
   321  	l.Level(INFO).msgf(msg, args...)
   322  }
   323  
   324  func (l FilteredLogger) Warning(msg string) {
   325  	l.Level(WARNING).msg(msg)
   326  }
   327  
   328  func (l FilteredLogger) Warningf(msg string, args ...interface{}) {
   329  	l.Level(WARNING).msgf(msg, args...)
   330  }
   331  
   332  func (l FilteredLogger) Error(msg string) {
   333  	l.Level(ERROR).msg(msg)
   334  }
   335  
   336  func (l FilteredLogger) Errorf(msg string, args ...interface{}) {
   337  	l.Level(ERROR).msgf(msg, args...)
   338  }
   339  
   340  func (l FilteredLogger) Critical(msg string) {
   341  	l.Level(FATAL).msg(msg)
   342  	panic(msg)
   343  }
   344  
   345  func (l FilteredLogger) Criticalf(msg string, args ...interface{}) {
   346  	l.Level(FATAL).msgf(msg, args...)
   347  }
   348  
   349  func LogLibvirtLogLine(logger *FilteredLogger, line string) {
   350  
   351  	if len(strings.TrimSpace(line)) == 0 {
   352  		return
   353  	}
   354  
   355  	fragments := strings.SplitN(line, ": ", 5)
   356  	if len(fragments) < 4 {
   357  		now := time.Now()
   358  		logger.logger.Log(
   359  			"level", "info",
   360  			"timestamp", now.Format(logTimestampFormat),
   361  			"component", logger.component,
   362  			"subcomponent", "libvirt",
   363  			"msg", line,
   364  		)
   365  		return
   366  	}
   367  	severity := strings.ToLower(strings.TrimSpace(fragments[2]))
   368  
   369  	if severity == "debug" {
   370  		severity = "info"
   371  	}
   372  
   373  	t, err := time.Parse(libvirtTimestampFormat, strings.TrimSpace(fragments[0]))
   374  	if err != nil {
   375  		fmt.Println(err)
   376  		return
   377  	}
   378  	thread := strings.TrimSpace(fragments[1])
   379  	pos := strings.TrimSpace(fragments[3])
   380  	msg := strings.TrimSpace(fragments[4])
   381  
   382  	//TODO: implement proper behavior for unsupported GA commands
   383  	// by either considering the GA version as unsupported or just don't
   384  	// send commands which not supported
   385  	if strings.Contains(msg, "unable to execute QEMU agent command") {
   386  		if logger.verbosityLevel < 4 {
   387  			return
   388  		}
   389  
   390  		severity = LogLevelNames[WARNING]
   391  	}
   392  
   393  	// check if we really got a position
   394  	isPos := false
   395  	if split := strings.Split(pos, ":"); len(split) == 2 {
   396  		if _, err := strconv.Atoi(split[1]); err == nil {
   397  			isPos = true
   398  		}
   399  	}
   400  
   401  	if !isPos {
   402  		msg = strings.TrimSpace(fragments[3] + ": " + fragments[4])
   403  		logger.logger.Log(
   404  			"level", severity,
   405  			"timestamp", t.Format(logTimestampFormat),
   406  			"component", logger.component,
   407  			"subcomponent", "libvirt",
   408  			"thread", thread,
   409  			"msg", msg,
   410  		)
   411  	} else {
   412  		logger.logger.Log(
   413  			"level", severity,
   414  			"timestamp", t.Format(logTimestampFormat),
   415  			"pos", pos,
   416  			"component", logger.component,
   417  			"subcomponent", "libvirt",
   418  			"thread", thread,
   419  			"msg", msg,
   420  		)
   421  	}
   422  }
   423  
   424  var qemuLogLines = ""
   425  
   426  func LogQemuLogLine(logger *FilteredLogger, line string) {
   427  
   428  	if len(strings.TrimSpace(line)) == 0 {
   429  		return
   430  	}
   431  
   432  	// Concat break lines to have full command in one log message
   433  	if strings.HasSuffix(line, "\\") {
   434  		qemuLogLines += line
   435  		return
   436  	}
   437  
   438  	if len(qemuLogLines) > 0 {
   439  		line = qemuLogLines + line
   440  		qemuLogLines = ""
   441  	}
   442  
   443  	now := time.Now()
   444  	logger.logger.Log(
   445  		"level", "info",
   446  		"timestamp", now.Format(logTimestampFormat),
   447  		"component", logger.component,
   448  		"subcomponent", "qemu",
   449  		"msg", line,
   450  	)
   451  }
   452
View as plain text