From 8ba5a2967998da6257a020e90f84de6862df55e1 Mon Sep 17 00:00:00 2001 From: Steve Kriss Date: Mon, 13 Nov 2017 15:57:40 -0800 Subject: [PATCH] add a logger that can be used within plugins to emit logs into Ark server Signed-off-by: Steve Kriss --- pkg/cmd/server/plugin/plugin.go | 14 ++++---- pkg/plugin/logger.go | 52 +++++++++++++++++++++++++++ pkg/util/logging/hclog_level_hook.go | 45 +++++++++++++++++++++++ pkg/util/logging/log_location_hook.go | 52 +++++++++++++++++++++++++-- 4 files changed, 154 insertions(+), 9 deletions(-) create mode 100644 pkg/plugin/logger.go create mode 100644 pkg/util/logging/hclog_level_hook.go diff --git a/pkg/cmd/server/plugin/plugin.go b/pkg/cmd/server/plugin/plugin.go index 3272f9ce2..ee7862c21 100644 --- a/pkg/cmd/server/plugin/plugin.go +++ b/pkg/cmd/server/plugin/plugin.go @@ -17,8 +17,6 @@ limitations under the License. package plugin import ( - "log" - plugin "github.com/hashicorp/go-plugin" "github.com/spf13/cobra" @@ -30,6 +28,8 @@ import ( ) func NewCommand() *cobra.Command { + logger := arkplugin.NewPluginLogger() + objectStores := map[string]cloudprovider.ObjectStore{ "aws": aws.NewObjectStore(), "gcp": gcp.NewObjectStore(), @@ -48,24 +48,24 @@ func NewCommand() *cobra.Command { Short: "INTERNAL COMMAND ONLY - not intended to be run directly by users", Run: func(c *cobra.Command, args []string) { if len(args) != 2 { - log.Fatalf("You must specify exactly two arguments, the plugin kind and the plugin name") + logger.Fatal("You must specify exactly two arguments, the plugin kind and the plugin name") } kind := args[0] name := args[1] - log.Printf("Running plugin command for kind=%s, name=%s", kind, name) + logger.Debugf("Running plugin command for kind=%s, name=%s", kind, name) switch kind { case "cloudprovider": objectStore, found := objectStores[name] if !found { - log.Fatalf("Unrecognized plugin name %q", name) + logger.Fatalf("Unrecognized plugin name %q", name) } blockStore, found := blockStores[name] if !found { - log.Fatalf("Unrecognized plugin name %q", name) + logger.Fatalf("Unrecognized plugin name %q", name) } plugin.Serve(&plugin.ServeConfig{ @@ -77,7 +77,7 @@ func NewCommand() *cobra.Command { GRPCServer: plugin.DefaultGRPCServer, }) default: - log.Fatalf("Unsupported plugin kind %q", kind) + logger.Fatalf("Unsupported plugin kind %q", kind) } }, } diff --git a/pkg/plugin/logger.go b/pkg/plugin/logger.go new file mode 100644 index 000000000..616a2eef2 --- /dev/null +++ b/pkg/plugin/logger.go @@ -0,0 +1,52 @@ +/* +Copyright 2017 the Heptio Ark contributors. + +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 plugin + +import ( + "github.com/sirupsen/logrus" + + "github.com/heptio/ark/pkg/util/logging" +) + +// NewPluginLogger returns a logger that is suitable for use within an +// Ark plugin. +func NewPluginLogger() logrus.FieldLogger { + logger := logrus.New() + + // we use the JSON formatter because go-plugin will parse incoming + // JSON on stderr and use it to create structured log entries. + logger.Formatter = &logrus.JSONFormatter{ + FieldMap: logrus.FieldMap{ + // this is the hclog-compatible message field + logrus.FieldKeyMsg: "@message", + }, + // Ark server already adds timestamps when emitting logs, so + // don't do it within the plugin. + DisableTimestamp: true, + } + + // set a logger name for the location hook which will signal to the Ark + // server logger that the location has been set within a hook. + logger.Hooks.Add((&logging.LogLocationHook{}).WithLoggerName("plugin")) + + // this hook adjusts the string representation of WarnLevel to "warn" + // rather than "warning" to make it parseable by go-plugin within the + // Ark server code + logger.Hooks.Add(&logging.HcLogLevelHook{}) + + return logger +} diff --git a/pkg/util/logging/hclog_level_hook.go b/pkg/util/logging/hclog_level_hook.go new file mode 100644 index 000000000..9b8772d76 --- /dev/null +++ b/pkg/util/logging/hclog_level_hook.go @@ -0,0 +1,45 @@ +/* +Copyright 2017 Heptio Inc. + +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 logging + +import ( + "github.com/sirupsen/logrus" +) + +// HcLogLevelHook adds an hclog-compatible field ("@level") containing +// the log level. Note that if you use this, you SHOULD NOT use +// logrus.JSONFormatter's FieldMap to set the level key to "@level" because +// that will result in the hclog-compatible info written here being +// overwritten. +type HcLogLevelHook struct{} + +func (h *HcLogLevelHook) Levels() []logrus.Level { + return logrus.AllLevels +} + +func (h *HcLogLevelHook) Fire(entry *logrus.Entry) error { + switch entry.Level { + // logrus uses "warning" to represent WarnLevel, + // which is not compatible with hclog's "warn". + case logrus.WarnLevel: + entry.Data["@level"] = "warn" + default: + entry.Data["@level"] = entry.Level.String() + } + + return nil +} diff --git a/pkg/util/logging/log_location_hook.go b/pkg/util/logging/log_location_hook.go index 784e3499b..6362a9471 100644 --- a/pkg/util/logging/log_location_hook.go +++ b/pkg/util/logging/log_location_hook.go @@ -24,11 +24,28 @@ import ( "github.com/sirupsen/logrus" ) -const logLocationField = "logSource" +const ( + logSourceField = "logSource" + logSourceSetMarkerField = "@logSourceSetBy" +) // LogLocationHook is a logrus hook that attaches location information // to log entries, i.e. the file and line number of the logrus log call. +// This hook is designed for use in both the Ark server and Ark plugin +// implementations. When triggered within a plugin, a marker field will +// be set on the log entry indicating that the location came from a plugin. +// The Ark server instance will not overwrite location information if +// it sees this marker. type LogLocationHook struct { + loggerName string +} + +// WithLoggerName gives the hook a name to use when setting the marker field +// on a log entry indicating the location has been recorded by a plugin. This +// should only be used when setting up a hook for a logger used in a plugin. +func (h *LogLocationHook) WithLoggerName(name string) *LogLocationHook { + h.loggerName = name + return h } func (h *LogLocationHook) Levels() []logrus.Level { @@ -60,9 +77,40 @@ func (h *LogLocationHook) Fire(entry *logrus.Entry) error { continue } - entry.Data[logLocationField] = fmt.Sprintf("%s:%d", frame.File, frame.Line) + // set the marker field if we're within a plugin indicating that + // the location comes from the plugin. + if h.loggerName != "" { + entry.Data[logSourceSetMarkerField] = h.loggerName + } + + // record the log statement location if we're within a plugin OR if + // we're in Ark server and not logging something that has the marker + // set (which would indicate the log statement is coming from a plugin). + if h.loggerName != "" || getLogSourceSetMarker(entry) == "" { + entry.Data[logSourceField] = fmt.Sprintf("%s:%d", frame.File, frame.Line) + } + + // if we're in the Ark server, remove the marker field since we don't + // want to record it in the actual log. + if h.loggerName == "" { + delete(entry.Data, logSourceSetMarkerField) + } + break } return nil } + +func getLogSourceSetMarker(entry *logrus.Entry) string { + nameVal, found := entry.Data[logSourceSetMarkerField] + if !found { + return "" + } + + if name, ok := nameVal.(string); ok { + return name + } + + return fmt.Sprintf("%s", nameVal) +}