Track HTTP client requests for /write and /query with /debug/requests #8350

jsternberg · 2017-05-02T20:43:17Z

After using /debug/requests, the client will wait for 30 seconds
(configurable by specifying seconds= in the query parameters) and the
HTTP handler will track every incoming query and write to the system.
After that time period has passed, it will output a JSON blob that looks
very similar to /debug/vars that shows every IP address and user
account (if authentication is used) that connected to the host during
that time.

In the future, we can add more metrics to track. This is an initial
start to aid with debugging machines that connect too often by looking
at a sample of time (like /debug/pprof).

Rebased/mergable
Tests pass
CHANGELOG.md updated
InfluxData Documentation: issue filed or pull request submitted <influxdata/docs.influxdata.com#1122>

jsternberg · 2017-05-02T20:50:35Z

This is an initial try at doing this. Likely, this needs a configuration option to turn it off (or turn it on) and likely needs to keep more statistics than it currently keeps.

jwilder · 2017-05-02T20:51:35Z

services/httpd/requests.go

+	}
+
+	// There is an entry in the request tracker. Increment that.
+	if n, ok := rt.requests[info]; ok {


This needs an RLock to prevent a concurrent map panic.

Ah, I was under the impression that maps could be read from concurrently. That may mean that we can't return the in-use map to be written to /debug/vars.

Concurrent readers are fine provided there are no writers. There is a writer here: https://github.com/influxdata/influxdb/pull/8350/files#diff-badb764b9e9789c5a3bf719f6c815aadR71

There is also a data race because the map is replaced here: https://github.com/influxdata/influxdb/pull/8350/files#diff-badb764b9e9789c5a3bf719f6c815aadR110

jwilder · 2017-05-02T21:04:06Z

services/httpd/requests.go

+		}
+
+		requests := rt.requests
+		rt.requests = make(map[RequestInfo]*int64, len(requests))


Wiping the map each minute might be confusing as a user. In one second, you would see a bunch of writers and in the next they would all be gone, then they might start to show up again. Recording it over time might show very spiky usage too.

It might be better to just take the aggregated map and store it and return that aggregated map from /debug/vars.

Maybe it would be better to just increment the request info always? But then the person would need to read the values over time and use derivative like they do with the other internal monitoring. It seems to me like any attempt to do this without storing some historical data in the database may not work. We would also have to eventually cull any clients that just disappear.

You might be able to use a ring buffer of these maps where each slot is some fixed sized time window (e.g. 10s). As you roll over to new slots, you would wipe them clean of old entries.

jwilder

This is a neat idea. I tried this locally, but didn't get much value out of the resulting JSON returned. For example, running concurrent writes and queries, I just see:

{"::1":{"counter":3846}}

I think it would helpful to segment the counter so you can see /write and /query counts. Also, user-agent or some other identifier would be useful when auth is not enabled.

jwilder · 2017-05-04T20:25:39Z

services/httpd/handler.go

+		return
+	}
+
+	w.Header().Add("Connection", "close")


Why the explicit close?

Anything that uses CloseNotify() needs to have this since the HTTP connection can't be reused. I can remove the CloseNotify() part, but then a lost connection will result in requests continuing to be tracked after the connection is lost.

Ok. Makes sense.

jwilder · 2017-05-04T20:26:48Z

services/httpd/handler.go

