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

httpbp: Set http.Server.ErrorLog #576

Merged
merged 1 commit into from
Oct 27, 2022
Merged

httpbp: Set http.Server.ErrorLog #576

merged 1 commit into from
Oct 27, 2022

Conversation

fishy
Copy link
Member

@fishy fishy commented Oct 27, 2022

It's used by upstream server to log some of the kinda-breaking issues,
for example 1. Since the majority of the http servers at Reddit are
public facing, when those happens it's usually just user messing with
us, not really that the http client we control doing things wrong. This
gives us a way to suppress those logs, and also emit counters to better
track how many times those happened.

This also makes the upstream http server to use the same json logger by
zap as the rest of our code, at warning level.

(I still need to write tests for it, but send it out first to get some early eyes/feedback) done

@fishy fishy requested a review from kylelemons October 27, 2022 18:36
@fishy fishy requested a review from a team as a code owner October 27, 2022 18:36
@fishy fishy requested review from konradreiche and ghirsch-reddit and removed request for a team October 27, 2022 18:36
Copy link
Contributor

@ghirsch-reddit ghirsch-reddit left a comment

Choose a reason for hiding this comment

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

RC'ing to appease Harold. I would love to see an example usage as well, if that's not covered by the tests you add

Comment on lines +240 to +238
// Should not happen, but if it really happens, we just fallback to stdlib
// logger, which is not that big a deal either.
Copy link
Contributor

Choose a reason for hiding this comment

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

Is this because we treat a nil logger as the stdlib logger somewhere? Where does that happen?

Copy link
Member Author

Choose a reason for hiding this comment

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

}, []string{"upstream_issue"})

type issueConfig struct {
rate float64
Copy link
Contributor

Choose a reason for hiding this comment

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

Suggested change
rate float64
sampleRate float64

@fishy
Copy link
Member Author

fishy commented Oct 27, 2022

I would love to see an example usage as well

There's not much to example. Users can supply the map config on how much they want to suppress the logs. If they don't change any code beyond updating baseplate.go, we fallback to 100% sample, so they get the free counter and the log will be in proper json format (instead of using stdlib logger).

@fishy fishy requested a review from ghirsch-reddit October 27, 2022 20:49
Comment on lines +81 to +73
logger.Printf("Hello, golang.org/issue/25192!")
if got, want := sb.String(), `{"level":"warn","msg":"Hello, golang.org/issue/25192!","from":"http-server"}`; strings.TrimSpace(got) != want {
t.Errorf("Got %q, want %q", got, want)
}

sb.Reset()
logger.Printf("Hello, world!")
if got, want := sb.String(), `{"level":"warn","msg":"Hello, world!","from":"http-server"}`; strings.TrimSpace(got) != want {
t.Errorf("Got %q, want %q", got, want)
}
Copy link
Contributor

Choose a reason for hiding this comment

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

🔕 just a nit that you do this differently on line 63

Copy link
Member Author

Choose a reason for hiding this comment

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

that's intentional. it's a long string so I actually prefer to have it in its own line as a const. but in this case I need it twice so a const no longer works.

// Example message:
// URL query contains semicolon, which is no longer a supported separator; parts of the query may be stripped when parsed; see golang.org/issue/25192
if strings.Contains(entry.Message, "golang.org/issue/25192") {
cfg := w.issues[25192]
Copy link
Contributor

Choose a reason for hiding this comment

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

I don't think the map is really helping you here. Since the error message is hard-coded and we are hard coding the supported IDs and so on, I would make a field for each one and just do

w.issue25192.Inc()

etc.

sb.Reset()
logger.Printf("Hello, world!")
const want = `{"level":"warn","msg":"Hello, world!","from":"http-server"}`
if got := sb.String(); strings.TrimSpace(got) != want {
Copy link
Contributor

Choose a reason for hiding this comment

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

🔕 cmp.Diff works well for strings like this, it calls out the part that changed instead of making a human squint at two almost identical lines

Copy link
Member Author

Choose a reason for hiding this comment

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

the problem with cmp.Diff is that you can't declare and assign all of got, want, diff in the same if statement :)

Copy link
Contributor

Choose a reason for hiding this comment

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

Yeah, that is definitely a bummer. I do

if diff := cmp.Diff(got, want); diff != "" {
  t.Errorf("<context> (-got +want)\n%s", diff)
}

which 🤷

httpbp/server.go Outdated
Comment on lines 168 to 171
// When a supported issue id is not in the map,
// currently the default sample rate is 1
// (100% sampled, e.g. not dropping those logs).
// This might be changed to 0 in the future.
Copy link
Contributor

Choose a reason for hiding this comment

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

🔕 I'm in kindof a YAGNI mode here... this is a lot of complexity to carry around for something we might not need.

@fishy fishy requested a review from kylelemons October 27, 2022 22:53
sb.Reset()
logger.Printf("Hello, world!")
const want = `{"level":"warn","msg":"Hello, world!","from":"http-server"}`
if got := sb.String(); strings.TrimSpace(got) != want {
Copy link
Contributor

Choose a reason for hiding this comment

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

Yeah, that is definitely a bummer. I do

if diff := cmp.Diff(got, want); diff != "" {
  t.Errorf("<context> (-got +want)\n%s", diff)
}

which 🤷

It's used by upstream server to log some of the kinda-breaking issues,
for example [1]. Since the majority of the http servers at Reddit are
public facing, when those happens it's usually just user messing with
us, not really that the http client we control doing things wrong. This
gives us a way to suppress those logs, and also emit counters to better
track how many times those happened.

This also makes the upstream http server to use the same json logger by
zap as the rest of our code, at warning level.

[1]: golang/go#25192 (comment)
@fishy fishy merged commit 23a8d5e into reddit:master Oct 27, 2022
@fishy fishy deleted the http-logger branch October 27, 2022 23:55
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

4 participants