Skip to content
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

Add common logger with specific fields #188

Merged
merged 8 commits into from Apr 30, 2020

Conversation

addudko
Copy link
Collaborator

@addudko addudko commented Apr 21, 2020

No description provided.

@addudko addudko marked this pull request as draft April 21, 2020 20:30
logger.Errorf("Unable to get %s from context", auth.MultiTenancyField)
}

if o.ophIDEnabled {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this entire block is implementation specific and does not belong in the opensource project. I think you want to implement ways to instruct the toolkit to parse out specific fields, namely ophid. I believe this field will become less useful in the future as account ID is included ( in all cases ) for a JWT

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agree with Drew, we should avoid exposing implementation specific details into open source projects

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of trying to solve specific problems we should focus on providing general and extensible tool which helps people to get what they needs

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Had the same thoughts regarding the ophid, but according to docs I understood this like we need logger with specific fields, set by default and not customizable.

logging/log.go Outdated
Comment on lines 29 to 34
if lvl, ok := logLevels[level]; !ok {
log.Errorf("Invalid %q provided for log level", lvl)
log.SetLevel(logrus.InfoLevel)
} else {
log.SetLevel(lvl)
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's better to rewrite this block in a more Go way and awoid if ... else cases

log.SetLevel(logrus.InfoLevel)
if lvl, ok = logLevels[level]; ok {
    log.SetLevel(lvl)
    return log
}

log.Errorf("Invalid %q provided for log level", lvl)
return log

func newLoggerForCall(ctx context.Context, entry *logrus.Entry, fields logrus.Fields) context.Context {
callLog := entry.WithFields(fields)
callLog = callLog.WithFields(ctxlogrus.Extract(ctx).Data)
return ctxlogrus.ToContext(ctx, callLog)
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please add blank line before return statement, it will male code more readable

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not totally agree with this particular case, because it's perfectly readable I think. But I've changed it

func newLoggerFields(fullMethodString string, start time.Time, kind string) logrus.Fields {
service := path.Dir(fullMethodString)[1:]
method := path.Base(fullMethodString)
return logrus.Fields{
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please add blank line before return statement, it will male code more readable

logger.Errorf("Unable to get %s from context", auth.MultiTenancyField)
}

if o.ophIDEnabled {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agree with Drew, we should avoid exposing implementation specific details into open source projects

logger.Errorf("Unable to get %s from context", auth.MultiTenancyField)
}

if o.ophIDEnabled {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of trying to solve specific problems we should focus on providing general and extensible tool which helps people to get what they needs

Comment on lines 59 to 67
startTime := time.Now()
fields := newLoggerFields(method, startTime, clientKind)
err := invoker(ctx, method, req, reply, cc, opts...)
addSpecificFields(ctx, fields, logger, o)
code := o.codeFunc(err)
level := o.levelFunc(code)
durField, durVal := o.durationFunc(time.Since(startTime))
fields["grpc.code"] = code.String()
fields[durField] = durVal
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This block has poor readability , it will be better to reduce LOC between initialization and actual usage of variable, as well please separe each field by blank line

startTime := time.Now()

fields := newLoggerFields(method, startTime, clientKind)
addSpecificFields(ctx, fields, logger, o)

err := invoker(ctx, method, req, reply, cc, opts...)
if err != nil {
 	fields[logrus.ErrorKey] = err
}

code := o.codeFunc(err)
fields[GRPCCodeKey] = code.String()

durField, durVal := o.durationFunc(time.Since(startTime))
fields[durField] = durVal

level := o.levelFunc(code)
levelLogf(logrus.NewEntry(logger).WithFields(fields), level, "finished unary call with code "+code.String())

return err

logging/log.go Outdated
Comment on lines 75 to 76
optCopy := &options{}
*optCopy = *defaultOptions
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From my point of view we can initialize defaultOptions per request instad of using global variable for this, this helps us to avoid such magic, simple is better than clever

logging/log.go Outdated
Comment on lines 50 to 53
levelFunc grpc_logrus.CodeToLevel
shouldLog grpc_logging.Decider
codeFunc grpc_logging.ErrorToCode
durationFunc grpc_logrus.DurationToField
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't see this options can be changed by client, in this case i don't think this is a good idea to add them into options pattern

logging/log.go Outdated
Comment on lines 60 to 62
func EnableOphID(opts *options) {
opts.ophIDEnabled = true
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As i mentioned before, this is special case for a few our applications, suggest to avoid introducing this into common logger

logging/log.go Outdated
"github.com/sirupsen/logrus"
)

func NewLogger(level string) *logrus.Logger {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we instead of using simple string define custom type

type logLevel logrus.Level

and define a few public constansts

const (
   DebugLevel = logrus.DebugLevel
   InfoLevel = logrus.InfoLevel
   ...
)

This helps us to make this function safe and forbide clients pass bad level

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's better to leave this argument as is and use already written levels from logrus. Don't see reasons to rewrite them

@Evgeniy-L Evgeniy-L requested a review from marcinas April 22, 2020 16:18
Copy link

@marcinas marcinas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

with the above suggested changes, this looks mostly good
this may not be the PR for this, but before the common logger is to be widely distributed, we should incorporate the new logging requirements, as detailed in https://docs.google.com/document/d/1jFk0SYh11b5y_pdiZ4OYSAUIy7Udt4NbOJ21UCxh9_g/edit#heading=h.odlsv7xt0st2
namely, the inclusion of account id, request id, and ophid in atlas_logs and unifying the field names

@addudko addudko marked this pull request as ready for review April 23, 2020 06:06
@addudko addudko requested review from burov and marcinas April 23, 2020 06:07
Copy link

@burov burov left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks almost done,but i still have a few concerns

@@ -169,7 +171,7 @@ func GatewayLoggingInterceptor(logger *logrus.Logger, opts ...GWLogOption) grpc.

// print log message with all fields
resLogger = resLogger.WithFields(fields)
levelLogf(resLogger, cfg.codeToLevel(grpc.Code(err)), "finished client unary call with code "+grpc.Code(err).String())
levelLogf(resLogger, cfg.codeToLevel(status.Code(err)), "finished client unary call with code "+status.Code(err).String())
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we initialize statusCode variable which store value of status.Code(err) instead of calling this function three times

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not my implementation, should be deprecated if not used. Just updated deprecated field

@@ -160,7 +162,7 @@ func GatewayLoggingInterceptor(logger *logrus.Logger, opts ...GWLogOption) grpc.
durField, durVal := grpc_logrus.DurationToTimeMillisField(time.Now().Sub(startTime))
fields = logrus.Fields{
durField: durVal,
"grpc.code": grpc.Code(err).String(),
"grpc.code": status.Code(err).String(),
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would like to avoid magin strings us DefaultGRPCCodeKey constant instead

Copy link
Collaborator Author

@addudko addudko Apr 23, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not my implementation, should be deprecated if not used. Just updated deprecated field

logging/interceptor.go Outdated Show resolved Hide resolved
Comment on lines 137 to 140
reqID, exists := requestid.FromContext(ctx)
if !exists || reqID == "" {
reqID = uuid.New().String()
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Evgeniy-L what do you think about generating request id there, from my point of view it's not a good thing, because we spread request id handling between requestid interceptor, nginx and logging library. From my point of view it better to do the same thing as we did with accountID return an error in case we can't find request id

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree with @burov, we should not spread the logic between multiple parties.
@addudko, please address this comment (e.g. return error similar to account_id).

logging/interceptor.go Outdated Show resolved Hide resolved
logging/log.go Outdated

// From https://github.com/grpc-ecosystem/go-grpc-middleware/blob/06f64829ca1f521d41cd6235a7a204a6566fb0dc/logging/logrus/options.go#L194
func durationToMilliseconds(duration time.Duration) float32 {
return float32(duration.Nanoseconds()/1000) / 1000
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

logging/log.go Outdated
Comment on lines 77 to 83
// WithDurationField customizes the function for mapping request durations to log fields.
// From https://github.com/grpc-ecosystem/go-grpc-middleware/blob/06f64829ca1f521d41cd6235a7a204a6566fb0dc/logging/logrus/options.go#L83
func WithDurationField(f DurationToField) Option {
return func(o *options) {
o.durationFunc = f
}
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can use describe why we have this option? I don't see any obvious case where i want to customize translation of duration to miliseconds

logging/interceptor.go Outdated Show resolved Hide resolved
Comment on lines +159 to +164
field, err := auth.GetJWTField(ctx, customField, nil)
if err != nil {
return ctx, fmt.Errorf("Unable to get custom %q field from context", customField)
}

fields[customField] = field
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we add the same option to get CustomFields from headers as well, from my point of view it can be reasonable

@addudko addudko requested a review from burov April 27, 2020 17:23
Copy link

@marcinas marcinas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With the additional changes implemented that were discussed with architects, this looks good to establish the interceptor side of standard logging 👍
At least from the side of the logging gap analysis and common logging fields, this LGTM as long as the other reviewers' comments are resolved.

Copy link
Contributor

@Evgeniy-L Evgeniy-L left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please address one comment related to request_id generation and we can merge this PR.

Comment on lines 137 to 140
reqID, exists := requestid.FromContext(ctx)
if !exists || reqID == "" {
reqID = uuid.New().String()
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree with @burov, we should not spread the logic between multiple parties.
@addudko, please address this comment (e.g. return error similar to account_id).

Copy link
Contributor

@Evgeniy-L Evgeniy-L left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good

@Evgeniy-L Evgeniy-L merged commit 6bd86d4 into infobloxopen:master Apr 30, 2020
Copy link
Contributor

@kd7lxl kd7lxl left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Many Atlas services use gRPC streams, so a Stream interceptor must also be provided. It seems only Unary was implemented.

Comment on lines +12 to +17
log := logrus.New()

// Default timeFormat
log.SetFormatter(&logrus.JSONFormatter{
TimestampFormat: time.RFC3339Nano,
})
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would be helpful if there was a way to pass the logrus global logger here instead of always creating a new logger. This way we could apply these formatter and level settings globally for the process, which will take effect on all packages that use logrus, regardless of whether they accept a logger to their functions.

}
}

func UnaryServerInterceptor(logger *logrus.Logger, opts ...Option) grpc.UnaryServerInterceptor {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If this were implemented as a ChainUnaryServer, it could be composed of existing interceptors, like the requestid middleware, without having to reimplement them.

abynenkov-ib added a commit that referenced this pull request Apr 27, 2021
* add resource identifiers

Resource IDs are a typed guid proceeded by metadata helpful for
humans to identify what the guid is referring to.

stopping gRPC does not immediately guarantee http server is stopped.
Serve() will call Stop() at the end. Stop() guarantees both servers
are stopped and listeners are closed.

* Expose HandleRequestID (#181)

* Add an option to enable field mask override (#183)

* Add an option to enable field mask override

* Implement option pattern for PresenceClientInterceptor
* Add WithOverrideFieldMask option to enable field mask override

* Fix minor issues

* provide test to override option

* add test for multiple field masks

* make requestid name consistent with JSON standart (#182)

* update grpc

* use >=1.4.1 for grpc-gateway

* Add common logger with specific fields (#188)

* Add common logger with specific fields

* Add common logger, interceptors with customizable fields

* Fix populating context

* Fix unused arguments

* Fix duplicate append ctx call, rename auxilary func name

* Add custom fields from request headers

* Add err handling if subject key is missing

* Add err handling in case request_id missing

* Begin transaction with options. (#189)

* Begin transaction with options.

  * Extended `Transaction` object with support of begging transaction with
    options (to be able to set isolation level and RO option). Added
    `gorm.BeginTx()` wrapper;
  * Added analog wrapper to do same thing while extracting txn from context;
  * Updated UTs.

* * Reduced code duplication in UTs.
  * Added comments.

* Add stream interceptors (#190)

* Add stream interceptors

* Add UTs, fix subject field handling

* Fix tests

* Improve subject value handling

* Remove redundant ctx returns, fix populating fields into cxt logger

* Add notes to generate mocks

* Add blank line

* Logging interceptor refactor (#192)

* use logrus server interceptors

* lint auth package

* move server stream mock outside of requestid for reuse

* add stream server interceptor for account_id logging

* Add FIXME on ClientInterceptor test

When the test correctly supplies Outgoing metadata, AuthFromMD cannot extract the authorization header because it is designed for Incoming MD only.
The GetAccountID() function will need to be rewritten to work in ClientInterceptors.

* Implement tracing package for toolkit (#193)

* add SpanContextAnnotator
SpanContextAnnotator retrieve current trace.Span from context.Context
or, in case there is no open trace.Span assemble trace.SpanContext from HTTP
headers

* Implement wrapper to extend ochttp.Handler

* Add options to configure what should be added to span

* Implement propogation of request/response headers, and body to span

* Implement wrapper to extend ocgrpc.ServerHandler

* Add options to configure what should be added to span

* Implement propogation of inbound/outbound metadata, and payload to span

* add util functions

* add grpc error into span

* implement simple exporter constructor

* implement obfuscation logic

* move obfuscation factor to constant

* Get lattest span value after calling wrapped handler

* Use library function to assemble span context

* Fix request id key (#197)

* fix request id key

* fix formating

* fix tests

* add test whith deprecated request-id key

* Provide customization to allow passing X-Geo-* headers into gRPC metadata (#201)

* dep ensure

* implement AtalsDefaultHeaderMatcher

* use AtlasDefaultHeaderMatcher by default

* Use AtlasDefaultHeaderMatcher in ExtendedHeaderMatcher

* add ChainHeaderMatcher

* Utilize ChainHeaderMatcher (#202)

* Add unit tests (#203)

* B-30111 - Add UTs

* B-30111 - Add UTs

* Add unit tests

* 'unable to get field from token' spam message (#205)

* 'unable to get field from token' spam message

* fix TestHeadersToAttributes map

* propagating context to gorm transaction (#207)

* Migrate atlas toolkit to go mod (#208)

migrated to go mod

updated travis CI

* Refactor Headers. Util to include Headers into outgoing context

* Refactor Headers. Util to include Headers into outgoing context

* Rename util funcs

* Added support for graceful shutdown (#210)

Added support for disabling automatic server stop

* update Go deps with Dependabot (#209)

* Bump github.com/sirupsen/logrus from 1.4.2 to 1.7.0 (#215)

Bumps [github.com/sirupsen/logrus](https://github.com/sirupsen/logrus) from 1.4.2 to 1.7.0.
- [Release notes](https://github.com/sirupsen/logrus/releases)
- [Changelog](https://github.com/sirupsen/logrus/blob/master/CHANGELOG.md)
- [Commits](sirupsen/logrus@v1.4.2...v1.7.0)

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* Bump github.com/golang/protobuf from 1.4.2 to 1.4.3 (#216)

Bumps [github.com/golang/protobuf](https://github.com/golang/protobuf) from 1.4.2 to 1.4.3.
- [Release notes](https://github.com/golang/protobuf/releases)
- [Commits](golang/protobuf@v1.4.2...v1.4.3)

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* Bump golang from 1.10.0 to 1.15.8 in /tools/debugging (#212)

Bumps golang from 1.10.0 to 1.15.8.

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* Bump github.com/grpc-ecosystem/go-grpc-middleware from 1.2.0 to 1.2.2 (#217)

Bumps [github.com/grpc-ecosystem/go-grpc-middleware](https://github.com/grpc-ecosystem/go-grpc-middleware) from 1.2.0 to 1.2.2.
- [Release notes](https://github.com/grpc-ecosystem/go-grpc-middleware/releases)
- [Changelog](https://github.com/grpc-ecosystem/go-grpc-middleware/blob/master/CHANGELOG.md)
- [Commits](grpc-ecosystem/go-grpc-middleware@v1.2.0...v1.2.2)

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* Bump github.com/DATA-DOG/go-sqlmock from 1.4.1 to 1.5.0 (#218)

Bumps [github.com/DATA-DOG/go-sqlmock](https://github.com/DATA-DOG/go-sqlmock) from 1.4.1 to 1.5.0.
- [Release notes](https://github.com/DATA-DOG/go-sqlmock/releases)
- [Commits](DATA-DOG/go-sqlmock@v1.4.1...v1.5.0)

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* Bump github.com/jinzhu/gorm from 1.9.12 to 1.9.16 (#213)

Bumps [github.com/jinzhu/gorm](https://github.com/jinzhu/gorm) from 1.9.12 to 1.9.16.
- [Release notes](https://github.com/jinzhu/gorm/releases)
- [Commits](jinzhu/gorm@v1.9.12...v1.9.16)

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* Bump github.com/google/uuid from 1.1.1 to 1.2.0 (#219)

Bumps [github.com/google/uuid](https://github.com/google/uuid) from 1.1.1 to 1.2.0.
- [Release notes](https://github.com/google/uuid/releases)
- [Commits](google/uuid@v1.1.1...v1.2.0)

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* Bump golang from 1.15.8 to 1.16.0 in /tools/debugging (#223)

Bumps golang from 1.15.8 to 1.16.0.

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* Bump github.com/sirupsen/logrus from 1.7.0 to 1.8.0 (#225)

Bumps [github.com/sirupsen/logrus](https://github.com/sirupsen/logrus) from 1.7.0 to 1.8.0.
- [Release notes](https://github.com/sirupsen/logrus/releases)
- [Changelog](https://github.com/sirupsen/logrus/blob/master/CHANGELOG.md)
- [Commits](sirupsen/logrus@v1.7.0...v1.8.0)

Signed-off-by: dependabot[bot] <support@github.com>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>

* valid token may not have subject field

* Bump golang from 1.16.0 to 1.16.3 in /tools/debugging

Bumps golang from 1.16.0 to 1.16.3.

Signed-off-by: dependabot[bot] <support@github.com>

* add OldStatusCreatedOnUpdate to support old grpc -> http status mapping

* update comment.

* fix fmt

* Make interceptor accept custom transaction.

Co-authored-by: Drew Wells <drew.wells00@gmail.com>
Co-authored-by: Arash Outadi <aoutadi@infoblox.com>
Co-authored-by: Aliaksei Burau <aburau@infoblox.com>
Co-authored-by: Daniel Garcia <daniel@danielgarcia.info>
Co-authored-by: Daniel Garcia <dgarcia@infoblox.com>
Co-authored-by: Anton Dudko <52532588+addudko@users.noreply.github.com>
Co-authored-by: Maksim Volkov <mvolkov@infoblox.com>
Co-authored-by: Tom Hayward <thayward@infoblox.com>
Co-authored-by: Alexey Bynenkov <54314036+abynenkov-ib@users.noreply.github.com>
Co-authored-by: Pavel Rybintsev <2716513+prybintsev@users.noreply.github.com>
Co-authored-by: Andrei Lavrov <alavrov@infoblox.com>
Co-authored-by: Anton Dudko <a.d.dudko@hotmail.com>
Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>
Co-authored-by: binjip978 <binjip978@gmail.com>
Co-authored-by: Sergei Semenchuk <ssementchouk@infoblox.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

6 participants