Skip to content

Commit cb073a9

Browse files
jkowalskimarkmandel
jkowalski
authored and
markmandel
committed
Unified logging of resource identifiers so that we can reliably get an entire history of a resource in stack driver.
Well-known identifiers of resources types are defined in logfields package.
1 parent 68d64e2 commit cb073a9

11 files changed

Lines changed: 213 additions & 131 deletions

File tree

‎pkg/fleetautoscalers/controller.go‎

Lines changed: 21 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -20,12 +20,14 @@ import (
2020
"time"
2121

2222
"agones.dev/agones/pkg/apis/stable"
23+
"agones.dev/agones/pkg/apis/stable/v1alpha1"
2324
stablev1alpha1 "agones.dev/agones/pkg/apis/stable/v1alpha1"
2425
"agones.dev/agones/pkg/client/clientset/versioned"
2526
getterv1alpha1 "agones.dev/agones/pkg/client/clientset/versioned/typed/stable/v1alpha1"
2627
"agones.dev/agones/pkg/client/informers/externalversions"
2728
listerv1alpha1 "agones.dev/agones/pkg/client/listers/stable/v1alpha1"
2829
"agones.dev/agones/pkg/util/crd"
30+
"agones.dev/agones/pkg/util/logfields"
2931
"agones.dev/agones/pkg/util/runtime"
3032
"agones.dev/agones/pkg/util/webhooks"
3133
"agones.dev/agones/pkg/util/workerqueue"
@@ -48,7 +50,7 @@ import (
4850

4951
// Controller is a the FleetAutoscaler controller
5052
type Controller struct {
51-
logger *logrus.Entry
53+
baseLogger *logrus.Entry
5254
crdGetter v1beta1.CustomResourceDefinitionInterface
5355
fleetGetter getterv1alpha1.FleetsGetter
5456
fleetLister listerv1alpha1.FleetLister
@@ -79,12 +81,12 @@ func NewController(
7981
fleetAutoscalerLister: agonesInformer.FleetAutoscalers().Lister(),
8082
fleetAutoscalerSynced: fasInformer.HasSynced,
8183
}
82-
c.logger = runtime.NewLoggerWithType(c)
83-
c.workerqueue = workerqueue.NewWorkerQueue(c.syncFleetAutoscaler, c.logger, stable.GroupName+".FleetAutoscalerController")
84+
c.baseLogger = runtime.NewLoggerWithType(c)
85+
c.workerqueue = workerqueue.NewWorkerQueue(c.syncFleetAutoscaler, c.baseLogger, logfields.FleetAutoscalerKey, stable.GroupName+".FleetAutoscalerController")
8486
health.AddLivenessCheck("fleetautoscaler-workerqueue", healthcheck.Check(c.workerqueue.Healthy))
8587

8688
eventBroadcaster := record.NewBroadcaster()
87-
eventBroadcaster.StartLogging(c.logger.Infof)
89+
eventBroadcaster.StartLogging(c.baseLogger.Infof)
8890
eventBroadcaster.StartRecordingToSink(&typedcorev1.EventSinkImpl{Interface: kubeClient.CoreV1().Events("")})
8991
c.recorder = eventBroadcaster.NewRecorder(scheme.Scheme, corev1.EventSource{Component: "fleetautoscaler-controller"})
9092

@@ -105,12 +107,12 @@ func NewController(
105107
// Run the FleetAutoscaler controller. Will block until stop is closed.
106108
// Runs threadiness number workers to process the rate limited queue
107109
func (c *Controller) Run(workers int, stop <-chan struct{}) error {
108-
err := crd.WaitForEstablishedCRD(c.crdGetter, "fleetautoscalers."+stable.GroupName, c.logger)
110+
err := crd.WaitForEstablishedCRD(c.crdGetter, "fleetautoscalers."+stable.GroupName, c.baseLogger)
109111
if err != nil {
110112
return err
111113
}
112114

113-
c.logger.Info("Wait for cache sync")
115+
c.baseLogger.Info("Wait for cache sync")
114116
if !cache.WaitForCacheSync(stop, c.fleetAutoscalerSynced) {
115117
return errors.New("failed to wait for caches to sync")
116118
}
@@ -119,14 +121,22 @@ func (c *Controller) Run(workers int, stop <-chan struct{}) error {
119121
return nil
120122
}
121123

124+
func (c *Controller) loggerForFleetAutoscalerKey(key string) *logrus.Entry {
125+
return logfields.AugmentLogEntry(c.baseLogger, logfields.FleetAutoscalerKey, key)
126+
}
127+
128+
func (c *Controller) loggerForFleetAutoscaler(fas *v1alpha1.FleetAutoscaler) *logrus.Entry {
129+
return c.loggerForFleetAutoscalerKey(fas.Namespace+"/"+fas.Name).WithField("fas", fas)
130+
}
131+
122132
// validationHandler will intercept when a FleetAutoscaler is created, and
123133
// validate its settings.
124134
func (c *Controller) validationHandler(review admv1beta1.AdmissionReview) (admv1beta1.AdmissionReview, error) {
125-
c.logger.WithField("review", review).Info("validationHandler")
126135
obj := review.Request.Object
127136
fas := &stablev1alpha1.FleetAutoscaler{}
128137
err := json.Unmarshal(obj.Raw, fas)
129138
if err != nil {
139+
c.baseLogger.WithField("review", review).WithError(err).Info("validationHandler")
130140
return review, errors.Wrapf(err, "error unmarshalling original FleetAutoscaler json: %s", obj.Raw)
131141
}
132142

@@ -154,20 +164,20 @@ func (c *Controller) validationHandler(review admv1beta1.AdmissionReview) (admv1
154164
// syncFleetAutoscaler scales the attached fleet and
155165
// synchronizes the FleetAutoscaler CRD
156166
func (c *Controller) syncFleetAutoscaler(key string) error {
157-
c.logger.WithField("key", key).Info("Synchronising")
167+
c.loggerForFleetAutoscalerKey(key).Info("Synchronising")
158168

159169
// Convert the namespace/name string into a distinct namespace and name
160170
namespace, name, err := cache.SplitMetaNamespaceKey(key)
161171
if err != nil {
162172
// don't return an error, as we don't want this retried
163-
runtime.HandleError(c.logger.WithField("key", key), errors.Wrapf(err, "invalid resource key"))
173+
runtime.HandleError(c.loggerForFleetAutoscalerKey(key), errors.Wrapf(err, "invalid resource key"))
164174
return nil
165175
}
166176

167177
fas, err := c.fleetAutoscalerLister.FleetAutoscalers(namespace).Get(name)
168178
if err != nil {
169179
if k8serrors.IsNotFound(err) {
170-
c.logger.WithField("key", key).Info(fmt.Sprintf("FleetAutoscaler %s from namespace %s is no longer available for syncing", name, namespace))
180+
c.loggerForFleetAutoscalerKey(key).Info(fmt.Sprintf("FleetAutoscaler %s from namespace %s is no longer available for syncing", name, namespace))
171181
return nil
172182
}
173183
return errors.Wrapf(err, "error retrieving FleetAutoscaler %s from namespace %s", name, namespace)
@@ -177,10 +187,7 @@ func (c *Controller) syncFleetAutoscaler(key string) error {
177187
fleet, err := c.fleetLister.Fleets(namespace).Get(fas.Spec.FleetName)
178188
if err != nil {
179189
if k8serrors.IsNotFound(err) {
180-
logrus.WithError(err).WithField("fleetAutoscaler", fas.Name).
181-
WithField("fleet", fas.Spec.FleetName).
182-
WithField("namespace", namespace).
183-
Warn("Could not find fleet for autoscaler. Skipping.")
190+
c.loggerForFleetAutoscaler(fas).Warn("Could not find fleet for autoscaler. Skipping.")
184191

185192
c.recorder.Eventf(fas, corev1.EventTypeWarning, "FailedGetFleet",
186193
"could not fetch fleet: %s", fas.Spec.FleetName)

‎pkg/fleets/controller.go‎

Lines changed: 29 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ import (
2626
"agones.dev/agones/pkg/client/informers/externalversions"
2727
listerv1alpha1 "agones.dev/agones/pkg/client/listers/stable/v1alpha1"
2828
"agones.dev/agones/pkg/util/crd"
29+
"agones.dev/agones/pkg/util/logfields"
2930
"agones.dev/agones/pkg/util/runtime"
3031
"agones.dev/agones/pkg/util/webhooks"
3132
"agones.dev/agones/pkg/util/workerqueue"
@@ -50,7 +51,7 @@ import (
5051

5152
// Controller is a the GameServerSet controller
5253
type Controller struct {
53-
logger *logrus.Entry
54+
baseLogger *logrus.Entry
5455
crdGetter v1beta1.CustomResourceDefinitionInterface
5556
gameServerSetGetter getterv1alpha1.GameServerSetsGetter
5657
gameServerSetLister listerv1alpha1.GameServerSetLister
@@ -87,12 +88,12 @@ func NewController(
8788
fleetSynced: fInformer.HasSynced,
8889
}
8990

90-
c.logger = runtime.NewLoggerWithType(c)
91-
c.workerqueue = workerqueue.NewWorkerQueue(c.syncFleet, c.logger, stable.GroupName+".FleetController")
91+
c.baseLogger = runtime.NewLoggerWithType(c)
92+
c.workerqueue = workerqueue.NewWorkerQueue(c.syncFleet, c.baseLogger, logfields.FleetKey, stable.GroupName+".FleetController")
9293
health.AddLivenessCheck("fleet-workerqueue", healthcheck.Check(c.workerqueue.Healthy))
9394

9495
eventBroadcaster := record.NewBroadcaster()
95-
eventBroadcaster.StartLogging(c.logger.Infof)
96+
eventBroadcaster.StartLogging(c.baseLogger.Infof)
9697
eventBroadcaster.StartRecordingToSink(&typedcorev1.EventSinkImpl{Interface: kubeClient.CoreV1().Events("")})
9798
c.recorder = eventBroadcaster.NewRecorder(scheme.Scheme, corev1.EventSource{Component: "fleet-controller"})
9899

@@ -126,7 +127,7 @@ func NewController(
126127
// Should only be called on fleet create operations.
127128
// nolint:dupl
128129
func (c *Controller) creationMutationHandler(review admv1beta1.AdmissionReview) (admv1beta1.AdmissionReview, error) {
129-
c.logger.WithField("review", review).Info("creationMutationHandler")
130+
c.baseLogger.WithField("review", review).Info("creationMutationHandler")
130131

131132
obj := review.Request.Object
132133
fleet := &stablev1alpha1.Fleet{}
@@ -154,7 +155,7 @@ func (c *Controller) creationMutationHandler(review admv1beta1.AdmissionReview)
154155
return review, errors.Wrapf(err, "error creating json for patch for Fleet %s", fleet.ObjectMeta.Name)
155156
}
156157

157-
c.logger.WithField("fleet", fleet.ObjectMeta.Name).WithField("patch", string(jsn)).Infof("patch created!")
158+
c.loggerForFleet(fleet).WithField("patch", string(jsn)).Infof("patch created!")
158159

159160
pt := admv1beta1.PatchTypeJSONPatch
160161
review.Response.PatchType = &pt
@@ -166,7 +167,7 @@ func (c *Controller) creationMutationHandler(review admv1beta1.AdmissionReview)
166167
// creationValidationHandler that validates a Fleet when it is created
167168
// Should only be called on Fleet create and Update operations.
168169
func (c *Controller) creationValidationHandler(review admv1beta1.AdmissionReview) (admv1beta1.AdmissionReview, error) {
169-
c.logger.WithField("review", review).Info("creationValidationHandler")
170+
c.baseLogger.WithField("review", review).Info("creationValidationHandler")
170171

171172
obj := review.Request.Object
172173
fleet := &stablev1alpha1.Fleet{}
@@ -191,7 +192,7 @@ func (c *Controller) creationValidationHandler(review admv1beta1.AdmissionReview
191192
Details: &details,
192193
}
193194

194-
c.logger.WithField("review", review).Info("Invalid Fleet")
195+
c.loggerForFleet(fleet).WithField("review", review).Info("Invalid Fleet")
195196
return review, nil
196197
}
197198

@@ -201,12 +202,12 @@ func (c *Controller) creationValidationHandler(review admv1beta1.AdmissionReview
201202
// Run the Fleet controller. Will block until stop is closed.
202203
// Runs threadiness number workers to process the rate limited queue
203204
func (c *Controller) Run(workers int, stop <-chan struct{}) error {
204-
err := crd.WaitForEstablishedCRD(c.crdGetter, "fleets.stable.agones.dev", c.logger)
205+
err := crd.WaitForEstablishedCRD(c.crdGetter, "fleets.stable.agones.dev", c.baseLogger)
205206
if err != nil {
206207
return err
207208
}
208209

209-
c.logger.Info("Wait for cache sync")
210+
c.baseLogger.Info("Wait for cache sync")
210211
if !cache.WaitForCacheSync(stop, c.gameServerSetSynced, c.fleetSynced) {
211212
return errors.New("failed to wait for caches to sync")
212213
}
@@ -215,6 +216,14 @@ func (c *Controller) Run(workers int, stop <-chan struct{}) error {
215216
return nil
216217
}
217218

219+
func (c *Controller) loggerForFleetKey(key string) *logrus.Entry {
220+
return logfields.AugmentLogEntry(c.baseLogger, logfields.FleetKey, key)
221+
}
222+
223+
func (c *Controller) loggerForFleet(f *v1alpha1.Fleet) *logrus.Entry {
224+
return c.loggerForFleetKey(f.Namespace+"/"+f.Name).WithField("fleet", f)
225+
}
226+
218227
// gameServerSetEventHandler enqueues the owning Fleet for this GameServerSet,
219228
// assuming that it has one
220229
func (c *Controller) gameServerSetEventHandler(obj interface{}) {
@@ -227,9 +236,9 @@ func (c *Controller) gameServerSetEventHandler(obj interface{}) {
227236
fleet, err := c.fleetLister.Fleets(gsSet.ObjectMeta.Namespace).Get(ref.Name)
228237
if err != nil {
229238
if k8serrors.IsNotFound(err) {
230-
c.logger.WithField("ref", ref).Info("Owner Fleet no longer available for syncing")
239+
c.baseLogger.WithField("ref", ref).Info("Owner Fleet no longer available for syncing")
231240
} else {
232-
runtime.HandleError(c.logger.WithField("fleet", fleet.ObjectMeta.Name).WithField("ref", ref),
241+
runtime.HandleError(c.loggerForFleet(fleet).WithField("ref", ref),
233242
errors.Wrap(err, "error retrieving GameServerSet owner"))
234243
}
235244
return
@@ -240,20 +249,20 @@ func (c *Controller) gameServerSetEventHandler(obj interface{}) {
240249
// syncFleet synchronised the fleet CRDs and configures/updates
241250
// backing GameServerSets
242251
func (c *Controller) syncFleet(key string) error {
243-
c.logger.WithField("key", key).Info("Synchronising")
252+
c.loggerForFleetKey(key).Info("Synchronising")
244253

245254
// Convert the namespace/name string into a distinct namespace and name
246255
namespace, name, err := cache.SplitMetaNamespaceKey(key)
247256
if err != nil {
248257
// don't return an error, as we don't want this retried
249-
runtime.HandleError(c.logger.WithField("key", key), errors.Wrapf(err, "invalid resource key"))
258+
runtime.HandleError(c.loggerForFleetKey(key), errors.Wrapf(err, "invalid resource key"))
250259
return nil
251260
}
252261

253262
fleet, err := c.fleetLister.Fleets(namespace).Get(name)
254263
if err != nil {
255264
if k8serrors.IsNotFound(err) {
256-
c.logger.WithField("key", key).Info("Fleet is no longer available for syncing")
265+
c.loggerForFleetKey(key).Info("Fleet is no longer available for syncing")
257266
return nil
258267
}
259268
return errors.Wrapf(err, "error retrieving fleet %s from namespace %s", name, namespace)
@@ -267,7 +276,7 @@ func (c *Controller) syncFleet(key string) error {
267276
active, rest := c.filterGameServerSetByActive(fleet, list)
268277
// if there isn't an active gameServerSet, create one (but don't persist yet)
269278
if active == nil {
270-
c.logger.WithField("fleet", fleet.ObjectMeta.Name).Info("could not find active GameServerSet, creating")
279+
c.loggerForFleet(fleet).Info("could not find active GameServerSet, creating")
271280
active = fleet.GameServerSet()
272281
}
273282

@@ -371,7 +380,7 @@ func (c *Controller) deleteEmptyGameServerSets(fleet *stablev1alpha1.Fleet, list
371380
func (c *Controller) recreateDeployment(fleet *stablev1alpha1.Fleet, rest []*stablev1alpha1.GameServerSet) (int32, error) {
372381
for _, gsSet := range rest {
373382
if gsSet.Spec.Replicas != 0 {
374-
c.logger.WithField("gameserverset", gsSet.ObjectMeta.Name).Info("applying recreate deployment: scaling to 0")
383+
c.loggerForFleet(fleet).WithField("gameserverset", gsSet.ObjectMeta.Name).Info("applying recreate deployment: scaling to 0")
375384
gsSetCopy := gsSet.DeepCopy()
376385
gsSetCopy.Spec.Replicas = 0
377386
if _, err := c.gameServerSetGetter.GameServerSets(gsSetCopy.ObjectMeta.Namespace).Update(gsSetCopy); err != nil {
@@ -434,7 +443,7 @@ func (c *Controller) rollingUpdateActive(fleet *stablev1alpha1.Fleet, active *st
434443
replicas = fleet.LowerBoundReplicas(replicas - sumAllocated)
435444
}
436445

437-
c.logger.WithField("gameserverset", active.ObjectMeta.Name).WithField("replicas", replicas).
446+
c.loggerForFleet(fleet).WithField("gameserverset", active.ObjectMeta.Name).WithField("replicas", replicas).
438447
Info("applying rolling update to active gameserverset")
439448

440449
return replicas, nil
@@ -467,7 +476,7 @@ func (c *Controller) rollingUpdateRest(fleet *stablev1alpha1.Fleet, rest []*stab
467476
gsSetCopy := gsSet.DeepCopy()
468477
gsSetCopy.Spec.Replicas = fleet.LowerBoundReplicas(gsSetCopy.Spec.Replicas - unavailable)
469478

470-
c.logger.WithField("gameserverset", gsSet.ObjectMeta.Name).WithField("replicas", gsSetCopy.Spec.Replicas).
479+
c.loggerForFleet(fleet).WithField("gameserverset", gsSet.ObjectMeta.Name).WithField("replicas", gsSetCopy.Spec.Replicas).
471480
Info("applying rolling update to inactive gameserverset")
472481

473482
if _, err := c.gameServerSetGetter.GameServerSets(gsSetCopy.ObjectMeta.Namespace).Update(gsSetCopy); err != nil {
@@ -486,8 +495,7 @@ func (c *Controller) rollingUpdateRest(fleet *stablev1alpha1.Fleet, rest []*stab
486495
// updateFleetStatus gets the GameServerSets for this Fleet and then
487496
// calculates the counts for the status, and updates the Fleet
488497
func (c *Controller) updateFleetStatus(fleet *stablev1alpha1.Fleet) error {
489-
490-
c.logger.WithField("key", fleet.Name).Info("Update Fleet Status")
498+
c.loggerForFleet(fleet).Info("Update Fleet Status")
491499

492500
list, err := ListGameServerSetsByFleetOwner(c.gameServerSetLister, fleet)
493501
if err != nil {

0 commit comments

Comments
 (0)