[RFC] Rest logging improvements #978

phlogistonjohn · 2018-07-09T19:10:56Z

Issue #887 requests a few improvements to the logging, based on that discussion I've done the following:

Added request logging before an http request is processed, adding more keys to the log lines
Add more specific user agents and a way for callers of the Go rest client api to set more specific agent info
Added the ability for cli tools, specifically glustercli, to pass the original command line arguments to the server so that the server can log them.

Still to-do is the ability to log these items to an additional/separate log file.

I figured I'd throw an RFC PR out to get some feedback on the approaches I took here. I do not expect this PR to be merged in this state, just looking for discussion.

It is useful to log the request as it is being made to the server rather than relying entirely on logging generated after the request. Logging before the request is processed can help a person debugging with understanding when the client first made the request. Log the client's user agent string. Signed-off-by: John Mulligan <[email protected]>

Support having the rest client library send a more specific user agent string to the server. Provide a mechanism for tools built upon that library to add more specific user agent information. Use the api in the glusercli command line tool to specify itself. Signed-off-by: John Mulligan <[email protected]>

Extend the cli such that it can send it's original command line arguments to the server so that the server may log the original command that initiated the api call. Signed-off-by: John Mulligan <[email protected]>

prashanthpai · 2018-07-13T06:21:50Z

I like the overall approach.

It'll be great if changes such as this come with a sample output. I pulled this to local repo to see how it looks like:

curl -s -X GET http://127.0.0.1:24007/v1/peers

INFO[2018-07-13 11:34:52.709635] HTTP Request                                  client=curl/7.53.1 method=GET reqid=80380fc9-c095-4f04-a914-f0ad4a771024 source="[request_logging.go:29:middleware.LogRequest.func1]" subsys=rest url=/v1/peers
INFO[2018-07-13 11:34:52.712011] 127.0.0.1 - - [13/Jul/2018:11:34:52 +0530] "GET /v1/peers HTTP/1.1" 200 224 "" "curl/7.53.1"  reqid=80380fc9-c095-4f04-a914-f0ad4a771024 subsys=rest

glustercli peer list

INFO[2018-07-13 11:35:24.705967] HTTP Request                                  client=Go-http-client/1.1 method=GET reqid=33de6a4a-db30-457f-a626-142e87b5e62e source="[request_logging.go:29:middleware.LogRequest.func1]" subsys=rest url=/v1/peers
INFO[2018-07-13 11:35:24.713151] 127.0.0.1 - - [13/Jul/2018:11:35:24 +0530] "GET /v1/peers HTTP/1.1" 200 224 "" "Go-http-client/1.1"  reqid=33de6a4a-db30-457f-a626-142e87b5e62e subsys=rest

Some observations and suggestion:

We can lose the subsys field if it's not deemed useful
Ensure that source field doesn't get logged for this specific use. I hope moving delete(entry.Data, logging.SourceField) line before logging entry should do it.
Rephrase HTTP Request to clearly indicate that at that point we've only accepted an incoming request but haven't processed it yet.

Still to-do is the ability to log these items to an additional/separate log file.

That is okay for now as it helps in debugging if it's in the same logfile. It's easier to track timelines.

prashanthpai · 2018-07-13T05:11:25Z

glusterd2/middleware/request_logging.go