@@ -257,6 +268,8 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		}
 	} else if strings.HasPrefix(r.URL.Path, "/debug/vars") {
 		h.serveExpvar(w, r)
+	} else if strings.HasPrefix(r.URL.Path, "/debug/track-requests") {


nit: could this just be /debug/requests?

jwilder · 2017-05-04T20:28:47Z

services/httpd/handler.go

+		h.httpError(w, err.Error(), http.StatusBadRequest)
+		return
+	} else {
+		d = time.Duration(seconds) * time.Second


Should probably have a cap on this. If you did s=99999999999, you might be able DOS/OOM the server.

jwilder · 2017-05-04T20:29:14Z

services/httpd/handler.go

+func (h *Handler) serveTrackRequests(w http.ResponseWriter, r *http.Request) {
+	var d time.Duration
+	if s := r.URL.Query().Get("seconds"); s == "" {
+		h.httpError(w, "missing required seconds parameter", http.StatusBadRequest)


Could we have a default of say 10s if one is not specified?

jwilder · 2017-05-04T20:51:09Z

services/httpd/handler.go

+	if h.requestTracker != nil {
+		return
+	}
+	h.requestTracker = NewRequestTracker()


This looks like a data race as there could be other goroutines checking for h.requestTracker. Maybe use an atomic.Value to avoid using a lock?

This can be removed. This was only used previously because the request tracker had a timer. Now it doesn't have a timer anymore so I can just move it to the handler creation.

jwilder · 2017-05-04T20:55:03Z

services/httpd/service.go

@@ -151,6 +151,10 @@ func (s *Service) Open() error {
 		time.Sleep(10 * time.Millisecond)
 	}

+	// Begin to track requests.
+	s.Logger.Info("Tracking HTTP requests")


This looks scary. Remove?

Also, since this is behind the /debug endpoint, probably need to check that pprof is enabled for enabling this.

jwilder · 2017-05-04T21:05:56Z

services/httpd/requests.go

+
+	for {
+		n := rt.rand.Int63()
+		if _, ok := rt.profiles[n]; ok {


Why not just use a slice and append the new profile to it? Id would be len(rt.profiles).

Wouldn't that make it difficult to remove? A linked list might actually be better for this kind of thing.

Is there 1 profiles map for each request to /track-requests? I can't imagine that there would be a lot of concurrent tracking requests in practice.

The idea is that each request to profile gets its own map so it can have its own tracking. Then, internally, there's a map for the requests themselves.

So there's one profiles map (or list) and there's on entry in that map (or list) per request. A slice would technically work, but then removing the entry when the time is finished is O(n) for removal and would shift the index of all of the other profiles making it harder for them to remove.

I've pushed the change that I made to use list.List instead which should be better for this situation.

jwilder · 2017-05-04T21:13:43Z

Other dimensions that might be useful to record as well are db and rp.

jsternberg · 2017-05-05T15:30:50Z

When it comes to /write and /query, do we want the format to be:

{
    "127.0.0.1": {
        "writes": 12,
        "queries": 5,
    },
}

Or

{
    "/query": {
        "127.0.0.1": 5
    },
    "/write": {
        "127.0.0.1": 12,
    },
}

If you're only looking for one of the two, the second might be more useful since it separates the information to only other data that's related to it. But the first might make more sense organizationally.

jwilder · 2017-05-05T15:44:54Z

I was thinking the first:

{
    "127.0.0.1": {
        "writes": 12,
        "queries": 5,
    },
}

Mainly because I was looking for a specific IP first and then figuring out what it was doing. The latter would require me to look at writes and then find my ip, then queries and find my IP again.

jwilder

Were you going to change the JSON output?

jwilder · 2017-05-05T17:36:20Z

services/httpd/handler.go

@@ -283,6 +292,10 @@ func (h *Handler) serveQuery(w http.ResponseWriter, r *http.Request, user *meta.
 		atomic.AddInt64(&h.stats.QueryRequestDuration, time.Since(start).Nanoseconds())
 	}(time.Now())

+	if h.requestTracker != nil {


Looks like this should never be nil now right?

jwilder · 2017-05-05T17:42:04Z

services/httpd/requests.go

+	Requests map[RequestInfo]*RequestStats
+	tracker  *RequestTracker
+	elem     *list.Element
+	mu       sync.RWMutex


Can you move this above the items that it protects. So above Requests

jwilder · 2017-05-05T17:44:26Z

services/httpd/handler.go

+
+	w.Header().Add("Connection", "close")
+	requests := make(map[string]*RequestStats, len(profile.Requests))
+	for req, st := range profile.Requests {


Requests is accessed w/o a lock here but is accessed w/ one in Add: https://github.com/influxdata/influxdb/pull/8350/files#diff-badb764b9e9789c5a3bf719f6c815aadR40

Looks like a possible data race.

Since the profile has been stopped, it shouldn't be modified any longer. The lock should only be needed while the profile is happening.

jwilder · 2017-05-05T17:45:09Z

services/httpd/requests.go

+
+type RequestTracker struct {
+	profiles *list.List
+	mu       sync.RWMutex


Can you move this above profiles so it's clear what it protects?

jwilder · 2017-05-05T17:45:48Z

services/httpd/handler.go

@@ -585,6 +598,10 @@ func (h *Handler) serveWrite(w http.ResponseWriter, r *http.Request, user *meta.
 		atomic.AddInt64(&h.stats.WriteRequestDuration, time.Since(start).Nanoseconds())
 	}(time.Now())

+	if h.requestTracker != nil {


jsternberg · 2017-05-05T21:08:07Z

I'm also thinking this should output the JSON in a similar manner to /debug/vars, but I'll do that after we work out the other details.

jwilder

Changelog?

After using `/debug/requests`, the client will wait for 30 seconds (configurable by specifying `seconds=` in the query parameters) and the HTTP handler will track every incoming query and write to the system. After that time period has passed, it will output a JSON blob that looks very similar to `/debug/vars` that shows every IP address and user account (if authentication is used) that connected to the host during that time. In the future, we can add more metrics to track. This is an initial start to aid with debugging machines that connect too often by looking at a sample of time (like `/debug/pprof`).

jsternberg · 2017-05-09T15:23:11Z

I squashed the PR, modified the format to look more like /debug/vars for easier readability, and updated the changelog.

jsternberg added the review label May 2, 2017

jsternberg requested a review from jwilder May 2, 2017 20:49

jwilder suggested changes May 2, 2017

View reviewed changes

jsternberg force-pushed the js-request-tracker branch 2 times, most recently from fcf09dd to b994f76 Compare May 4, 2017 20:21

jwilder suggested changes May 4, 2017

View reviewed changes

jwilder suggested changes May 5, 2017

View reviewed changes

jwilder approved these changes May 8, 2017

View reviewed changes

jsternberg force-pushed the js-request-tracker branch from 194364c to 2780630 Compare May 9, 2017 15:21

jsternberg changed the title ~~Track the HTTP requests that come into the system for debugging~~ Track HTTP client requests for /write and /query with /debug/requests May 9, 2017

jsternberg mentioned this pull request May 9, 2017

[InfluxDB] Document /debug/requests influxdata/docs.influxdata.com-ARCHIVE#1122

Closed

jsternberg merged commit 38735b2 into master May 9, 2017

jsternberg deleted the js-request-tracker branch May 9, 2017 18:53

jsternberg removed the review label May 9, 2017

rbetts added this to the 1.3.0 milestone May 25, 2017

Track HTTP client requests for /write and /query with /debug/requests #8350

Track HTTP client requests for /write and /query with /debug/requests #8350

Conversation

jsternberg commented May 2, 2017 • edited Loading

jsternberg commented May 2, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jwilder left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jwilder commented May 4, 2017

jsternberg commented May 5, 2017

jwilder commented May 5, 2017 • edited Loading

jwilder left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jsternberg commented May 5, 2017

jwilder left a comment

Choose a reason for hiding this comment

jsternberg commented May 9, 2017

jsternberg commented May 2, 2017 •

edited

Loading

jwilder commented May 5, 2017 •

edited

Loading