From b6aae16394ba1a2fb9c0d727e6ad9cacfdaa9a40 Mon Sep 17 00:00:00 2001 From: Frank Mai Date: Wed, 3 Jun 2020 14:22:51 +0800 Subject: [PATCH] refactor(log): adjust the logging system - change the implementation of logr - adjust the log verbosity - adjust the log arguments --- api/v1alpha1/devicelink_webhook.go | 4 +- pkg/brain/index/devicelink_by_model.go | 2 +- pkg/brain/index/devicelink_by_node.go | 2 +- pkg/brain/predicate/model_changed.go | 4 +- pkg/brain/predicate/node_changed.go | 6 +- pkg/limb/index/devicelink_by_adaptor.go | 2 +- pkg/limb/predicate/devicelink_changed.go | 8 +- pkg/suctioncup/registration/server.go | 6 +- pkg/suctioncup/registration/socket_watcher.go | 4 +- pkg/util/log/logflag/logflag.go | 25 ++--- pkg/util/log/zap/logr.go | 105 ++++++++++++++++++ pkg/util/log/zap/zap.go | 36 ++++++ 12 files changed, 171 insertions(+), 33 deletions(-) create mode 100644 pkg/util/log/zap/logr.go create mode 100644 pkg/util/log/zap/zap.go diff --git a/api/v1alpha1/devicelink_webhook.go b/api/v1alpha1/devicelink_webhook.go index 1c6b5ba9..df4021ba 100644 --- a/api/v1alpha1/devicelink_webhook.go +++ b/api/v1alpha1/devicelink_webhook.go @@ -24,7 +24,7 @@ func (in *DeviceLink) SetupWebhookWithManager(mgr ctrl.Manager) error { var _ webhook.Defaulter = &DeviceLink{} func (in *DeviceLink) Default() { - deviceWebhookLog.V(0).Info("default", "name", in.Name) + deviceWebhookLog.V(4).Info("default", "name", in.Name) // fill `status.conditions` if it is empty if len(in.Status.Conditions) == 0 { @@ -47,7 +47,7 @@ var _ webhook.Validator = &DeviceLink{} // ValidateCreate implements webhook.Validator so a webhook will be registered for the type func (in *DeviceLink) ValidateCreate() error { - deviceWebhookLog.V(0).Info("validate create", "name", in.Name) + deviceWebhookLog.V(4).Info("validate create", "name", in.Name) var spec = in.Spec diff --git a/pkg/brain/index/devicelink_by_model.go b/pkg/brain/index/devicelink_by_model.go index 1713f8a2..52b1a592 100644 --- a/pkg/brain/index/devicelink_by_model.go +++ b/pkg/brain/index/devicelink_by_model.go @@ -20,7 +20,7 @@ func DeviceLinkByModelFunc(rawObj runtime.Object) []string { var crdName = model.GetCRDNameOfGroupVersionKind(link.Status.Model.GroupVersionKind()) if crdName != "" { - deviceLinkByModelIndexLog.V(0).Info("Index DeviceLink by Model", "crdName", crdName, "object", object.GetNamespacedName(link)) + deviceLinkByModelIndexLog.V(5).Info("Indexed", "crdName", crdName, "object", object.GetNamespacedName(link)) return []string{crdName} } return nil diff --git a/pkg/brain/index/devicelink_by_node.go b/pkg/brain/index/devicelink_by_node.go index 26a169b5..43350097 100644 --- a/pkg/brain/index/devicelink_by_node.go +++ b/pkg/brain/index/devicelink_by_node.go @@ -19,7 +19,7 @@ func DeviceLinkByNodeFunc(rawObj runtime.Object) []string { var nodeName = link.Status.NodeName if nodeName != "" { - deviceLinkByNodeIndexLog.V(0).Info("Index DeviceLink by Node", "nodeName", nodeName, "object", object.GetNamespacedName(link)) + deviceLinkByNodeIndexLog.V(5).Info("Indexed", "nodeName", nodeName, "object", object.GetNamespacedName(link)) return []string{nodeName} } return nil diff --git a/pkg/brain/predicate/model_changed.go b/pkg/brain/predicate/model_changed.go index fea73b73..0f7c76dc 100644 --- a/pkg/brain/predicate/model_changed.go +++ b/pkg/brain/predicate/model_changed.go @@ -30,13 +30,13 @@ func (ModelChangedPredicate) Update(e event.UpdateEvent) bool { // handles when deleting if object.IsDeleted(e.MetaNew) { - modelChangedPredicateLog.V(0).Info("Accept UpdateEvent as deleted object", "key", object.GetNamespacedName(e.MetaOld)) + modelChangedPredicateLog.V(5).Info("Accept UpdateEvent as deleted object", "key", object.GetNamespacedName(e.MetaOld)) return true } // handles when it's not backward compatible if !isBackwardCompatibleCRDVersions(crdOld.Spec.Versions, crdNew.Spec.Versions) { - modelChangedPredicateLog.V(0).Info("Accept UpdateEvent as bad backward compatible", "key", object.GetNamespacedName(e.MetaOld)) + modelChangedPredicateLog.V(5).Info("Accept UpdateEvent as bad backward compatible", "key", object.GetNamespacedName(e.MetaOld)) return true } diff --git a/pkg/brain/predicate/node_changed.go b/pkg/brain/predicate/node_changed.go index 9a19f5f4..ab0c024a 100644 --- a/pkg/brain/predicate/node_changed.go +++ b/pkg/brain/predicate/node_changed.go @@ -27,7 +27,7 @@ func (NodeChangedPredicate) Update(e event.UpdateEvent) bool { // handles when deleting if object.IsDeleted(e.MetaNew) { - nodeChangedPredicateLog.V(0).Info("Accept UpdateEvent as deleted object", "key", object.GetNamespacedName(e.MetaOld)) + nodeChangedPredicateLog.V(5).Info("Accept UpdateEvent as deleted object", "key", object.GetNamespacedName(e.MetaOld)) return true } @@ -36,13 +36,13 @@ func (NodeChangedPredicate) Update(e event.UpdateEvent) bool { // handles when changing addresses if diffNodeAddresses(nodeOld.Status.Addresses, nodeNew.Status.Addresses) { - nodeChangedPredicateLog.V(0).Info("Accept UpdateEvent as diffed addresses", "key", object.GetNamespacedName(e.MetaOld)) + nodeChangedPredicateLog.V(5).Info("Accept UpdateEvent as diffed addresses", "key", object.GetNamespacedName(e.MetaOld)) return true } // handles when changing nodes if diffNodeConditions(nodeOld.Status.Conditions, nodeNew.Status.Conditions) { - nodeChangedPredicateLog.V(0).Info("Accept UpdateEvent as diffed conditions", "key", object.GetNamespacedName(e.MetaOld)) + nodeChangedPredicateLog.V(5).Info("Accept UpdateEvent as diffed conditions", "key", object.GetNamespacedName(e.MetaOld)) return true } diff --git a/pkg/limb/index/devicelink_by_adaptor.go b/pkg/limb/index/devicelink_by_adaptor.go index d1e8a998..bb97aa68 100644 --- a/pkg/limb/index/devicelink_by_adaptor.go +++ b/pkg/limb/index/devicelink_by_adaptor.go @@ -19,7 +19,7 @@ func DeviceLinkByAdaptorFunc(rawObj runtime.Object) []string { var adaptorName = link.Status.AdaptorName if adaptorName != "" { - deviceLinkByAdaptorIndexLog.V(0).Info("Index DeviceLink by Adaptor", "adaptorName", adaptorName, "object", object.GetNamespacedName(link)) + deviceLinkByAdaptorIndexLog.V(5).Info("Indexed", "adaptorName", adaptorName, "object", object.GetNamespacedName(link)) return []string{adaptorName} } return nil diff --git a/pkg/limb/predicate/devicelink_changed.go b/pkg/limb/predicate/devicelink_changed.go index 0643114e..73cf04e5 100644 --- a/pkg/limb/predicate/devicelink_changed.go +++ b/pkg/limb/predicate/devicelink_changed.go @@ -30,7 +30,7 @@ func (p DeviceLinkChangedPredicate) Create(e event.CreateEvent) bool { // handles if the requested node if p.NodeName == dl.Spec.Adaptor.Node { - deviceLinkChangedPredicateLog.V(0).Info("Accept CreateEvent as requested the same node", "key", object.GetNamespacedName(e.Meta)) + deviceLinkChangedPredicateLog.V(5).Info("Accept CreateEvent as requested the same node", "key", object.GetNamespacedName(e.Meta)) return true } @@ -67,14 +67,14 @@ func (p DeviceLinkChangedPredicate) Update(e event.UpdateEvent) bool { // handles if the object is requesting the same node if p.NodeName == dlNew.Status.NodeName { - deviceLinkChangedPredicateLog.V(0).Info("Accept UpdateEvent as the object is requesting the same node", "key", object.GetNamespacedName(e.MetaNew)) + deviceLinkChangedPredicateLog.V(5).Info("Accept UpdateEvent as the object is requesting the same node", "key", object.GetNamespacedName(e.MetaNew)) return true } // handles if the object has requested the same node previously if p.NodeName == dlOld.Status.NodeName { // NB(thxCode) help the reconciling logic to close the previous connection - deviceLinkChangedPredicateLog.V(0).Info("Accept UpdateEvent as the object has requested the same node previously", "key", object.GetNamespacedName(e.MetaOld)) + deviceLinkChangedPredicateLog.V(5).Info("Accept UpdateEvent as the object has requested the same node previously", "key", object.GetNamespacedName(e.MetaOld)) return true } @@ -95,7 +95,7 @@ func (p DeviceLinkChangedPredicate) Generic(e event.GenericEvent) bool { // handles if the requested node if p.NodeName == dl.Spec.Adaptor.Node { - deviceLinkChangedPredicateLog.V(0).Info("Accept GenericEvent as requested the same node", "key", object.GetNamespacedName(e.Meta)) + deviceLinkChangedPredicateLog.V(5).Info("Accept GenericEvent as requested the same node", "key", object.GetNamespacedName(e.Meta)) return true } diff --git a/pkg/suctioncup/registration/server.go b/pkg/suctioncup/registration/server.go index 1bba6f5d..2df8e60e 100644 --- a/pkg/suctioncup/registration/server.go +++ b/pkg/suctioncup/registration/server.go @@ -138,15 +138,15 @@ func cleanup(socketDir string) error { continue } if pi.IsDir() { - log.V(0).Info("Ignore dir", "path", path) + log.V(4).Info("Ignore dir", "path", path) continue } if strings.HasPrefix(pi.Name(), ".") { - log.V(0).Info("Ignore ignoring file", "path", path) + log.V(4).Info("Ignore ignoring file", "path", path) continue } if pi.Mode()&os.ModeSocket == 0 { - log.V(0).Info("Ignore non socket file", "path", path) + log.V(4).Info("Ignore non socket file", "path", path) continue } err = os.RemoveAll(path) diff --git a/pkg/suctioncup/registration/socket_watcher.go b/pkg/suctioncup/registration/socket_watcher.go index 4aa83f52..78d380a6 100644 --- a/pkg/suctioncup/registration/socket_watcher.go +++ b/pkg/suctioncup/registration/socket_watcher.go @@ -46,7 +46,7 @@ func (w *socketWatcher) Watch(adp adaptor.Adaptor) error { // at the same time, that loop ensures that all links will be updated. w.notifier.NoticeAdaptorRegistered(adp.GetName()) - w.log.V(0).Info("Watching path", "path", path) + w.log.V(2).Info("Watching path", "path", path) return nil } @@ -65,7 +65,7 @@ loop: w.notifier.NoticeAdaptorUnregistered(adp.GetName()) w.set.Delete(adp.GetEndpoint()) _ = w.fsWatcher.Remove(path) - w.log.V(0).Info("Unwatching path", "path", path) + w.log.V(2).Info("Unwatching path", "path", path) } } case err, ok := <-w.fsWatcher.Errors: diff --git a/pkg/util/log/logflag/logflag.go b/pkg/util/log/logflag/logflag.go index ac92402c..025af6eb 100644 --- a/pkg/util/log/logflag/logflag.go +++ b/pkg/util/log/logflag/logflag.go @@ -2,29 +2,26 @@ package logflag import ( flag "github.com/spf13/pflag" - uberzap "go.uber.org/zap" - uberzapcore "go.uber.org/zap/zapcore" ctrl "sigs.k8s.io/controller-runtime" - "sigs.k8s.io/controller-runtime/pkg/log/zap" + + "github.com/rancher/octopus/pkg/util/log/zap" ) type loggingT struct { - verbosity int - enableBriefLog bool + verbosity int + asJSON bool + inProduction bool } -var logging = loggingT{verbosity: 1} +var logging = loggingT{} func AddFlags(fs *flag.FlagSet) { - fs.IntVar(&logging.verbosity, "v", logging.verbosity, "The level of log verbosity: debug(0) > info(1) > warn(2) > error(3) > panic(4).") - fs.BoolVar(&logging.enableBriefLog, "enable-brief-log", logging.enableBriefLog, "Print brief json-style log on console.") + fs.IntVar(&logging.verbosity, "v", logging.verbosity, "The level of log verbosity, a higher verbosity level means a log message is less important(more details). The log verbosity is following the klog's conventions: https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md.") + fs.BoolVar(&logging.asJSON, "log-as-json", logging.asJSON, "Print brief json-style log.") + fs.BoolVar(&logging.inProduction, "log-in-production", logging.inProduction, "Use the reasonable production logging configuration of zap.") } func Configure() { - level := uberzap.NewAtomicLevelAt(uberzapcore.Level(int8(logging.verbosity) - 1)) - - ctrl.SetLogger(zap.New( - zap.UseDevMode(!logging.enableBriefLog), - zap.Level(&level), - )) + var logger = zap.NewLogger(logging.asJSON, logging.inProduction) + ctrl.SetLogger(zap.WrapAsLogr(logging.verbosity, logger)) } diff --git a/pkg/util/log/zap/logr.go b/pkg/util/log/zap/logr.go new file mode 100644 index 00000000..1dc629fe --- /dev/null +++ b/pkg/util/log/zap/logr.go @@ -0,0 +1,105 @@ +package zap + +import ( + "fmt" + + "github.com/go-logr/logr" + "go.uber.org/zap" +) + +type nullLogger struct { +} + +func (nullLogger) Enabled() bool { return false } + +func (nullLogger) Info(_ string, _ ...interface{}) {} + +type infoLogger struct { + z *zap.Logger +} + +func (l *infoLogger) Enabled() bool { return true } + +func (l *infoLogger) Info(msg string, keysAndValues ...interface{}) { + l.z.Info(msg, handleFields(keysAndValues)...) +} + +type zapLogger struct { + v int + z *zap.Logger +} + +func (l *zapLogger) Enabled() bool { return true } + +func (l *zapLogger) Info(msg string, keysAndValues ...interface{}) { + l.z.Info(msg, handleFields(keysAndValues)...) +} + +func (l *zapLogger) Error(err error, msg string, keysAndValues ...interface{}) { + l.z.Error(msg, handleFields(keysAndValues, zap.Error(err))...) +} + +func (l *zapLogger) V(level int) logr.InfoLogger { + if 0 <= level && level <= l.v { + return &infoLogger{ + z: l.z, + } + } + + return nullLogger{} +} + +func (l *zapLogger) WithValues(keysAndValues ...interface{}) logr.Logger { + return &zapLogger{ + v: l.v, + z: l.z.With(handleFields(keysAndValues)...), + } +} + +func (l *zapLogger) WithName(name string) logr.Logger { + return &zapLogger{ + v: l.v, + z: l.z.Named(name), + } +} + +func handleFields(args []interface{}, additional ...zap.Field) []zap.Field { + var argSize = len(args) + if argSize == 0 { + return additional + } + + var fields = make([]zap.Field, 0, argSize/2+len(additional)) + for i := 0; i < argSize; { + var field zap.Field + + var arg = args[i] + switch a := arg.(type) { + case zap.Field: + field = a + case string: + if i+1 < argSize { + field = zap.Any(a, args[i+1]) + i++ + } else { + field = zap.Any("#key$", a) + } + case error: + field = zap.Any(fmt.Sprintf("#err%d", i+1), a) + default: + field = zap.Any(fmt.Sprintf("#key%d", i+1), a) + } + + fields = append(fields, field) + i++ + } + return append(fields, additional...) +} + +// WrapAsLogr wraps a Zap log as logr.Logger. +func WrapAsLogr(v int, z *zap.Logger) logr.Logger { + return &zapLogger{ + v: v, + z: z, + } +} diff --git a/pkg/util/log/zap/zap.go b/pkg/util/log/zap/zap.go new file mode 100644 index 00000000..370a2590 --- /dev/null +++ b/pkg/util/log/zap/zap.go @@ -0,0 +1,36 @@ +package zap + +import ( + "os" + "time" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func NewLogger(asJSON, inProduction bool) *zap.Logger { + var zapLevel = zap.InfoLevel + var zapWriteSyncer = zapcore.AddSync(os.Stderr) + var zapOptions = []zap.Option{ + zap.AddCallerSkip(1), + zap.AddStacktrace(zap.ErrorLevel), + zap.ErrorOutput(zapWriteSyncer), + } + + var zapEncoderConfig = zap.NewDevelopmentEncoderConfig() + if inProduction { + zapEncoderConfig = zap.NewProductionEncoderConfig() + zapOptions = append(zapOptions, + zap.WrapCore(func(core zapcore.Core) zapcore.Core { + return zapcore.NewSampler(core, time.Second, 100, 100) + }), + ) + } + + var zapEncoder = zapcore.NewConsoleEncoder(zapEncoderConfig) + if asJSON { + zapEncoder = zapcore.NewJSONEncoder(zapEncoderConfig) + } + + return zap.New(zapcore.NewCore(zapEncoder, zapWriteSyncer, zapLevel), zapOptions...) +}