@@ -14,8 +14,16 @@ import (
 // Apache Common Log Format (CLF)
 func LogRequest(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		entry := log.WithField("reqid", gdctx.GetReqID(r.Context()).String())
+		entry := log.WithFields(log.Fields{
+			"subsys": "rest",


Is subsys an Apache log term with a specific meaning ?

If it's a general term that expands to "subsystem", we don't have other subsystems and this field can be removed.

prashanthpai · 2018-07-13T06:32:03Z

pkg/restclient/common.go

@@ -114,6 +123,8 @@ func (c *Client) do(method string, url string, data interface{}, expectStatusCod
 		req.Header.Set("Authorization", "bearer "+getAuthToken(c.username, c.password))
 	}

+	c.sendOriginArgs(req)


Suggestion: this can be named to setOriginArgs

We have a c.SetOriginArgs which does a different job to sendOriginArgs. The suggested rename makes the code more confusing.

I'd suggest that it be renamed to addOriginArgs, but that would take away the consistent naming with the other "set" methods being called. Maybe also rename 'c.setAgenttoc.addAgent`?

Perhaps we keep SetOriginArgs and rename this to addOriginArgsToHeaders ?

rishubhjain · 2018-07-13T07:10:54Z

glusterd2/middleware/request_logging.go

+			"reqid":  gdctx.GetReqID(r.Context()).String(),
+		}
+		if origin := r.Header.Get("X-Gluster-Origin-Args"); origin != "" {
+			f["origin"] = origin


TRIVIAL: IMO origin seems a bit ambiguous, a better variable name can be chosen, something like orgnArgs.

Sounds good.

aravindavk

Looks good, some minor comments

aravindavk · 2018-07-13T08:07:03Z

glustercli/cmd/common.go

@@ -20,6 +21,8 @@ var (

 func initRESTClient(hostname, user, secret, cacert string, insecure bool) {
 	client = restclient.New(hostname, user, secret, cacert, insecure)
+	client.ExtendAgent(
+		fmt.Sprintf("glustercli/%v", version.GlusterdVersion))


nit: We can have cli version instead of glusterd version. For now it is same, but it can change in future. @prashanthpai your thoughts?

IMO, this should be okay. glustercli and glusterd are almost always built together. We can quickly identify if older/outdated clients connect to more recent glusterd2 by looking at the version if they follow same versioning. A separate version for CLI will makes more sense if it's a separate repo/project.

makes sense. we can update later if that happens.

aravindavk · 2018-07-13T08:15:07Z

pkg/restclient/common.go

+// by prefixing it to the existing agent information.
+// This allows client programs to identify themselves more than
+// just something using the rest client api.
+func (c *Client) ExtendAgent(a string) {


please rename "a" to something meaningful.

aravindavk · 2018-07-13T08:16:19Z

pkg/restclient/common.go

+// inform the server what arguments were provided to generate
+// the api call(s). The contents of the array are meant only for
+// human interpretation but will generally be command line args.
+func (c *Client) SetOriginArgs(a []string) {


same here, please rename "a"

aravindavk · 2018-07-13T08:18:29Z

pkg/restclient/common.go

+
+func (c *Client) sendOriginArgs(req *http.Request) {
+	if len(c.originArgs) != 0 {
+		req.Header.Set("X-Gluster-Origin-Args",


This is nice. is this logged? I don't see this detail in output @prashanthpai posted #978 (comment)

It should be, but only if the client sends it. I'm not exactly sure exactly how @prashanthpai got his examples, but when I incorporate the other feedback for these changes I'll include examples of the logging as well.

My bad. I think I did make glusterd2 as I usually do. I can see it after I recompiled the CLI.

INFO[2018-07-17 10:03:37.209081] HTTP Request client="glustercli/v4.1.0-97.git987fac1 GlusterD2-rest-client/v4.1.0-97.git987fac1 (Go-http-client/1.1)" method=GET origin="1:\"glustercli peer list\"" reqid=817c7683-37dd-4b04-a589-16136deaf766 source="[request_logging.go:29:middleware.LogRequest.func1]" subsys=rest url=/v1/peers INFO[2018-07-17 10:03:37.209832] 127.0.0.1 - - [17/Jul/2018:10:03:37 +0530] "GET /v1/peers HTTP/1.1" 401 71 "" "glustercli/v4.1.0-97.git987fac1 GlusterD2-rest-client/v4.1.0-97.git987fac1 (Go-http-client/1.1)" origin="1:\"glustercli peer list\"" reqid=817c7683-37dd-4b04-a589-16136deaf766 subsys=rest

nice, thanks for the update

atinmu · 2018-07-15T14:39:12Z

Do we need this to extend to sprint 2? Or we can close it in a day's time?

phlogistonjohn · 2018-07-16T17:11:02Z

We can lose the subsys field if it's not deemed useful

Subsys was going to be how I redirected some of the logging into an special purpose log file equivalent to what @atinmu orginally requested. Additionally, I actually think the general approach is good; tag subsystems so that you can easily grep a logfile for the subsystem you care about. Note I'm not deeply in love with the 'subsys' name, but I think there's some value here.

Ensure that source field doesn't get logged for this specific use. I hope moving delete(entry.Data, logging.SourceField) line before logging entry should do it.

When I was working on this change orginally, I was wondering why this was one of the only places that didn't log the source. I tried to make it so that the logging that was originally there continued to skip the

If you really want it gone I think we'll need to tweak the hook that generates the source item rather than
trying to work around it. I will take a look into this - but I may suggest this can go in a separate pr.

Rephrase HTTP Request to clearly indicate that at that point we've only accepted an incoming request but haven't processed it yet.

Good point. Will do.

That is okay for now as it helps in debugging if it's in the same logfile. It's easier to track timelines.

Sure, based on the original issue I was going to add an additional option like `--accesslog [/path/to/file | STDOUT] that would start a seperate "logging stream" for certain log entries (see above). When deployed as a container this could certainly be off by default but in the more traditional deployment the service file might specify --accesslog to create the gd2 equivalent of the command log.

atinmu · 2018-09-14T07:04:45Z

@phlogistonjohn would you mind refreshing this?

phlogistonjohn · 2018-09-20T19:59:01Z

Sorry for the long delay. I will try to get around to this soon.

prashanthpai added the GCS-Sprint1-review-pending label Jul 10, 2018

prashanthpai requested review from kshlm and prashanthpai July 10, 2018 12:07

phlogistonjohn and others added 4 commits July 10, 2018 13:42

rest client: add mechanism to have server log cli arguments

e4b5945

Extend the cli such that it can send it's original command line arguments to the server so that the server may log the original command that initiated the api call. Signed-off-by: John Mulligan <[email protected]>

Merge branch 'master' into jjm-logging-commands-887

39b5ad3

prashanthpai reviewed Jul 13, 2018

View reviewed changes

prashanthpai requested review from aravindavk and prashanthpai July 13, 2018 06:27

prashanthpai reviewed Jul 13, 2018

View reviewed changes

rishubhjain reviewed Jul 13, 2018

View reviewed changes

aravindavk reviewed Jul 13, 2018

View reviewed changes

atinmu removed the GCS-Sprint1-review-pending label Oct 4, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[RFC] Rest logging improvements #978

[RFC] Rest logging improvements #978

phlogistonjohn commented Jul 9, 2018

prashanthpai commented Jul 13, 2018 •

edited

Loading

prashanthpai Jul 13, 2018

prashanthpai Jul 13, 2018

kshlm Jul 13, 2018

phlogistonjohn Jul 16, 2018

rishubhjain Jul 13, 2018

phlogistonjohn Jul 16, 2018

aravindavk left a comment

aravindavk Jul 13, 2018

prashanthpai Jul 13, 2018

aravindavk Jul 13, 2018

aravindavk Jul 13, 2018

aravindavk Jul 13, 2018

aravindavk Jul 13, 2018

phlogistonjohn Jul 16, 2018

prashanthpai Jul 17, 2018

aravindavk Jul 17, 2018

atinmu commented Jul 15, 2018

phlogistonjohn commented Jul 16, 2018

atinmu commented Sep 14, 2018

phlogistonjohn commented Sep 20, 2018

[RFC] Rest logging improvements #978

Are you sure you want to change the base?

[RFC] Rest logging improvements #978

Conversation

phlogistonjohn commented Jul 9, 2018

prashanthpai commented Jul 13, 2018 • edited Loading

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

aravindavk 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

atinmu commented Jul 15, 2018

phlogistonjohn commented Jul 16, 2018

atinmu commented Sep 14, 2018

phlogistonjohn commented Sep 20, 2018

prashanthpai commented Jul 13, 2018 •

edited

Loading