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

[feat] Add a request ID and include it in log lines #1476

Merged
merged 1 commit into from
Feb 17, 2023

Conversation

daenney
Copy link
Member

@daenney daenney commented Feb 11, 2023

Description

This adds the necessary code to:

  • Extend the global logger to allow for hooks that can be used to modify what's getting logged
  • Add a new middleware that:
    • Fetches or generates a Request ID as the first middleware in the chain
    • Plonk the Request ID in both the Gin and stdlib context's
    • Add a hook to the logger to extract the RequestID and log it along with everything else
  • Pull the context with our request ID through just about every log call so we can log it along with anything else

Checklist

Please put an x inside each checkbox to indicate that you've read and followed it: [ ] -> [x]

If this is a documentation change, only the first checkbox must be filled (you can delete the others if you want).

  • I/we have read the GoToSocial contribution guidelines.
  • I/we have discussed the proposed changes already, either in an issue on the repository, or in the Matrix chat.
  • I/we have performed a self-review of added code.
  • I/we have written code that is legible and maintainable by others.
  • I/we have commented the added code, particularly in hard-to-understand areas.
  • I/we have made any necessary changes to documentation.
  • I/we have added tests that cover new code.
  • I/we have run tests and they pass locally with the changes.
  • I/we have run go fmt ./... and golangci-lint run.

@daenney daenney changed the title Plumb a request ID through HTTP and logger Plumb a request ID through HTTP and logger (v2/custom) Feb 11, 2023
@daenney
Copy link
Member Author

daenney commented Feb 11, 2023

Despite the fact that the request ID is now set on the context.Context and that there's a way to retrieve it, a lot of functions that may get called along the way from a request handler simply do log.Info() etc. calling into the global log package. This results in a log line without fields being emitted, so those lines don't emit an entry with a request ID.

If the log.XXX functions would take a context.Context as their first argument it becomes possible to extract a requestID in those functions and call logf with fields not set to nil.

@daenney
Copy link
Member Author

daenney commented Feb 12, 2023

So golang-ci lint is a little unhappy with us due to the context changes I guess. I'm not super convinced it's rightfully complaining about all cases though:

internal/media/cron.go:49:13: Non-inherited new context, use function like `context.WithXXX` instead (contextcheck)
			log.Error(nil, err)
			         ^
internal/media/processingmedia.go:251:33: Function `decodeVideoFrame->decodeVideoFrame$1` should pass the context parameter (contextcheck)
		video, err := decodeVideoFrame(rc)
		                              ^
internal/media/prune.go:89:14: Non-inherited new context, use function like `context.WithXXX` instead (contextcheck)
		if err := f(context.Background()); err != nil {
		           ^
internal/typeutils/astointernal.go:85:12: Non-inherited new context, use function like `context.WithXXX` instead (contextcheck)
		log.Infof(nil, "error extracting account emojis: %s", err)
		         ^
internal/typeutils/astointernal.go:260:43: Function `extractAttachments` should pass the context parameter (contextcheck)
	status.Attachments = c.extractAttachments(statusable)
	                                         ^
internal/config/validate.go:58:13: SA1012: do not pass a nil Context, even if a function permits it; pass context.TODO if you are unsure about which Context to use (staticcheck)
		log.Warnf(nil, "%s was set to 'http'; this should *only* be used for debugging and tests!", ProtocolFlag())
		          ^
internal/cache/util.go:38:13: SA1012: do not pass a nil Context, even if a function permits it; pass context.TODO if you are unsure about which Context to use (staticcheck)
	log.Panicf(nil, "failed %s after %d tries", msg, count)
	           ^
internal/concurrency/workers.go:69:12: SA1012: do not pass a nil Context, even if a function permits it; pass context.TODO if you are unsure about which Context to use (staticcheck)
	log.Infof(nil, "%s created with workers=%d queue=%d",

@daenney daenney marked this pull request as ready for review February 12, 2023 21:19
@daenney
Copy link
Member Author

daenney commented Feb 12, 2023

Thanks to the awesome help of @NyaaaWhatsUpDoc this is now ready to go! Ish. Once we figure out what to do about the lint thing.

@NyaaaWhatsUpDoc
Copy link
Member

Definitely best to disable that linter imo. It's been annoying me for a while :p

@daenney
Copy link
Member Author

daenney commented Feb 12, 2023

Weird extra thing, the following lint warnings are bogus:

internal/media/processingmedia.go:251:33: Function `decodeVideoFrame->decodeVideoFrame$1` should pass the context parameter (contextcheck)
		video, err := decodeVideoFrame(rc)
internal/typeutils/astointernal.go:260:43: Function `extractAttachments` should pass the context parameter (contextcheck)
	status.Attachments = c.extractAttachments(statusable)

Neither of those two functions take a context in their signature.

@tsmethurst
Copy link
Contributor

I'm OK with dropping the contextcheck linter altogether in a separate PR, afaik it hasn't found any actual hits yet, only false positives.

Anyway, reviewing this now :)

Copy link
Contributor

@tsmethurst tsmethurst left a comment

Choose a reason for hiding this comment

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

looking good so far :)

