Arvados

ResponseWriter doesn't let you read the response status code later, but you could wrap it with a LoggingResponseWriter that does:

https://groups.google.com/forum/#!topic/golang-nuts/fxUz5WK6Hek

Capturing the informal review we just did face-to-face at d4224bfe:

• The WrapRESTRouter code could wrap the mux.Router directly inside MakeRESTRouter, and remove the need for any other code to know it needs to wrap the router in order to add logging.
• The loggingWriter should make a copy of the data that it's being passed and not just store a reference to the slice. If we only care about the first 200 bytes of the response anyway, this could be something like:

type LoggingResponseWriter struct {
    data bytes.Buffer
    status int
    http.ResponseWriter
}

func (w *LoggingResponseWriter) Write(data []bytes) {
    if w.data.Len() < 200 {
        w.Write(data)
    }
    w.ResponseWriter.Write(data)
}

I had some worries about the way this code embeds http.ResponseWriter but after reviewing the docs more closely I'm comfortable that you're right. That's a nice approach.

Reviewing at 0e5dfbb

This looks great. A couple of suggestions for organizing the code:

• say, services/keepstore/router (so it can be imported as git.curoverse.com/arvados.git/services/keepstore/router
• call the router type LoggingRouter instead of RESTRouterWrapper
• rename MakeRESTRouterWrapper to New (so a program which has imported the router package invokes it as router.New()

That makes it easier to untangle this package when we want to import it into another Keep package, and also helps to explain what it is that we're doing with the router. LoggingRouter is more descriptive than RESTRouterWrapper.

Defining methods on a pointer to a struct rather than on the struct itself tends to make the code more consistent. There's a strong convention for doing this with struct types in particular. See https://golang.org/doc/effective_go.html#pointers_vs_values for more details. I'd like to follow this when there isn't a strong reason not to, i.e.:

func (wrapper *RESTRouterWrapper) ServeHTTP(resp http.ResponseWriter, req *http.Request) {

instead of

func (wrapper RESTRouterWrapper) ServeHTTP(resp http.ResponseWriter, req *http.Request) {

(Consequently, MakeRESTRouterWrapper should also return *RESTRouterWrapper)

Tim, addressed all your feedback, except the first one about moving the Logging router into its own package named "router".

When I tried to move this file into router package, the package git.curoverse.com/arvados.git/services/keepstore/router needed to import git.curoverse.com/arvados.git/services/keepstore package (for handler stuff) and the package git.curoverse.com/arvados.git/services/keepstore needed to import git.curoverse.com/arvados.git/services/keepstore/router (for logging router).

I do not (yet) know if this is even permissible or if go has circular references issues etc; but, it does not seem right doing it this way in the first place. I think if we really want to do this, we need to move more of the code into appropriate packages such as handler (handler related code), router, perms, etc while leaving just the "main" related stuff in keepstore package. It seems that at a minimum, we should move all but main related code into a keepstore/somename package and the router into keepstore/router package.

I am not sure if we are interested in going this path now? Let me know what you think. Thanks.

Radhika Chippada wrote:

When I tried to move this file into router package, the package git.curoverse.com/arvados.git/services/keepstore/router needed to import git.curoverse.com/arvados.git/services/keepstore package (for handler stuff) and the package git.curoverse.com/arvados.git/services/keepstore needed to import git.curoverse.com/arvados.git/services/keepstore/router (for logging router).

Ugh. Okay, let's scrap this for now and add a ticket to move the router into its own package.

Couple of comments at 07bf4bb

• Writing arbitrary user-supplied binary data to log files is dangerous. It's easy for users to write data that looks like a real log message, sends control chars to an admin user's terminal, confuses post-processors, etc.
• Current log format can make data indistinguishable from length ("120") (admittedly trivial to fix)
• Buffering a copy of the entire ~64MiB response is wasteful

Instead we could just update a ResponseLength field during Write(), and print that in the log message.

(Is the "log content of small blocks" feature important for some reason I'm not thinking of?)

• Golang says always use tabs to indent, never spaces.
• Go will fix this for you: go fmt services/keepstore/logging_router.go

Tom, addressed your comments. Yes, you are right about printing data and I was also concerned about it, but lost track of it. Thanks for catching.

One question about the length versus data. The log message for PUT would be:

With response data string printed: PUT e4d909c290d0fb1ca068ffaddf22cbd0 200 e4d909c290d0fb1ca068ffaddf22cbd0+44

With length of data string printed: PUT e4d909c290d0fb1ca068ffaddf22cbd0 200 36

Here the log statement is printing the size of data string (e4d909c290d0fb1ca068ffaddf22cbd0+44), rather than the actual data size witch is 44.

Do we want to look for data ending with "+\d" and print the value of "\d" in these cases?

Thanks.

Radhika Chippada wrote:

One question about the length versus data. The log message for PUT would be:

With response data string printed: PUT e4d909c290d0fb1ca068ffaddf22cbd0 200 e4d909c290d0fb1ca068ffaddf22cbd0+44

With length of data string printed: PUT e4d909c290d0fb1ca068ffaddf22cbd0 200 36

Here the log statement is printing the size of data string (e4d909c290d0fb1ca068ffaddf22cbd0+44), rather than the actual data size witch is 44.

Do we want to look for data ending with "+\d" and print the value of "\d" in these cases?

IMHO, no -- the +44 refers to the amount of data available at that block, not the amount of data returned in the HTTP request. We always want to log the latter.

Radhika Chippada wrote:

With length of data string printed: PUT e4d909c290d0fb1ca068ffaddf22cbd0 200 36

Here the log statement is printing the size of data string (e4d909c290d0fb1ca068ffaddf22cbd0+44), rather than the actual data size witch is 44.

Looks good to me -- "number of bytes sent to the client" is a good number to have. For PUT this is pretty boring but for GET it's a bit more useful. When we add support for Range requests it'll get a bit more interesting.

Do we want to look for data ending with "+\d" and print the value of "\d" in these cases?

Nah... let's save this for another day but I think "bytes received from client" would be the appropriate thing to log if we wanted to log the data size for PUT requests.

I wonder if this should be += instead of =?

+       loggingWriter.Length = len(data)

Is there any reason not to print the Length field for non-200 status codes? (It will be boring, like PUT, but consistent and much better for post-processing.)

Great. I update "=" to "+=". I also updated to use the same log statement in both error and success cases. Thanks.

b1f3c94 LGTM, thanks!