diff --git a/cmd/ela-controller/OWNERS b/cmd/ela-controller/OWNERS new file mode 100644 index 000000000000..39dc9812b82b --- /dev/null +++ b/cmd/ela-controller/OWNERS @@ -0,0 +1,6 @@ +# The OWNERS file is used by prow to automatically merge approved PRs. + +approvers: +- mattmoor +- grantr +- tcnghia diff --git a/cmd/ela-controller/main.go b/cmd/ela-controller/main.go index 3eb75a1ab2e7..f63885eccb15 100644 --- a/cmd/ela-controller/main.go +++ b/cmd/ela-controller/main.go @@ -141,10 +141,10 @@ func main() { // Build all of our controllers, with the clients constructed above. // Add new controllers to this array. controllers := []controller.Interface{ - configuration.NewController(kubeClient, elaClient, buildClient, kubeInformerFactory, elaInformerFactory, cfg, *controllerConfig), - revision.NewController(kubeClient, elaClient, kubeInformerFactory, elaInformerFactory, buildInformerFactory, cfg, &revControllerConfig), + configuration.NewController(kubeClient, elaClient, buildClient, kubeInformerFactory, elaInformerFactory, cfg, *controllerConfig, logger), + revision.NewController(kubeClient, elaClient, kubeInformerFactory, elaInformerFactory, buildInformerFactory, cfg, &revControllerConfig, logger), route.NewController(kubeClient, elaClient, kubeInformerFactory, elaInformerFactory, cfg, *controllerConfig, autoscaleEnableScaleToZero, logger), - service.NewController(kubeClient, elaClient, kubeInformerFactory, elaInformerFactory, cfg, *controllerConfig), + service.NewController(kubeClient, elaClient, kubeInformerFactory, elaInformerFactory, cfg, *controllerConfig, logger), } go kubeInformerFactory.Start(stopCh) diff --git a/pkg/controller/BUILD.bazel b/pkg/controller/BUILD.bazel index f49d433669e5..a0447a917d9b 100644 --- a/pkg/controller/BUILD.bazel +++ b/pkg/controller/BUILD.bazel @@ -17,8 +17,10 @@ go_library( "//pkg/client/clientset/versioned:go_default_library", "//pkg/client/clientset/versioned/scheme:go_default_library", "//pkg/client/informers/externalversions:go_default_library", + "//pkg/logging:go_default_library", + "//pkg/logging/logkey:go_default_library", "//vendor/github.com/ghodss/yaml:go_default_library", - "//vendor/github.com/golang/glog:go_default_library", + "//vendor/go.uber.org/zap:go_default_library", "//vendor/k8s.io/api/core/v1:go_default_library", "//vendor/k8s.io/apimachinery/pkg/api/errors:go_default_library", "//vendor/k8s.io/apimachinery/pkg/apis/meta/v1:go_default_library", diff --git a/pkg/controller/configuration/BUILD.bazel b/pkg/controller/configuration/BUILD.bazel index aa1326d24414..573787f0a625 100644 --- a/pkg/controller/configuration/BUILD.bazel +++ b/pkg/controller/configuration/BUILD.bazel @@ -12,9 +12,11 @@ go_library( "//pkg/client/informers/externalversions:go_default_library", "//pkg/client/listers/ela/v1alpha1:go_default_library", "//pkg/controller:go_default_library", + "//pkg/logging:go_default_library", + "//pkg/logging/logkey:go_default_library", "//vendor/github.com/elafros/build/pkg/apis/build/v1alpha1:go_default_library", "//vendor/github.com/elafros/build/pkg/client/clientset/versioned:go_default_library", - "//vendor/github.com/golang/glog:go_default_library", + "//vendor/go.uber.org/zap:go_default_library", "//vendor/k8s.io/api/core/v1:go_default_library", "//vendor/k8s.io/apimachinery/pkg/api/errors:go_default_library", "//vendor/k8s.io/apimachinery/pkg/apis/meta/v1:go_default_library", @@ -43,6 +45,7 @@ go_test( "//vendor/github.com/elafros/build/pkg/apis/build/v1alpha1:go_default_library", "//vendor/github.com/elafros/build/pkg/client/clientset/versioned/fake:go_default_library", "//vendor/github.com/google/go-cmp/cmp:go_default_library", + "//vendor/go.uber.org/zap:go_default_library", "//vendor/k8s.io/api/core/v1:go_default_library", "//vendor/k8s.io/apimachinery/pkg/apis/meta/v1:go_default_library", "//vendor/k8s.io/apimachinery/pkg/runtime:go_default_library", diff --git a/pkg/controller/configuration/configuration.go b/pkg/controller/configuration/configuration.go index 2963232cf842..c3920cd56606 100644 --- a/pkg/controller/configuration/configuration.go +++ b/pkg/controller/configuration/configuration.go @@ -17,6 +17,7 @@ limitations under the License. package configuration import ( + "context" "fmt" buildv1alpha1 "github.com/elafros/build/pkg/apis/build/v1alpha1" @@ -27,7 +28,9 @@ import ( informers "github.com/elafros/elafros/pkg/client/informers/externalversions" listers "github.com/elafros/elafros/pkg/client/listers/ela/v1alpha1" "github.com/elafros/elafros/pkg/controller" - "github.com/golang/glog" + "github.com/elafros/elafros/pkg/logging" + "github.com/elafros/elafros/pkg/logging/logkey" + "go.uber.org/zap" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -62,7 +65,8 @@ func NewController( kubeInformerFactory kubeinformers.SharedInformerFactory, elaInformerFactory informers.SharedInformerFactory, config *rest.Config, - controllerConfig controller.Config) controller.Interface { + controllerConfig controller.Config, + logger *zap.SugaredLogger) controller.Interface { // obtain references to a shared index informer for the Configuration // and Revision type. @@ -71,14 +75,14 @@ func NewController( controller := &Controller{ Base: controller.NewBase(kubeClientSet, elaClientSet, kubeInformerFactory, - elaInformerFactory, informer.Informer(), controllerAgentName, "Configurations"), + elaInformerFactory, informer.Informer(), controllerAgentName, "Configurations", logger), buildClientSet: buildClientSet, lister: informer.Lister(), synced: informer.Informer().HasSynced, revisionsSynced: revisionInformer.Informer().HasSynced, } - glog.Info("Setting up event handlers") + controller.Logger.Info("Setting up event handlers") revisionInformer.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{ AddFunc: controller.addRevisionEvent, UpdateFunc: controller.updateRevisionEvent, @@ -95,6 +99,11 @@ func (c *Controller) Run(threadiness int, stopCh <-chan struct{}) error { []cache.InformerSynced{c.synced, c.revisionsSynced}, c.syncHandler, "Configuration") } +// loggerWithConfigInfo enriches the logs with configuration name and namespace. +func loggerWithConfigInfo(logger *zap.SugaredLogger, ns string, name string) *zap.SugaredLogger { + return logger.With(zap.String(logkey.Namespace, ns), zap.String(logkey.Configuration, name)) +} + // syncHandler compares the actual state with the desired, and attempts to // converge the two. It then updates the Status block of the Configuration // resource with the current status of the resource. @@ -106,6 +115,8 @@ func (c *Controller) syncHandler(key string) error { return nil } + logger := loggerWithConfigInfo(c.Logger, namespace, name) + // Get the Configuration resource with this namespace/name config, err := c.lister.Configurations(namespace).Get(name) if err != nil { @@ -124,12 +135,12 @@ func (c *Controller) syncHandler(key string) error { // Configuration business logic if config.GetGeneration() == config.Status.ObservedGeneration { // TODO(vaikas): Check to see if Status.LatestCreatedRevisionName is ready and update Status.LatestReady - glog.Infof("Skipping reconcile since already reconciled %d == %d", + logger.Infof("Skipping reconcile since already reconciled %d == %d", config.Spec.Generation, config.Status.ObservedGeneration) return nil } - glog.Infof("Running reconcile Configuration for %s\n%+v\n%+v\n", + logger.Infof("Running reconcile Configuration for %s\n%+v\n%+v\n", config.Name, config, config.Spec.RevisionTemplate) spec := config.Spec.RevisionTemplate.Spec controllerRef := controller.NewConfigurationControllerRef(config) @@ -146,11 +157,11 @@ func (c *Controller) syncHandler(key string) error { build.OwnerReferences = append(build.OwnerReferences, *controllerRef) created, err := c.buildClientSet.BuildV1alpha1().Builds(build.Namespace).Create(build) if err != nil { - glog.Errorf("Failed to create Build:\n%+v\n%s", build, err) + logger.Errorf("Failed to create Build:\n%+v\n%s", build, err) c.Recorder.Eventf(config, corev1.EventTypeWarning, "CreationFailed", "Failed to create Build %q: %v", build.Name, err) return err } - glog.Infof("Created Build:\n%+v", created.Name) + logger.Infof("Created Build:\n%+v", created.Name) c.Recorder.Eventf(config, corev1.EventTypeNormal, "Created", "Created Build %q", created.Name) spec.BuildName = created.Name } @@ -164,7 +175,7 @@ func (c *Controller) syncHandler(key string) error { created, err := revClient.Get(revName, metav1.GetOptions{}) if err != nil { if !errors.IsNotFound(err) { - glog.Errorf("Revisions Get for %q failed: %s", revName, err) + logger.Error("Revisions Get failed", zap.Error(err), zap.String(logkey.Revision, revName)) return err } @@ -194,14 +205,14 @@ func (c *Controller) syncHandler(key string) error { created, err = revClient.Create(rev) if err != nil { - glog.Errorf("Failed to create Revision:\n%+v\n%s", rev, err) + logger.Errorf("Failed to create Revision:\n%+v\n%s", rev, err) c.Recorder.Eventf(config, corev1.EventTypeWarning, "CreationFailed", "Failed to create Revision %q: %v", rev.Name, err) return err } c.Recorder.Eventf(config, corev1.EventTypeNormal, "Created", "Created Revision %q", rev.Name) - glog.Infof("Created Revision:\n%+v", created) + logger.Infof("Created Revision:\n%+v", created) } else { - glog.Infof("Revision already created %s: %s", created.ObjectMeta.Name, err) + logger.Infof("Revision already created %s: %s", created.ObjectMeta.Name, err) } // Update the Status of the configuration with the latest generation that // we just reconciled against so we don't keep generating revisions. @@ -210,10 +221,10 @@ func (c *Controller) syncHandler(key string) error { config.Status.LatestCreatedRevisionName = created.ObjectMeta.Name config.Status.ObservedGeneration = config.Spec.Generation - glog.Infof("Updating the configuration status:\n%+v", config) + logger.Infof("Updating the configuration status:\n%+v", config) if _, err = c.updateStatus(config); err != nil { - glog.Errorf("Failed to update the configuration %s", err) + logger.Error("Failed to update the configuration", zap.Error(err)) return err } @@ -253,16 +264,18 @@ func (c *Controller) addRevisionEvent(obj interface{}) { return } + logger := loggerWithConfigInfo(c.Logger, namespace, configName).With(zap.String(logkey.Revision, revisionName)) + ctx := logging.WithLogger(context.TODO(), logger) + config, err := c.lister.Configurations(namespace).Get(configName) if err != nil { - glog.Errorf("Error fetching configuration '%s/%s' upon revision becoming ready: %v", - namespace, configName, err) + logger.Error("Error fetching configuration upon revision becoming ready", zap.Error(err)) return } if revision.Name != config.Status.LatestCreatedRevisionName { // The revision isn't the latest created one, so ignore this event. - glog.Infof("Revision %q is not the latest created one", revisionName) + logger.Info("Revision is not the latest created one") return } @@ -270,32 +283,30 @@ func (c *Controller) addRevisionEvent(obj interface{}) { config = config.DeepCopy() if !revision.Status.IsReady() { - glog.Infof("Revision %q of configuration %q is not ready", revisionName, config.Name) + logger.Infof("Revision %q of configuration %q is not ready", revisionName, config.Name) //add LatestRevision condition to be false with the status from the revision - c.markConfigurationLatestRevisionStatus(config, revision) + c.markConfigurationLatestRevisionStatus(ctx, config, revision) if _, err := c.updateStatus(config); err != nil { - glog.Errorf("Error updating configuration '%s/%s': %v", - namespace, configName, err) + logger.Error("Error updating configuration", zap.Error(err)) } c.Recorder.Eventf(config, corev1.EventTypeNormal, "LatestRevisionUpdate", "Latest revision of configuration is not ready") } else { - glog.Infof("Revision %q is ready", revisionName) + logger.Info("Revision is ready") alreadyReady := config.Status.IsReady() if !alreadyReady { - c.markConfigurationReady(config, revision) + c.markConfigurationReady(ctx, config, revision) } - glog.Infof("Setting LatestReadyRevisionName of Configuration %q to revision %q", + logger.Infof("Setting LatestReadyRevisionName of Configuration %q to revision %q", config.Name, revision.Name) config.Status.LatestReadyRevisionName = revision.Name if _, err := c.updateStatus(config); err != nil { - glog.Errorf("Error updating configuration '%s/%s': %v", - namespace, configName, err) + logger.Error("Error updating configuration", zap.Error(err)) } if !alreadyReady { c.Recorder.Eventf(config, corev1.EventTypeNormal, "ConfigurationReady", @@ -324,8 +335,10 @@ func getLatestRevisionStatusCondition(revision *v1alpha1.Revision) *v1alpha1.Rev // Mark ConfigurationConditionReady of Configuration ready as the given latest // created revision is ready. func (c *Controller) markConfigurationReady( + ctx context.Context, config *v1alpha1.Configuration, revision *v1alpha1.Revision) { - glog.Infof("Marking Configuration %q ready", config.Name) + logger := logging.FromContext(ctx) + logger.Info("Marking Configuration ready") config.Status.RemoveCondition(v1alpha1.ConfigurationConditionLatestRevisionReady) config.Status.SetCondition( &v1alpha1.ConfigurationCondition{ @@ -338,11 +351,13 @@ func (c *Controller) markConfigurationReady( // Mark ConfigurationConditionLatestRevisionReady of Configuration to false with the status // from the revision func (c *Controller) markConfigurationLatestRevisionStatus( + ctx context.Context, config *v1alpha1.Configuration, revision *v1alpha1.Revision) { + logger := logging.FromContext(ctx) config.Status.RemoveCondition(v1alpha1.ConfigurationConditionReady) cond := getLatestRevisionStatusCondition(revision) if cond == nil { - glog.Infof("Revision status is not updated yet") + logger.Info("Revision status is not updated yet") return } config.Status.SetCondition( diff --git a/pkg/controller/configuration/configuration_test.go b/pkg/controller/configuration/configuration_test.go index f84f9ecb8206..733d87a707ae 100644 --- a/pkg/controller/configuration/configuration_test.go +++ b/pkg/controller/configuration/configuration_test.go @@ -32,6 +32,7 @@ import ( "time" "github.com/google/go-cmp/cmp" + "go.uber.org/zap" corev1 "k8s.io/api/core/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/runtime" @@ -151,6 +152,7 @@ func newTestController(t *testing.T, elaObjects ...runtime.Object) ( elaInformer, &rest.Config{}, ctrl.Config{}, + zap.NewNop().Sugar(), ).(*Controller) return diff --git a/pkg/controller/controller.go b/pkg/controller/controller.go index 8887f05450c7..65ee5ea2d1f9 100644 --- a/pkg/controller/controller.go +++ b/pkg/controller/controller.go @@ -23,7 +23,8 @@ import ( clientset "github.com/elafros/elafros/pkg/client/clientset/versioned" elascheme "github.com/elafros/elafros/pkg/client/clientset/versioned/scheme" informers "github.com/elafros/elafros/pkg/client/informers/externalversions" - "github.com/golang/glog" + "github.com/elafros/elafros/pkg/logging/logkey" + "go.uber.org/zap" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/util/runtime" "k8s.io/apimachinery/pkg/util/wait" @@ -74,6 +75,13 @@ type Base struct { // time, and makes it easy to ensure we are never processing the same item // simultaneously in two different workers. WorkQueue workqueue.RateLimitingInterface + + // Sugared logger is easier to use but is not as performant as the + // raw logger. In performance critical paths, call logger.Desugar() + // and use the returned raw logger instead. In addition to the + // performance benefits, raw logger also preserves type-safety at + // the expense of slightly greater verbosity. + Logger *zap.SugaredLogger } // NewBase instantiates a new instance of Base implementing @@ -85,12 +93,16 @@ func NewBase( elaInformerFactory informers.SharedInformerFactory, informer cache.SharedIndexInformer, controllerAgentName string, - workQueueName string) *Base { + workQueueName string, + logger *zap.SugaredLogger) *Base { + + // Enrich the logs with controller name + logger = logger.Named(controllerAgentName).With(zap.String(logkey.ControllerType, controllerAgentName)) // Create event broadcaster - glog.V(4).Info("Creating event broadcaster") + logger.Debug("Creating event broadcaster") eventBroadcaster := record.NewBroadcaster() - eventBroadcaster.StartLogging(glog.Infof) + eventBroadcaster.StartLogging(logger.Named("event-broadcaster").Infof) eventBroadcaster.StartRecordingToSink(&typedcorev1.EventSinkImpl{Interface: kubeClientSet.CoreV1().Events("")}) recorder := eventBroadcaster.NewRecorder(scheme.Scheme, corev1.EventSource{Component: controllerAgentName}) @@ -101,6 +113,7 @@ func NewBase( ElaInformerFactory: elaInformerFactory, Recorder: recorder, WorkQueue: workqueue.NewNamedRateLimitingQueue(workqueue.DefaultControllerRateLimiter(), workQueueName), + Logger: logger, } // Set up an event handler for when the resource types of interest change @@ -140,10 +153,11 @@ func (c *Base) RunController( defer runtime.HandleCrash() defer c.WorkQueue.ShutDown() - glog.Infof("Starting %s controller", controllerName) + logger := c.Logger + logger.Infof("Starting %s controller", controllerName) // Wait for the caches to be synced before starting workers - glog.Info("Waiting for informer caches to sync") + logger.Info("Waiting for informer caches to sync") for i, synced := range informersSynced { if ok := cache.WaitForCacheSync(stopCh, synced); !ok { return fmt.Errorf("failed to wait for cache at index %v to sync", i) @@ -151,7 +165,7 @@ func (c *Base) RunController( } // Launch workers to process Revision resources - glog.Info("Starting workers") + logger.Info("Starting workers") for i := 0; i < threadiness; i++ { go wait.Until(func() { for c.processNextWorkItem(syncHandler) { @@ -159,9 +173,9 @@ func (c *Base) RunController( }, time.Second, stopCh) } - glog.Info("Started workers") + logger.Info("Started workers") <-stopCh - glog.Info("Shutting down workers") + logger.Info("Shutting down workers") return nil } @@ -207,7 +221,7 @@ func (c *Base) processNextWorkItem(syncHandler func(string) error) bool { // Finally, if no error occurs we Forget this item so it does not // get queued again until another change happens. c.WorkQueue.Forget(obj) - glog.Infof("Successfully synced %q", key) + c.Logger.Infof("Successfully synced %q", key) return nil }(obj) diff --git a/pkg/controller/names.go b/pkg/controller/names.go index 2bcdede86cbc..0e0deff16bc9 100644 --- a/pkg/controller/names.go +++ b/pkg/controller/names.go @@ -17,9 +17,12 @@ limitations under the License. package controller import ( - "log" + "context" + + "go.uber.org/zap" "github.com/elafros/elafros/pkg/apis/ela/v1alpha1" + "github.com/elafros/elafros/pkg/logging" corev1 "k8s.io/api/core/v1" apierrs "k8s.io/apimachinery/pkg/api/errors" @@ -81,18 +84,19 @@ func GetRevisionHeaderNamespace() string { return "Elafros-Namespace" } -func GetOrCreateRevisionNamespace(ns string, c clientset.Interface) (string, error) { - return GetOrCreateNamespace(GetElaNamespaceName(ns), c) +func GetOrCreateRevisionNamespace(ctx context.Context, ns string, c clientset.Interface) (string, error) { + return GetOrCreateNamespace(ctx, GetElaNamespaceName(ns), c) } -func GetOrCreateNamespace(namespace string, c clientset.Interface) (string, error) { +func GetOrCreateNamespace(ctx context.Context, namespace string, c clientset.Interface) (string, error) { _, err := c.Core().Namespaces().Get(namespace, metav1.GetOptions{}) if err != nil { + logger := logging.FromContext(ctx) if !apierrs.IsNotFound(err) { - log.Printf("namespace: %v, unable to get namespace due to error: %v", namespace, err) + logger.Errorf("namespace: %v, unable to get namespace due to error: %v", namespace, err) return "", err } - log.Printf("namespace: %v, not found. Creating...", namespace) + logger.Infof("namespace: %v, not found. Creating...", namespace) nsObj := &corev1.Namespace{ ObjectMeta: metav1.ObjectMeta{ Name: namespace, @@ -101,7 +105,7 @@ func GetOrCreateNamespace(namespace string, c clientset.Interface) (string, erro } _, err := c.Core().Namespaces().Create(nsObj) if err != nil { - log.Printf("Unexpected error while creating namespace: %v", err) + logger.Error("Unexpected error while creating namespace", zap.Error(err)) return "", err } } diff --git a/pkg/controller/revision/BUILD.bazel b/pkg/controller/revision/BUILD.bazel index ed747bec250c..60c5509d12c7 100644 --- a/pkg/controller/revision/BUILD.bazel +++ b/pkg/controller/revision/BUILD.bazel @@ -21,14 +21,16 @@ go_library( "//pkg/client/informers/externalversions:go_default_library", "//pkg/client/listers/ela/v1alpha1:go_default_library", "//pkg/controller:go_default_library", + "//pkg/logging:go_default_library", + "//pkg/logging/logkey:go_default_library", "//pkg/queue:go_default_library", "//vendor/github.com/elafros/build/pkg/apis/build/v1alpha1:go_default_library", "//vendor/github.com/elafros/build/pkg/client/informers/externalversions:go_default_library", - "//vendor/github.com/golang/glog:go_default_library", "//vendor/github.com/google/go-containerregistry/name:go_default_library", "//vendor/github.com/google/go-containerregistry/v1/remote:go_default_library", "//vendor/github.com/josephburnett/k8sflag/pkg/k8sflag:go_default_library", "//vendor/github.com/mattmoor/k8schain:go_default_library", + "//vendor/go.uber.org/zap:go_default_library", "//vendor/k8s.io/api/apps/v1:go_default_library", "//vendor/k8s.io/api/core/v1:go_default_library", "//vendor/k8s.io/apimachinery/pkg/api/errors:go_default_library", @@ -69,6 +71,7 @@ go_test( "//vendor/github.com/google/go-containerregistry/v1:go_default_library", "//vendor/github.com/google/go-containerregistry/v1/random:go_default_library", "//vendor/github.com/josephburnett/k8sflag/pkg/k8sflag:go_default_library", + "//vendor/go.uber.org/zap:go_default_library", "//vendor/k8s.io/api/apps/v1:go_default_library", "//vendor/k8s.io/api/core/v1:go_default_library", "//vendor/k8s.io/apimachinery/pkg/api/errors:go_default_library", diff --git a/pkg/controller/revision/ela_pod.go b/pkg/controller/revision/ela_pod.go index a388fc5f8381..2277aa75f3ae 100644 --- a/pkg/controller/revision/ela_pod.go +++ b/pkg/controller/revision/ela_pod.go @@ -41,7 +41,7 @@ const ( varLogVolumeName = "varlog" ) -func hasHttpPath(p *corev1.Probe) bool { +func hasHTTPPath(p *corev1.Probe) bool { if p == nil { return false } @@ -105,7 +105,7 @@ func MakeElaPodSpec( // // TODO(tcnghia): Fail validation webhook when users specify their // own port in readiness checks. - if hasHttpPath(elaContainer.ReadinessProbe) { + if hasHTTPPath(elaContainer.ReadinessProbe) { elaContainer.ReadinessProbe.Handler.HTTPGet.Port = intstr.FromInt(queue.RequestQueuePort) } diff --git a/pkg/controller/revision/ela_resource.go b/pkg/controller/revision/ela_resource.go index 9161265d01d9..adde735b3e25 100644 --- a/pkg/controller/revision/ela_resource.go +++ b/pkg/controller/revision/ela_resource.go @@ -13,6 +13,7 @@ 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 revision import ( diff --git a/pkg/controller/revision/revision.go b/pkg/controller/revision/revision.go index a7144bfba08b..2bf72f447aff 100644 --- a/pkg/controller/revision/revision.go +++ b/pkg/controller/revision/revision.go @@ -17,17 +17,19 @@ limitations under the License. package revision import ( + "context" "fmt" - "log" "net/http" "strings" "time" "github.com/elafros/elafros/pkg/apis/ela" + "github.com/elafros/elafros/pkg/logging" + "github.com/elafros/elafros/pkg/logging/logkey" "github.com/josephburnett/k8sflag/pkg/k8sflag" + "go.uber.org/zap" clientset "github.com/elafros/elafros/pkg/client/clientset/versioned" - "github.com/golang/glog" appsv1 "k8s.io/api/apps/v1" corev1 "k8s.io/api/core/v1" kubeinformers "k8s.io/client-go/informers" @@ -58,7 +60,7 @@ const ( fluentdContainerName string = "fluentd-proxy" queueContainerName string = "queue-proxy" // queueSidecarName set by -queueSidecarName flag - queueHttpPortName string = "queue-http-port" + queueHTTPPortName string = "queue-http-port" requestQueueContainerName string = "request-queue" @@ -77,14 +79,6 @@ var ( elaPodMaxSurge = intstr.IntOrString{Type: intstr.Int, IntVal: 1} ) -// Helper to make sure we log error messages returned by Reconcile(). -func printErr(err error) error { - if err != nil { - log.Printf("Logging error: %s", err) - } - return err -} - type resolver interface { Resolve(*appsv1.Deployment) error } @@ -156,7 +150,8 @@ func NewController( elaInformerFactory informers.SharedInformerFactory, buildInformerFactory buildinformers.SharedInformerFactory, config *rest.Config, - controllerConfig *ControllerConfig) controller.Interface { + controllerConfig *ControllerConfig, + logger *zap.SugaredLogger) controller.Interface { // obtain references to a shared index informer for the Revision and Endpoint type. informer := elaInformerFactory.Elafros().V1alpha1().Revisions() @@ -165,7 +160,7 @@ func NewController( controller := &Controller{ Base: controller.NewBase(kubeClientSet, elaClientSet, kubeInformerFactory, - elaInformerFactory, informer.Informer(), controllerAgentName, "Revisions"), + elaInformerFactory, informer.Informer(), controllerAgentName, "Revisions", logger), lister: informer.Lister(), synced: informer.Informer().HasSynced, endpointsSynced: endpointsInformer.Informer().HasSynced, @@ -174,7 +169,7 @@ func NewController( controllerConfig: controllerConfig, } - glog.Info("Setting up event handlers") + controller.Logger.Info("Setting up event handlers") // Obtain a reference to a shared index informer for the Build type. buildInformer := buildInformerFactory.Build().V1alpha1().Builds() buildInformer.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{ @@ -204,6 +199,11 @@ func (c *Controller) Run(threadiness int, stopCh <-chan struct{}) error { c.syncHandler, "Revision") } +// loggerWithRevisionInfo enriches the logs with revision name and namespace. +func loggerWithRevisionInfo(logger *zap.SugaredLogger, ns string, name string) *zap.SugaredLogger { + return logger.With(zap.String(logkey.Namespace, ns), zap.String(logkey.Revision, name)) +} + // syncHandler compares the actual state with the desired, and attempts to // converge the two. It then updates the Status block of the Revision resource // with the current status of the resource. @@ -214,7 +214,10 @@ func (c *Controller) syncHandler(key string) error { runtime.HandleError(fmt.Errorf("invalid resource key: %s", key)) return nil } - log.Printf("Running reconcile Revision for %q:%q\n", namespace, name) + + logger := loggerWithRevisionInfo(c.Logger, namespace, name) + ctx := logging.WithLogger(context.TODO(), logger) + logger.Info("Running reconcile Revision") // Get the Revision resource with this namespace/name rev, err := c.lister.Revisions(namespace).Get(name) @@ -231,15 +234,15 @@ func (c *Controller) syncHandler(key string) error { rev = rev.DeepCopy() if err := c.updateRevisionLoggingURL(rev); err != nil { - glog.Errorf("Error updating the revisions logging url: %s", err) + logger.Error("Error updating the revisions logging url", zap.Error(err)) return err } if rev.Spec.BuildName != "" { if done, failed := isBuildDone(rev); !done { if alreadyTracked := c.buildtracker.Track(rev); !alreadyTracked { - if err := c.markRevisionBuilding(rev); err != nil { - glog.Errorf("Error recording the BuildSucceeded=Unknown condition: %s", err) + if err := c.markRevisionBuilding(ctx, rev); err != nil { + logger.Error("Error recording the BuildSucceeded=Unknown condition", zap.Error(err)) return err } } @@ -254,19 +257,22 @@ func (c *Controller) syncHandler(key string) error { } } - ns, err := controller.GetOrCreateRevisionNamespace(namespace, c.KubeClientSet) + _, err = controller.GetOrCreateRevisionNamespace(ctx, namespace, c.KubeClientSet) if err != nil { - log.Printf("Failed to create namespace: %s", err) - panic("Failed to create namespace") + logger.Panic("Failed to create namespace", zap.Error(err)) } - log.Printf("Namespace %q validated to exist, moving on", ns) + logger.Info("Namespace validated to exist, moving on") - return c.reconcileWithImage(rev, namespace) + return c.reconcileWithImage(ctx, rev, namespace) } // reconcileWithImage handles enqueued messages that have an image. -func (c *Controller) reconcileWithImage(rev *v1alpha1.Revision, ns string) error { - return printErr(c.reconcileOnceBuilt(rev, ns)) +func (c *Controller) reconcileWithImage(ctx context.Context, rev *v1alpha1.Revision, ns string) error { + err := c.reconcileOnceBuilt(ctx, rev, ns) + if err != nil { + logging.FromContext(ctx).Error("Reconcile once build failed", zap.Error(err)) + } + return err } func (c *Controller) updateRevisionLoggingURL(rev *v1alpha1.Revision) error { @@ -307,8 +313,9 @@ func isBuildDone(rev *v1alpha1.Revision) (done, failed bool) { return false, false } -func (c *Controller) markRevisionReady(rev *v1alpha1.Revision) error { - glog.Infof("Marking Revision %q ready", rev.Name) +func (c *Controller) markRevisionReady(ctx context.Context, rev *v1alpha1.Revision) error { + logger := logging.FromContext(ctx) + logger.Info("Marking Revision ready") rev.Status.SetCondition( &v1alpha1.RevisionCondition{ Type: v1alpha1.RevisionConditionReady, @@ -319,8 +326,9 @@ func (c *Controller) markRevisionReady(rev *v1alpha1.Revision) error { return err } -func (c *Controller) markRevisionFailed(rev *v1alpha1.Revision) error { - glog.Infof("Marking Revision %q failed", rev.Name) +func (c *Controller) markRevisionFailed(ctx context.Context, rev *v1alpha1.Revision) error { + logger := logging.FromContext(ctx) + logger.Info("Marking Revision failed") reason, message := "ServiceTimeout", "Timed out waiting for a service endpoint to become ready" rev.Status.SetCondition( &v1alpha1.RevisionCondition{ @@ -340,9 +348,10 @@ func (c *Controller) markRevisionFailed(rev *v1alpha1.Revision) error { return err } -func (c *Controller) markRevisionBuilding(rev *v1alpha1.Revision) error { +func (c *Controller) markRevisionBuilding(ctx context.Context, rev *v1alpha1.Revision) error { + logger := logging.FromContext(ctx) reason := "Building" - glog.Infof("Marking Revision %q %s", rev.Name, reason) + logger.Infof("Marking Revision %s", reason) rev.Status.SetCondition( &v1alpha1.RevisionCondition{ Type: v1alpha1.RevisionConditionBuildSucceeded, @@ -453,10 +462,12 @@ func (c *Controller) addBuildEvent(obj interface{}) { namespace, name := splitKey(k) rev, err := c.lister.Revisions(namespace).Get(name) if err != nil { - glog.Errorf("Error fetching revision %q/%q upon build completion: %v", namespace, name, err) + c.Logger.Error("Error fetching revision upon build completion", + zap.String(logkey.Namespace, namespace), zap.String(logkey.Revision, name), zap.Error(err)) } if err := c.markBuildComplete(rev, cond); err != nil { - glog.Errorf("Error marking build completion for %q/%q: %v", namespace, name, err) + c.Logger.Error("Error marking build completion", + zap.String(logkey.Namespace, namespace), zap.String(logkey.Revision, name), zap.Error(err)) } } @@ -478,10 +489,11 @@ func (c *Controller) addDeploymentProgressEvent(obj interface{}) { //Get the handle of Revision in context revName := deployment.Name namespace := deployment.Namespace + logger := loggerWithRevisionInfo(c.Logger, namespace, revName) rev, err := c.lister.Revisions(namespace).Get(revName) if err != nil { - glog.Errorf("Error fetching revision '%s/%s': %v", namespace, revName, err) + logger.Error("Error fetching revision", zap.Error(err)) return } //Set the revision condition reason to ProgressDeadlineExceeded @@ -493,9 +505,9 @@ func (c *Controller) addDeploymentProgressEvent(obj interface{}) { Message: fmt.Sprintf("Unable to create pods for more than %d seconds.", progressDeadlineSeconds), }) - glog.Infof("Updating status with the following conditions %+v", rev.Status.Conditions) + logger.Infof("Updating status with the following conditions %+v", rev.Status.Conditions) if _, err := c.updateStatus(rev); err != nil { - glog.Errorf("Error recording revision completion: %s", err) + logger.Error("Error recording revision completion", zap.Error(err)) return } c.Recorder.Eventf(rev, corev1.EventTypeNormal, "ProgressDeadlineExceeded", "Revision %s not ready due to Deployment timeout", revName) @@ -516,10 +528,12 @@ func (c *Controller) addEndpointsEvent(obj interface{}) { if revName == "" { return } + logger := loggerWithRevisionInfo(c.Logger, namespace, revName) + ctx := logging.WithLogger(context.TODO(), logger) rev, err := c.lister.Revisions(namespace).Get(revName) if err != nil { - glog.Errorf("Error fetching revision '%s/%s': %v", namespace, revName, err) + logger.Error("Error fetching revision", zap.Error(err)) return } @@ -538,9 +552,9 @@ func (c *Controller) addEndpointsEvent(obj interface{}) { rev = rev.DeepCopy() if getIsServiceReady(endpoint) { - glog.Infof("Endpoint %q is ready", eName) - if err := c.markRevisionReady(rev); err != nil { - glog.Errorf("Error marking revision ready for '%s/%s': %v", namespace, revName, err) + logger.Infof("Endpoint %q is ready", eName) + if err := c.markRevisionReady(ctx, rev); err != nil { + logger.Error("Error marking revision ready", zap.Error(err)) return } c.Recorder.Eventf(rev, corev1.EventTypeNormal, "RevisionReady", "Revision becomes ready upon endpoint %q becoming ready", endpoint.Name) @@ -552,8 +566,8 @@ func (c *Controller) addEndpointsEvent(obj interface{}) { return } - if err := c.markRevisionFailed(rev); err != nil { - glog.Errorf("Error marking revision failed for '%s/%s': %v", namespace, revName, err) + if err := c.markRevisionFailed(ctx, rev); err != nil { + logger.Error("Error marking revision failed", zap.Error(err)) return } c.Recorder.Eventf(rev, corev1.EventTypeWarning, "RevisionFailed", "Revision did not become ready due to endpoint %q", endpoint.Name) @@ -565,50 +579,51 @@ func (c *Controller) updateEndpointsEvent(old, new interface{}) { } // reconcileOnceBuilt handles enqueued messages that have an image. -func (c *Controller) reconcileOnceBuilt(rev *v1alpha1.Revision, ns string) error { +func (c *Controller) reconcileOnceBuilt(ctx context.Context, rev *v1alpha1.Revision, ns string) error { + logger := logging.FromContext(ctx) accessor, err := meta.Accessor(rev) if err != nil { - log.Printf("Failed to get metadata: %s", err) - panic("Failed to get metadata") + logger.Panic("Failed to get metadata", zap.Error(err)) } deletionTimestamp := accessor.GetDeletionTimestamp() - log.Printf("Check the deletionTimestamp: %s\n", deletionTimestamp) + logger.Infof("Check the deletionTimestamp: %s\n", deletionTimestamp) elaNS := controller.GetElaNamespaceName(rev.Namespace) if deletionTimestamp == nil && rev.Spec.ServingState == v1alpha1.RevisionServingStateActive { - log.Printf("Creating or reconciling resources for %s\n", rev.Name) - return c.createK8SResources(rev, elaNS) + logger.Info("Creating or reconciling resources for revision") + return c.createK8SResources(ctx, rev, elaNS) } - return c.deleteK8SResources(rev, elaNS) + return c.deleteK8SResources(ctx, rev, elaNS) } -func (c *Controller) deleteK8SResources(rev *v1alpha1.Revision, ns string) error { - log.Printf("Deleting the resources for %s\n", rev.Name) - err := c.deleteDeployment(rev, ns) +func (c *Controller) deleteK8SResources(ctx context.Context, rev *v1alpha1.Revision, ns string) error { + logger := logging.FromContext(ctx) + logger.Info("Deleting the resources for revision") + err := c.deleteDeployment(ctx, rev, ns) if err != nil { - log.Printf("Failed to delete a deployment: %s", err) + logger.Error("Failed to delete a deployment", zap.Error(err)) } - log.Printf("Deleted deployment") + logger.Info("Deleted deployment") - err = c.deleteAutoscalerDeployment(rev) + err = c.deleteAutoscalerDeployment(ctx, rev) if err != nil { - log.Printf("Failed to delete autoscaler Deployment: %s", err) + logger.Error("Failed to delete autoscaler Deployment", zap.Error(err)) } - log.Printf("Deleted autoscaler Deployment") + logger.Info("Deleted autoscaler Deployment") - err = c.deleteAutoscalerService(rev) + err = c.deleteAutoscalerService(ctx, rev) if err != nil { - log.Printf("Failed to delete autoscaler Service: %s", err) + logger.Error("Failed to delete autoscaler Service", zap.Error(err)) } - log.Printf("Deleted autoscaler Service") + logger.Info("Deleted autoscaler Service") - err = c.deleteService(rev, ns) + err = c.deleteService(ctx, rev, ns) if err != nil { - log.Printf("Failed to delete k8s service: %s", err) + logger.Error("Failed to delete k8s service", zap.Error(err)) } - log.Printf("Deleted service") + logger.Info("Deleted service") // And the deployment is no longer ready, so update that rev.Status.SetCondition( @@ -617,39 +632,40 @@ func (c *Controller) deleteK8SResources(rev *v1alpha1.Revision, ns string) error Status: corev1.ConditionFalse, Reason: "Inactive", }) - log.Printf("Updating status with the following conditions %+v", rev.Status.Conditions) + logger.Infof("Updating status with the following conditions %+v", rev.Status.Conditions) if _, err := c.updateStatus(rev); err != nil { - log.Printf("Error recording inactivation of revision: %s", err) + logger.Error("Error recording inactivation of revision", zap.Error(err)) return err } return nil } -func (c *Controller) createK8SResources(rev *v1alpha1.Revision, ns string) error { +func (c *Controller) createK8SResources(ctx context.Context, rev *v1alpha1.Revision, ns string) error { + logger := logging.FromContext(ctx) // Fire off a Deployment.. - if err := c.reconcileDeployment(rev, ns); err != nil { - log.Printf("Failed to create a deployment: %s", err) + if err := c.reconcileDeployment(ctx, rev, ns); err != nil { + logger.Error("Failed to create a deployment", zap.Error(err)) return err } // Autoscale the service - if err := c.reconcileAutoscalerDeployment(rev); err != nil { - log.Printf("Failed to create autoscaler Deployment: %s", err) + if err := c.reconcileAutoscalerDeployment(ctx, rev); err != nil { + logger.Error("Failed to create autoscaler Deployment", zap.Error(err)) } - if err := c.reconcileAutoscalerService(rev); err != nil { - log.Printf("Failed to create autoscaler Service: %s", err) + if err := c.reconcileAutoscalerService(ctx, rev); err != nil { + logger.Error("Failed to create autoscaler Service", zap.Error(err)) } if c.controllerConfig.EnableVarLogCollection { - if err := c.reconcileFluentdConfigMap(rev); err != nil { - log.Printf("Failed to create fluent config map: %s", err) + if err := c.reconcileFluentdConfigMap(ctx, rev); err != nil { + logger.Error("Failed to create fluent config map", zap.Error(err)) } } // Create k8s service - serviceName, err := c.reconcileService(rev, ns) + serviceName, err := c.reconcileService(ctx, rev, ns) if err != nil { - log.Printf("Failed to create k8s service: %s", err) + logger.Error("Failed to create k8s service", zap.Error(err)) } else { rev.Status.ServiceName = serviceName } @@ -683,49 +699,51 @@ func (c *Controller) createK8SResources(rev *v1alpha1.Revision, ns string) error Status: corev1.ConditionUnknown, Reason: reason, }) - log.Printf("Updating status with the following conditions %+v", rev.Status.Conditions) + logger.Infof("Updating status with the following conditions %+v", rev.Status.Conditions) if _, err := c.updateStatus(rev); err != nil { - log.Printf("Error recording build completion: %s", err) + logger.Error("Error recording build completion", zap.Error(err)) return err } return nil } -func (c *Controller) deleteDeployment(rev *v1alpha1.Revision, ns string) error { +func (c *Controller) deleteDeployment(ctx context.Context, rev *v1alpha1.Revision, ns string) error { + logger := logging.FromContext(ctx) deploymentName := controller.GetRevisionDeploymentName(rev) dc := c.KubeClientSet.AppsV1().Deployments(ns) if _, err := dc.Get(deploymentName, metav1.GetOptions{}); err != nil && apierrs.IsNotFound(err) { return nil } - log.Printf("Deleting Deployment %q", deploymentName) + logger.Infof("Deleting Deployment %q", deploymentName) tmp := metav1.DeletePropagationForeground err := dc.Delete(deploymentName, &metav1.DeleteOptions{ PropagationPolicy: &tmp, }) if err != nil && !apierrs.IsNotFound(err) { - log.Printf("deployments.Delete for %q failed: %s", deploymentName, err) + logger.Errorf("deployments.Delete for %q failed: %s", deploymentName, err) return err } return nil } -func (c *Controller) reconcileDeployment(rev *v1alpha1.Revision, ns string) error { +func (c *Controller) reconcileDeployment(ctx context.Context, rev *v1alpha1.Revision, ns string) error { + logger := logging.FromContext(ctx) dc := c.KubeClientSet.AppsV1().Deployments(ns) // First, check if deployment exists already. deploymentName := controller.GetRevisionDeploymentName(rev) if _, err := dc.Get(deploymentName, metav1.GetOptions{}); err != nil { if !apierrs.IsNotFound(err) { - log.Printf("deployments.Get for %q failed: %s", deploymentName, err) + logger.Errorf("deployments.Get for %q failed: %s", deploymentName, err) return err } - log.Printf("Deployment %q doesn't exist, creating", deploymentName) + logger.Infof("Deployment %q doesn't exist, creating", deploymentName) } else { // TODO(mattmoor): Compare the deployments and update if it has changed // out from under us. - log.Printf("Found existing deployment %q", deploymentName) + logger.Infof("Found existing deployment %q", deploymentName) return nil } @@ -741,7 +759,7 @@ func (c *Controller) reconcileDeployment(rev *v1alpha1.Revision, ns string) erro // Resolve tag image references to digests. if err := c.resolver.Resolve(deployment); err != nil { - glog.Errorf("Error resolving deployment: %v", err) + logger.Error("Error resolving deployment", zap.Error(err)) rev.Status.SetCondition( &v1alpha1.RevisionCondition{ Type: v1alpha1.RevisionConditionContainerHealthy, @@ -757,7 +775,7 @@ func (c *Controller) reconcileDeployment(rev *v1alpha1.Revision, ns string) erro Message: err.Error(), }) if _, err := c.updateStatus(rev); err != nil { - log.Printf("Error recording resolution problem: %s", err) + logger.Error("Error recording resolution problem", zap.Error(err)) return err } return err @@ -767,165 +785,172 @@ func (c *Controller) reconcileDeployment(rev *v1alpha1.Revision, ns string) erro deployment.Spec.ProgressDeadlineSeconds = new(int32) *deployment.Spec.ProgressDeadlineSeconds = progressDeadlineSeconds - log.Printf("Creating Deployment: %q", deployment.Name) + logger.Infof("Creating Deployment: %q", deployment.Name) _, createErr := dc.Create(deployment) return createErr } -func (c *Controller) deleteService(rev *v1alpha1.Revision, ns string) error { +func (c *Controller) deleteService(ctx context.Context, rev *v1alpha1.Revision, ns string) error { + logger := logging.FromContext(ctx) sc := c.KubeClientSet.Core().Services(ns) serviceName := controller.GetElaK8SServiceNameForRevision(rev) - log.Printf("Deleting service %q", serviceName) + logger.Infof("Deleting service %q", serviceName) tmp := metav1.DeletePropagationForeground err := sc.Delete(serviceName, &metav1.DeleteOptions{ PropagationPolicy: &tmp, }) if err != nil && !apierrs.IsNotFound(err) { - log.Printf("service.Delete for %q failed: %s", serviceName, err) + logger.Errorf("service.Delete for %q failed: %s", serviceName, err) return err } return nil } -func (c *Controller) reconcileService(rev *v1alpha1.Revision, ns string) (string, error) { +func (c *Controller) reconcileService(ctx context.Context, rev *v1alpha1.Revision, ns string) (string, error) { + logger := logging.FromContext(ctx) sc := c.KubeClientSet.Core().Services(ns) serviceName := controller.GetElaK8SServiceNameForRevision(rev) if _, err := sc.Get(serviceName, metav1.GetOptions{}); err != nil { if !apierrs.IsNotFound(err) { - log.Printf("services.Get for %q failed: %s", serviceName, err) + logger.Errorf("services.Get for %q failed: %s", serviceName, err) return "", err } - log.Printf("serviceName %q doesn't exist, creating", serviceName) + logger.Infof("serviceName %q doesn't exist, creating", serviceName) } else { // TODO(vaikas): Check that the service is legit and matches what we expect // to have there. - log.Printf("Found existing service %q", serviceName) + logger.Infof("Found existing service %q", serviceName) return serviceName, nil } controllerRef := controller.NewRevisionControllerRef(rev) service := MakeRevisionK8sService(rev, ns) service.OwnerReferences = append(service.OwnerReferences, *controllerRef) - log.Printf("Creating service: %q", service.Name) + logger.Infof("Creating service: %q", service.Name) _, err := sc.Create(service) return serviceName, err } -func (c *Controller) reconcileFluentdConfigMap(rev *v1alpha1.Revision) error { +func (c *Controller) reconcileFluentdConfigMap(ctx context.Context, rev *v1alpha1.Revision) error { + logger := logging.FromContext(ctx) ns := rev.Namespace cmc := c.KubeClientSet.Core().ConfigMaps(ns) _, err := cmc.Get(fluentdConfigMapName, metav1.GetOptions{}) if err != nil { if !apierrs.IsNotFound(err) { - log.Printf("configmaps.Get for %q failed: %s", fluentdConfigMapName, err) + logger.Errorf("configmaps.Get for %q failed: %s", fluentdConfigMapName, err) return err } - log.Printf("ConfigMap %q doesn't exist, creating", fluentdConfigMapName) + logger.Infof("ConfigMap %q doesn't exist, creating", fluentdConfigMapName) } else { - log.Printf("Found existing ConfigMap %q", fluentdConfigMapName) + logger.Infof("Found existing ConfigMap %q", fluentdConfigMapName) return nil } controllerRef := controller.NewRevisionControllerRef(rev) configMap := MakeFluentdConfigMap(rev, ns) configMap.OwnerReferences = append(configMap.OwnerReferences, *controllerRef) - log.Printf("Creating configmap: %q", configMap.Name) + logger.Infof("Creating configmap: %q", configMap.Name) _, err = cmc.Create(configMap) return err } -func (c *Controller) deleteAutoscalerService(rev *v1alpha1.Revision) error { +func (c *Controller) deleteAutoscalerService(ctx context.Context, rev *v1alpha1.Revision) error { + logger := logging.FromContext(ctx) autoscalerName := controller.GetRevisionAutoscalerName(rev) sc := c.KubeClientSet.Core().Services(AutoscalerNamespace) if _, err := sc.Get(autoscalerName, metav1.GetOptions{}); err != nil && apierrs.IsNotFound(err) { return nil } - log.Printf("Deleting autoscaler Service %q", autoscalerName) + logger.Infof("Deleting autoscaler Service %q", autoscalerName) tmp := metav1.DeletePropagationForeground err := sc.Delete(autoscalerName, &metav1.DeleteOptions{ PropagationPolicy: &tmp, }) if err != nil && !apierrs.IsNotFound(err) { - log.Printf("Autoscaler Service delete for %q failed: %s", autoscalerName, err) + logger.Errorf("Autoscaler Service delete for %q failed: %s", autoscalerName, err) return err } return nil } -func (c *Controller) reconcileAutoscalerService(rev *v1alpha1.Revision) error { +func (c *Controller) reconcileAutoscalerService(ctx context.Context, rev *v1alpha1.Revision) error { + logger := logging.FromContext(ctx) autoscalerName := controller.GetRevisionAutoscalerName(rev) sc := c.KubeClientSet.Core().Services(AutoscalerNamespace) _, err := sc.Get(autoscalerName, metav1.GetOptions{}) if err != nil { if !apierrs.IsNotFound(err) { - log.Printf("Autoscaler Service get for %q failed: %s", autoscalerName, err) + logger.Errorf("Autoscaler Service get for %q failed: %s", autoscalerName, err) return err } - log.Printf("Autoscaler Service %q doesn't exist, creating", autoscalerName) + logger.Infof("Autoscaler Service %q doesn't exist, creating", autoscalerName) } else { - log.Printf("Found existing autoscaler Service %q", autoscalerName) + logger.Infof("Found existing autoscaler Service %q", autoscalerName) return nil } controllerRef := controller.NewRevisionControllerRef(rev) service := MakeElaAutoscalerService(rev) service.OwnerReferences = append(service.OwnerReferences, *controllerRef) - log.Printf("Creating autoscaler Service: %q", service.Name) + logger.Infof("Creating autoscaler Service: %q", service.Name) _, err = sc.Create(service) return err } -func (c *Controller) deleteAutoscalerDeployment(rev *v1alpha1.Revision) error { +func (c *Controller) deleteAutoscalerDeployment(ctx context.Context, rev *v1alpha1.Revision) error { + logger := logging.FromContext(ctx) autoscalerName := controller.GetRevisionAutoscalerName(rev) dc := c.KubeClientSet.AppsV1().Deployments(AutoscalerNamespace) _, err := dc.Get(autoscalerName, metav1.GetOptions{}) if err != nil && apierrs.IsNotFound(err) { return nil } - log.Printf("Deleting autoscaler Deployment %q", autoscalerName) + logger.Infof("Deleting autoscaler Deployment %q", autoscalerName) tmp := metav1.DeletePropagationForeground err = dc.Delete(autoscalerName, &metav1.DeleteOptions{ PropagationPolicy: &tmp, }) if err != nil && !apierrs.IsNotFound(err) { - log.Printf("Autoscaler Deployment delete for %q failed: %s", autoscalerName, err) + logger.Errorf("Autoscaler Deployment delete for %q failed: %s", autoscalerName, err) return err } return nil } -func (c *Controller) reconcileAutoscalerDeployment(rev *v1alpha1.Revision) error { +func (c *Controller) reconcileAutoscalerDeployment(ctx context.Context, rev *v1alpha1.Revision) error { + logger := logging.FromContext(ctx) autoscalerName := controller.GetRevisionAutoscalerName(rev) dc := c.KubeClientSet.AppsV1().Deployments(AutoscalerNamespace) _, err := dc.Get(autoscalerName, metav1.GetOptions{}) if err != nil { if !apierrs.IsNotFound(err) { - log.Printf("Autoscaler Deployment get for %q failed: %s", autoscalerName, err) + logger.Errorf("Autoscaler Deployment get for %q failed: %s", autoscalerName, err) return err } - log.Printf("Autoscaler Deployment %q doesn't exist, creating", autoscalerName) + logger.Infof("Autoscaler Deployment %q doesn't exist, creating", autoscalerName) } else { - log.Printf("Found existing autoscaler Deployment %q", autoscalerName) + logger.Infof("Found existing autoscaler Deployment %q", autoscalerName) return nil } controllerRef := controller.NewRevisionControllerRef(rev) deployment := MakeElaAutoscalerDeployment(rev, c.controllerConfig.AutoscalerImage) deployment.OwnerReferences = append(deployment.OwnerReferences, *controllerRef) - log.Printf("Creating autoscaler Deployment: %q", deployment.Name) + logger.Infof("Creating autoscaler Deployment: %q", deployment.Name) _, err = dc.Create(deployment) return err } -func (c *Controller) removeFinalizers(rev *v1alpha1.Revision, ns string) error { - log.Printf("Removing finalizers for %q\n", rev.Name) +func (c *Controller) removeFinalizers(ctx context.Context, rev *v1alpha1.Revision, ns string) error { + logger := logging.FromContext(ctx) + logger.Infof("Removing finalizers for %q\n", rev.Name) accessor, err := meta.Accessor(rev) if err != nil { - log.Printf("Failed to get metadata: %s", err) - panic("Failed to get metadata") + logger.Panic("Failed to get metadata", zap.Error(err)) } finalizers := accessor.GetFinalizers() for i, v := range finalizers { @@ -936,7 +961,7 @@ func (c *Controller) removeFinalizers(rev *v1alpha1.Revision, ns string) error { accessor.SetFinalizers(finalizers) prClient := c.ElaClientSet.ElafrosV1alpha1().Revisions(rev.Namespace) prClient.Update(rev) - log.Printf("The finalizer 'controller' is removed.") + logger.Infof("The finalizer 'controller' is removed.") return nil } diff --git a/pkg/controller/revision/revision_test.go b/pkg/controller/revision/revision_test.go index 790a797c6fbd..5fc5478abd8b 100644 --- a/pkg/controller/revision/revision_test.go +++ b/pkg/controller/revision/revision_test.go @@ -28,6 +28,8 @@ import ( "testing" "time" + "go.uber.org/zap" + buildv1alpha1 "github.com/elafros/build/pkg/apis/build/v1alpha1" fakebuildclientset "github.com/elafros/build/pkg/client/clientset/versioned/fake" buildinformers "github.com/elafros/build/pkg/client/informers/externalversions" @@ -233,6 +235,7 @@ func newTestControllerWithConfig(t *testing.T, controllerConfig *ControllerConfi buildInformer, &rest.Config{}, controllerConfig, + zap.NewNop().Sugar(), ).(*Controller) controller.resolver = &nopResolver{} diff --git a/pkg/controller/route/route.go b/pkg/controller/route/route.go index 4e85333f7ac0..b5f9ac8c65c7 100644 --- a/pkg/controller/route/route.go +++ b/pkg/controller/route/route.go @@ -93,13 +93,6 @@ type Controller struct { // Autoscale enable scale to zero experiment flag. enableScaleToZero *k8sflag.BoolFlag - - // Sugared logger is easier to use but is not as performant as the - // raw logger. In performance critical paths, call logger.Desugar() - // and use the returned raw logger instead. In addition to the - // performance benefits, raw logger also preserves type-safety at - // the expense of slightly greater verbosity. - logger *zap.SugaredLogger } // NewController initializes the controller and is called by the generated code @@ -117,9 +110,6 @@ func NewController( enableScaleToZero *k8sflag.BoolFlag, logger *zap.SugaredLogger) controller.Interface { - // Enrich the logs with controller type set to route - logger = logger.Named("route").With(zap.String(logkey.ControllerType, "route")) - // obtain references to a shared index informer for the Routes and // Configurations type. informer := elaInformerFactory.Elafros().V1alpha1().Routes() @@ -128,16 +118,15 @@ func NewController( controller := &Controller{ Base: controller.NewBase(kubeClientSet, elaClientSet, kubeInformerFactory, - elaInformerFactory, informer.Informer(), controllerAgentName, "Routes"), + elaInformerFactory, informer.Informer(), controllerAgentName, "Routes", logger), lister: informer.Lister(), synced: informer.Informer().HasSynced, configSynced: configInformer.Informer().HasSynced, controllerConfig: controllerConfig, enableScaleToZero: enableScaleToZero, - logger: logger, } - logger.Info("Setting up event handlers") + controller.Logger.Info("Setting up event handlers") configInformer.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{ AddFunc: controller.addConfigurationEvent, UpdateFunc: controller.updateConfigurationEvent, @@ -157,7 +146,7 @@ func (c *Controller) Run(threadiness int, stopCh <-chan struct{}) error { c.updateRouteEvent, "Route") } -// loggerWithRouteInfo enriches the logs with route name and route namespace. +// loggerWithRouteInfo enriches the logs with route name and namespace. func loggerWithRouteInfo(logger *zap.SugaredLogger, ns string, name string) *zap.SugaredLogger { return logger.With(zap.String(logkey.Namespace, ns), zap.String(logkey.Route, name)) } @@ -173,7 +162,7 @@ func (c *Controller) updateRouteEvent(key string) error { return nil } - logger := loggerWithRouteInfo(c.logger, namespace, name) + logger := loggerWithRouteInfo(c.Logger, namespace, name) ctx := logging.WithLogger(context.TODO(), logger) // Get the Route resource with this namespace/name @@ -890,17 +879,17 @@ func (c *Controller) addConfigurationEvent(obj interface{}) { ns := config.Namespace if config.Status.LatestReadyRevisionName == "" { - c.logger.Infof("Configuration %s is not ready", configName) + c.Logger.Infof("Configuration %s is not ready", configName) return } routeName, ok := config.Labels[ela.RouteLabelKey] if !ok { - c.logger.Infof("Configuration %s does not have label %s", configName, ela.RouteLabelKey) + c.Logger.Infof("Configuration %s does not have label %s", configName, ela.RouteLabelKey) return } - logger := loggerWithRouteInfo(c.logger, ns, routeName) + logger := loggerWithRouteInfo(c.Logger, ns, routeName) ctx := logging.WithLogger(context.TODO(), logger) route, err := c.lister.Routes(ns).Get(routeName) if err != nil { @@ -940,7 +929,7 @@ func (c *Controller) updateIngressEvent(old, new interface{}) { routeClient := c.ElaClientSet.ElafrosV1alpha1().Routes(ns) route, err := routeClient.Get(routeName, metav1.GetOptions{}) if err != nil { - c.logger.Error( + c.Logger.Error( "Error fetching route upon ingress becoming", zap.Error(err), zap.String(logkey.Namespace, ns), @@ -957,7 +946,7 @@ func (c *Controller) updateIngressEvent(old, new interface{}) { }) if _, err = routeClient.Update(route); err != nil { - c.logger.Error( + c.Logger.Error( "Error updating readiness of route upon ingress becoming", zap.Error(err), zap.String(logkey.Namespace, ns), diff --git a/pkg/controller/service/BUILD.bazel b/pkg/controller/service/BUILD.bazel index cb94c9c09387..fc0d7d3c9706 100644 --- a/pkg/controller/service/BUILD.bazel +++ b/pkg/controller/service/BUILD.bazel @@ -17,9 +17,10 @@ go_library( "//pkg/client/informers/externalversions:go_default_library", "//pkg/client/listers/ela/v1alpha1:go_default_library", "//pkg/controller:go_default_library", - "//vendor/github.com/golang/glog:go_default_library", + "//pkg/logging/logkey:go_default_library", "//vendor/go.opencensus.io/stats:go_default_library", "//vendor/go.opencensus.io/tag:go_default_library", + "//vendor/go.uber.org/zap:go_default_library", "//vendor/k8s.io/apimachinery/pkg/api/errors:go_default_library", "//vendor/k8s.io/apimachinery/pkg/apis/meta/v1:go_default_library", "//vendor/k8s.io/apimachinery/pkg/util/runtime:go_default_library", diff --git a/pkg/controller/service/service.go b/pkg/controller/service/service.go index 9ec913e2e7e2..2a0f5ff6a45c 100644 --- a/pkg/controller/service/service.go +++ b/pkg/controller/service/service.go @@ -20,7 +20,7 @@ import ( "fmt" "reflect" - "github.com/golang/glog" + "go.uber.org/zap" apierrs "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/util/runtime" @@ -36,6 +36,7 @@ import ( informers "github.com/elafros/elafros/pkg/client/informers/externalversions" listers "github.com/elafros/elafros/pkg/client/listers/ela/v1alpha1" "github.com/elafros/elafros/pkg/controller" + "github.com/elafros/elafros/pkg/logging/logkey" "go.opencensus.io/stats" "go.opencensus.io/tag" ) @@ -80,16 +81,15 @@ func NewController( kubeInformerFactory kubeinformers.SharedInformerFactory, elaInformerFactory informers.SharedInformerFactory, config *rest.Config, - controllerConfig controller.Config) controller.Interface { - - glog.Infof("Service controller Init") + controllerConfig controller.Config, + logger *zap.SugaredLogger) controller.Interface { // obtain references to a shared index informer for the Services. informer := elaInformerFactory.Elafros().V1alpha1().Services() controller := &Controller{ Base: controller.NewBase(kubeClientSet, elaClientSet, kubeInformerFactory, - elaInformerFactory, informer.Informer(), controllerAgentName, "Revisions"), + elaInformerFactory, informer.Informer(), controllerAgentName, "Revisions", logger), lister: informer.Lister(), synced: informer.Informer().HasSynced, } @@ -106,6 +106,11 @@ func (c *Controller) Run(threadiness int, stopCh <-chan struct{}) error { c.updateServiceEvent, "Service") } +// loggerWithServiceInfo enriches the logs with service name and namespace. +func loggerWithServiceInfo(logger *zap.SugaredLogger, ns string, name string) *zap.SugaredLogger { + return logger.With(zap.String(logkey.Namespace, ns), zap.String(logkey.Service, name)) +} + // updateServiceEvent compares the actual state with the desired, and attempts to // converge the two. It then updates the Status block of the Service resource // with the current status of the resource. @@ -117,6 +122,8 @@ func (c *Controller) updateServiceEvent(key string) error { return nil } + logger := loggerWithServiceInfo(c.Logger, namespace, name) + // Get the Service resource with this namespace/name service, err := c.lister.Services(namespace).Get(name) if err != nil { @@ -133,7 +140,7 @@ func (c *Controller) updateServiceEvent(key string) error { // Don't modify the informers copy service = service.DeepCopy() - glog.Infof("Running reconcile Service for %s\n%+v\n", service.Name, service) + logger.Infof("Running reconcile Service for %s\n%+v\n", service.Name, service) config := MakeServiceConfiguration(service) if err := c.reconcileConfiguration(config); err != nil { diff --git a/pkg/logging/logkey/constants.go b/pkg/logging/logkey/constants.go index 67c5107fcbdb..d560aacbdca7 100644 --- a/pkg/logging/logkey/constants.go +++ b/pkg/logging/logkey/constants.go @@ -23,12 +23,21 @@ const ( // Namespace is the key used for namespace in structured logs Namespace = "elafros.dev/namespace" + // Service is the key used for service name in structured logs + Service = "elafros.dev/service" + + // Configuration is the key used for configuration name in structured logs + Configuration = "elafros.dev/configuration" + // Revision is the key used for revision name in structured logs Revision = "elafros.dev/revision" // Route is the key used for route name in structured logs Route = "elafros.dev/route" + // Build is the key used for build name in structured logs + Build = "elafros.dev/build" + // JSONConfig is the key used for JSON configurations (not to be confused by the Configuration object) JSONConfig = "elafros.dev/jsonconfig" )