example/config.yaml Outdated Show resolved Hide resolved
.golangci.yml Show resolved Hide resolved
.golangci.yml Show resolved Hide resolved
docs/configuration/observability.md Show resolved Hide resolved
docs/configuration/observability.md Outdated Show resolved Hide resolved
internal/middleware/requestid.go Show resolved Hide resolved
internal/middleware/requestid.go Show resolved Hide resolved
internal/middleware/requestid.go Outdated Show resolved Hide resolved
web/template/404.tmpl Show resolved Hide resolved
web/template/error.tmpl Outdated Show resolved Hide resolved
@daenney daenney changed the title Plumb a request ID through HTTP and logger (v2/custom) [feat] Add a request ID and include it in log lines Feb 13, 2023
@daenney
Copy link
Member Author

daenney commented Feb 13, 2023

The history is a bit messy now and you can't really roll back any individual commit so probably best to squash-merge this

@tsmethurst
Copy link
Contributor

The history is a bit messy now and you can't really roll back any individual commit so probably best to squash-merge this

we always do, don't worry :)

@NyaaaWhatsUpDoc
Copy link
Member

we love squerges

@daenney daenney force-pushed the request-id-custom branch 2 times, most recently from 381cff9 to 4d3a646 Compare February 14, 2023 12:25
@daenney
Copy link
Member Author

daenney commented Feb 14, 2023

I smashed the history to make this easier to rebase. The only way I could find to retain @NyaaaWhatsUpDoc's authorship was the Co-authored-by tag in the commit. I hope that's OK.

This adds a lightweight form of tracing to GTS. Each incoming request is
assigned a Request ID which we then pass on and log in all our log
lines. Any function that gets called downstream from an HTTP handler
should now emit a requestID=value pair whenever it logs something.

Co-authored-by: kim <grufwub@gmail.com>
@daenney
Copy link
Member Author

daenney commented Feb 17, 2023

I rebased this on main, should be good to go with 0.7.0 being out.

@tsmethurst tsmethurst merged commit 68e6d08 into superseriousbusiness:main Feb 17, 2023
@tsmethurst
Copy link
Contributor

Merged, thank you! :)

@daenney daenney deleted the request-id-custom branch February 17, 2023 11:03
@daenney daenney mentioned this pull request Feb 17, 2023
9 tasks
daenney added a commit to daenney/gotosocial that referenced this pull request Feb 17, 2023
This updates the middleware log.WithField calls that create new loggers
to include the context the first time around. Without it the requestID
does not get logged.

Fixup from superseriousbusiness#1476
tsmethurst pushed a commit that referenced this pull request Feb 17, 2023
This updates the middleware log.WithField calls that create new loggers
to include the context the first time around. Without it the requestID
does not get logged.

Fixup from #1476
daenney added a commit to daenney/gotosocial that referenced this pull request Feb 17, 2023
In superseriousbusiness#1476 we updated log.WithFields() but we forgot about
log.WithField(). Also updates a few explicit log.Entry{} creations.
NyaaaWhatsUpDoc pushed a commit that referenced this pull request Feb 17, 2023
In #1476 we updated log.WithFields() but we forgot about
log.WithField(). Also updates a few explicit log.Entry{} creations.
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

3 participants