-
Notifications
You must be signed in to change notification settings - Fork 1.4k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
migrate from glog to logrus and errors to pkg/errors #98
Conversation
Sample output:
|
pkg/controller/backup_controller.go
Outdated
@@ -82,7 +84,8 @@ func NewBackupController( | |||
client: client, | |||
queue: workqueue.NewNamedRateLimitingQueue(workqueue.DefaultControllerRateLimiter(), "backup"), | |||
|
|||
clock: &clock.RealClock{}, | |||
clock: &clock.RealClock{}, | |||
logger: logrus.New(), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm not very familiar with the setup/configuration of logrus. Would it be more appropriate to pass this into the controllers as an argument instead of having the controllers bootstrap their own individually?
Specifically if we were to want to add in the ability to use structured logging or any of the other hooks it supports, would this be easy to accomplish?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I agree, we'll want to set up logging once, as high as we can, and pass it down.
Review now. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM with minor comments.
TBH, I didn't review all of this as my comments were mostly the same all the way throught.
A few general comments.
- Thank you! Thank you! for making logger a field, not a package level var. I cannot express how happy I am to see this.
- Perhaps a convention of passing logger into the constructor/function first, rather than the last param might help. A convention might make it easier to filter out the noise the repetition of this parameter; ie, the way that ctx always comes first, logger could come second (or first if there is no context).
- The remaining comments were about logging errors at info level, which is done inconsistently in this PR, sometimes errors are logged at info, sometimes at error, please try to make them consistent.
- Logging an error and returning the error can lead to really verbose logs where every stack frame logs and returns the error to the caller, who logs it, and so on. To throw shade at Java, this pattern is why people rage about Java's verbosity. My general suggestion is to log the error or return it, and in most cases as the error means the function cannot continue, logging isn't an option, so you have to return it. I've also pitched my pkg/errors package as an aide for this. It's just a suggestion, i'm not shilling for my side projects.
gr, err := helper.ResolveGroupResource(item) | ||
if err != nil { | ||
return "", err | ||
ctx.log("Unable to resolve resource %q: %v", item, err) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why did you change this from returning an error to logging the error and returning a valid value (i'm guessing "" is valid in some circumstances)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
so that includes_excludes.GenerateIncludesExcludes(...) doesn't have to take a logger (right now it's glogging this error). See related change to that function to check for empty-strings.
@@ -41,15 +41,17 @@ type backupCache struct { | |||
// This doesn't really need to be a map right now, but if we ever move to supporting multiple | |||
// buckets, this will be ready for it. | |||
buckets map[string]*backupCacheBucket | |||
logger *logrus.Logger | |||
} | |||
|
|||
var _ BackupGetter = &backupCache{} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
nit: I see these assertions as tests, so maybe they should move to a _test.go file. I also have a a belief that 90% of these assertions are unnecessary as tests will fail if X doesn't implement Y in the general case, and in the specific case that you want to test that X implements an Y, it should be a test case with a type assertion rather than a compilation failure.
} | ||
|
||
var _ BackupGetter = &backupCache{} | ||
|
||
// NewBackupCache returns a new backup cache that refreshes from delegate every resyncPeriod. | ||
func NewBackupCache(ctx context.Context, delegate BackupGetter, resyncPeriod time.Duration) BackupGetter { | ||
func NewBackupCache(ctx context.Context, delegate BackupGetter, resyncPeriod time.Duration, logger *logrus.Logger) BackupGetter { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
thank you from the bottom of my heart for not passing the logger in via context.WithValue.
c := &backupCache{ | ||
delegate: delegate, | ||
buckets: make(map[string]*backupCacheBucket), | ||
logger: logger, |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
suggestion, which you may not agree with. backupCache
is unexported, and being returned inside the BackupGetter
interface so if you did something like this
type backupCache struct {
*logrus.Logger
...
}
Then anywhere you call c.logger.Info
you can use c.Info
.
pkg/cmd/server/server.go
Outdated
@@ -177,12 +183,14 @@ func (s *server) loadConfig() (*api.Config, error) { | |||
break | |||
} | |||
if !apierrors.IsNotFound(err) { | |||
glog.Errorf("error retrieving configuration: %v", err) | |||
s.logger.WithField("error", err).Info("Error retrieving configuration") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
s/Info/Error
pkg/controller/restore_controller.go
Outdated
|
||
if _, err := file.Seek(0, 0); err != nil { | ||
glog.V(4).Infof("error seeking: %v", err) | ||
logContext.WithFields(logrus.Fields{ |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Please don't log an error at Info level, please don't log and return an error, just return it.
return nil | ||
} | ||
glog.V(4).Infof("error getting schedule %s: %v", key, err) | ||
logContext.WithField("error", err).Info("Error getting schedule") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Please don't log an error at Info level, please don't log and return an error, just return it.
// don't modify items in the cache | ||
schedule, err = cloneSchedule(schedule) | ||
if err != nil { | ||
glog.V(4).Infof("error cloning schedule %s: %v", key, err) | ||
logContext.WithField("error", err).Info("Error cloning schedule") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
as above
@@ -259,7 +280,7 @@ func (controller *scheduleController) processSchedule(key string) error { | |||
|
|||
// check for the schedule being due to run, and submit a Backup if so | |||
if err := controller.submitBackupIfDue(schedule, cronSchedule); err != nil { | |||
glog.V(4).Infof("error processing Schedule %v/%v: err=%v", schedule.Namespace, schedule.Name, err) | |||
logContext.WithField("error", err).Info("Error processing schedule") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
as above
logContext.WithFields(logrus.Fields{ | ||
"schedule": itm.Spec.Schedule, | ||
"error": err, | ||
}).Info("Error parsing schedule") | ||
validationErrors = append(validationErrors, fmt.Sprintf("invalid schedule: %v", err)) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
see above about maybe using something like pkg/errors to attach context to the error message, rather than using logging.
Signed-off-by: Steve Kriss <steve@heptio.com>
@ncdc PTAL at the latest commit. This demonstrates the pattern I'd like to use for errors/logging: -use @davecheney's pkg/errors package in order to get stack traces |
pkg/controller/backup_controller.go
Outdated
@@ -42,6 +42,7 @@ import ( | |||
arkv1client "github.com/heptio/ark/pkg/generated/clientset/typed/ark/v1" | |||
informers "github.com/heptio/ark/pkg/generated/informers/externalversions/ark/v1" | |||
listers "github.com/heptio/ark/pkg/generated/listers/ark/v1" | |||
"github.com/heptio/ark/pkg/util" |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Let's not have a util
package. util/errors
aliased to arkerrors
or something would be better imho
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
fixed
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
yes, very much lets not have a generic util
package.
pkg/util/error.go
Outdated
kvs = append(kvs, fmt.Sprintf("%s=%v", k, v)) | ||
} | ||
|
||
return fmt.Sprintf("%s %s", message, strings.Join(kvs, " ")) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Hmmm... It would be nice if the fields were exposed to logrus's WithFields()
method. Maybe we need our own custom Wrap()
style method that both retains the original error and maintains fields? Or something along those lines. WDYT @davecheney?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
You're saying have a custom error type that contains a Fields map and when logging an errors the fields get passed to logrus?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yeah, something along those lines. I'm not crazy about creating an error message where the string has the fields hardcoded as key=value pairs. But maybe I'm overthinking/overworrying?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I can create a custom logrus formatter to do this (which I think I need to do anyway to get the stack traces to be logged).
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Before doing that let's see what @davecheney thinks
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I can definitely write the stack trace to the log using a logrus hook (they allow you to permute the log Entry before it's written, so I can write the error using %+v
there). This could theoretically work for errors with fields as well (though per earlier discussion, @ncdc does not want to implement this).
@davecheney @skriss what do you think of the way that the docker/distribution project has organized its logging? To summarize:
See e.g. docs at https://github.com/docker/distribution/blob/master/context/doc.go I'm trying to avoid having to pass loggers into lots and lots of functions. I think I'd prefer they exist as part of a Context, and optionally that our major structs embed the Context for easier access. WDYT? |
meh, I have strong views on using a context value (maybe not the
If this is a (yes, I have a very complicated relationship with |
@ncdc I'm specifically concerned with placing loggers inside a context type value because this creates invisible coupling between the code that creates the context and the code that uses it. The creator has to know to place a logger value into the context, and the code that expects a logger needs to have a fallback case if the logger value is missing. Both of these can be made more explicit by passing a logger into the constructor during construction (which most types complex enough to have something to log generally have) |
pkg/cloudprovider/backup_service.go
Outdated
@@ -125,7 +127,11 @@ func (br *backupService) UploadBackup(bucket, backupName string, metadata, backu | |||
// success | |||
logKey := getBackupLogKey(backupName) | |||
if err := br.objectStorage.PutObject(bucket, logKey, log); err != nil { | |||
glog.Errorf("error uploading %s/%s: %v", bucket, logKey, err) | |||
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
delete blank line
pkg/cloudprovider/backup_service.go
Outdated
|
||
br.logger.WithError(err).WithFields(logrus.Fields{ | ||
"bucket": bucket, | ||
"logKey": logKey, |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Just call this key?
pkg/cloudprovider/backup_service.go
Outdated
@@ -149,7 +155,7 @@ func (br *backupService) GetAllBackups(bucket string) ([]*api.Backup, error) { | |||
for _, backupDir := range prefixes { | |||
backup, err := br.GetBackup(bucket, backupDir) | |||
if err != nil { | |||
glog.Errorf("Error reading backup directory %s: %v", backupDir, err) | |||
br.logger.WithError(err).WithField("backupDir", backupDir).Error("Error reading backup directory") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
s/backupDir/dir/
pkg/cmd/server/server.go
Outdated
|
||
ctx := s.ctx | ||
var wg sync.WaitGroup | ||
|
||
cloudBackupCacheResyncPeriod := durationMin(config.GCSyncPeriod.Duration, config.BackupSyncPeriod.Duration) | ||
glog.Infof("Caching cloud backups every %s", cloudBackupCacheResyncPeriod) | ||
s.logger.WithField("cloudBackupCacheResyncPeriod", cloudBackupCacheResyncPeriod).Info("Setting cloud backup cache sync period") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'd change cloudBackupCacheResyncPeriod to one of period, resyncPeriod, duration. Trying to avoid repetition.
@@ -215,11 +228,11 @@ func (controller *backupController) processBackup(key string) error { | |||
return nil | |||
} | |||
|
|||
glog.V(4).Infof("Cloning backup %s", key) | |||
logContext.Debug("Cloning backup") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It was V4, which is essentially debug
@@ -101,7 +99,7 @@ func (c *downloadRequestController) Run(ctx context.Context, numWorkers int) err | |||
var wg sync.WaitGroup | |||
|
|||
defer func() { | |||
glog.Infof("Waiting for workers to finish their work") | |||
c.logger.Info("Waiting for workers to finish their work") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This should be consistent with all the other controllers. The intent is to log that we're waiting, then shut down the queue so we're actually doing so.
if err := c.snapshotService.DeleteSnapshot(volumeBackup.SnapshotID); err != nil { | ||
glog.Errorf("error deleting snapshot %v: %v", volumeBackup.SnapshotID, err) | ||
logContext.WithError(err).WithField("snapshotID", volumeBackup.SnapshotID).Error("Error deleting snapshot") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
isn't the field already part of the logContext?
@@ -121,45 +125,46 @@ func (c *gcController) garbageCollectBackup(backup *api.Backup, deleteBackupFile | |||
deletionFailure := false | |||
|
|||
for _, volumeBackup := range backup.Status.VolumeBackups { | |||
glog.Infof("Removing snapshot %s associated with backup %s", volumeBackup.SnapshotID, kube.NamespaceAndName(backup)) | |||
logContext.WithField("snapshotID", volumeBackup.SnapshotID).Info("Removing snapshot associated with backup") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
call the field id
pkg/controller/restore_controller.go
Outdated
return err | ||
} | ||
|
||
glog.V(4).Infof("Getting restore %s", key) | ||
logContext.Debug("Getting Restore") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Same comment as above - yes - we basically want to lump Infof/V1/V2 as Info and V3+ as Debug
errors.Ark = append(errors.Ark, err.Error()) | ||
return | ||
} | ||
|
||
logFile, err := ioutil.TempFile("", "") | ||
if err != nil { | ||
glog.Errorf("error creating log temp file: %v", err) | ||
logContext.WithField("error", err).Error("Error creating log temp file") | ||
errors.Ark = append(errors.Ark, err.Error()) | ||
return | ||
} | ||
|
||
defer func() { | ||
if err := tmpFile.Close(); err != nil { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Do you have suggestions for how to do this better? I'm not sure we can do much other than throw our hands up in the air?
@skriss I talked with @davecheney on slack last night and we're both good with the approach you have here. I think what's left before we merge this:
|
pushed updates. recommended to look at the commits separately, as one is focused on logging with the controllers, while another wraps external library errors across all non-controller code. I think the main issue now is to figure out if/when we want stack traces, and if we don't want full ones, what we do want and how to get it. |
Looks like we can't get nicely-formatted stack traces without a custom logrus formatter (which is more work than the hook that I implemented) -- see sirupsen/logrus#608 |
FYI we can get the file, line, and function name of the error if we always use type stackTracker interface {
StackTrace() errors.StackTrace
}
err := someFunction()
stackErr, ok := errors.Cause(err).(stackTracker)
if ok {
stackTrace := stackErr.StackTrace()
functionName := fmt.Sprintf("%n", stackTrace[0])
fileAndLine := fmt.Sprintf("%s:%d", stackTrace[0], stackTrace[0])
logrus.WithError(err).WithFields(logrus.Fields{
"error.file": fileAndLine,
"error.function": functionName,
}).Error("something bad happened!")
} This prints out something like this (I have a few functions that call
The only thing I wish
and I don't want the function name or the newline+tab formatting. @davecheney any chance we could just expose a |
Minor correction to determining the innermost error location: func getInnermostTrace(err error) stackTracer {
var tracer stackTracer
for {
t, isTracer := err.(stackTracer)
if isTracer {
tracer = t
}
c, isCauser := err.(causer)
if isCauser {
err = c.Cause()
}
if !isTracer && !isCauser {
return tracer
}
}
return nil
} |
So the guidelines are probably:
WDYT? |
cool, this looks great. guidelines make sense -- I've already done both. Re: the second, I would add that you should call .Wrap or .WithStack for errors that are being returned from third-party libraries, but not for errors returning from your code (since if you do bullet 1 they'll already have a stack trace) |
Is there any harm in wrapping an error that came from |
well, every time you wrap you get a new stack trace from that point, which can result in the duplicated stacks like we saw yesterday. will check with the updated logging approach. |
Right, if you print a full trace of the error, repeated wraps leads to repeated traces printed out. Ok, let's not do that :). |
I wonder if we need 2 sets of file/function fields: 1 for the innermost error, and 1 for where it's actually logged from? |
Marking my changes as approved; I don't want to be a blocker on landing this change. |
@@ -85,7 +85,7 @@ func NewBlockStorageAdapter(location string, apiTimeout time.Duration) (cloudpro | |||
|
|||
spt, err := helpers.NewServicePrincipalTokenFromCredentials(cfg, azure.PublicCloud.ResourceManagerEndpoint) | |||
if err != nil { | |||
return nil, fmt.Errorf("error creating new service principal: %v", err) | |||
return nil, errors.WithStack(err) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Do you want to preserve the message?
pkg/cloudprovider/backup_cache.go
Outdated
@@ -64,10 +66,10 @@ func (c *backupCache) refresh() { | |||
c.lock.Lock() | |||
defer c.lock.Unlock() | |||
|
|||
glog.V(4).Infof("refreshing all cached backup lists from object storage") | |||
c.logger.Info("refreshing all cached backup lists from object storage") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Debug
pkg/cloudprovider/backup_cache.go
Outdated
|
||
for bucketName, bucket := range c.buckets { | ||
glog.V(4).Infof("refreshing bucket %q", bucketName) | ||
c.logger.WithField("bucket", bucketName).Info("Refreshing bucket") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Debug
pkg/cloudprovider/backup_cache.go
Outdated
if found { | ||
glog.V(4).Infof("returning cached backup list for bucket %q", bucketName) | ||
logContext.Info("Returning cached backup list for bucket") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Debug
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
remove "for bucket"
pkg/cloudprovider/backup_cache.go
Outdated
@@ -76,12 +78,15 @@ func (c *backupCache) GetAllBackups(bucketName string) ([]*v1.Backup, error) { | |||
c.lock.RLock() | |||
bucket, found := c.buckets[bucketName] | |||
c.lock.RUnlock() | |||
|
|||
logContext := c.logger.WithField("bucketName", bucketName) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
s/bucketName/bucket/
@@ -82,10 +85,10 @@ func (nsr *podRestorer) Prepare(obj runtime.Unstructured, restore *api.Restore, | |||
return nil, nil, err | |||
} | |||
|
|||
glog.V(4).Infof("setting spec.volumes") | |||
r.logger.Info("Setting spec.volumes") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
debug
spec["volumes"] = newVolumes | ||
|
||
glog.V(4).Infof("iterating over containers") | ||
r.logger.Info("iterating over containers") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
debug
@@ -94,13 +97,12 @@ func (nsr *podRestorer) Prepare(obj runtime.Unstructured, restore *api.Restore, | |||
return err | |||
} | |||
|
|||
glog.V(4).Infof("checking volumeMount with name %q", name) | |||
|
|||
r.logger.WithField("volumeMount", name).Info("Checking volumeMount") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
debug
if !defaultTokenRegex.MatchString(name) { | ||
glog.V(4).Infof("preserving volumeMount") | ||
r.logger.WithField("volumeMount", name).Info("Preserving volumeMount") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
debug
newVolumeMounts = append(newVolumeMounts, volumeMount) | ||
} else { | ||
glog.V(4).Infof("excluding volumeMount") | ||
r.logger.WithField("volumeMount", name).Info("Excluding volumeMount") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
debug
@ncdc addressed most of the feedback. I'll squash this down to two commits for the 2 new vendored dependencies, one commit for the logrus hook and one commit for the rest. |
@skriss squash & let's get it in. 🎉 |
Signed-off-by: Steve Kriss <steve@heptio.com>
Signed-off-by: Steve Kriss <steve@heptio.com>
Signed-off-by: Steve Kriss <steve@heptio.com>
squashed, building now... |
@ncdc good to go! |
bug 1967858 - bug introduced in 1.6 restore progress: fix CR restore
Starting the migration to logrus. Appreciate any input before I continue across the rest of the codebase, particularly on what we should be logging at each level -- @davecheney, I know you have thoughts on the matter :)
Fixes #70