gddo-server: add logging for start and end of each request

In order to better understand what endpoints are being used
on godoc.org, an entry is now logged for the start and end of each
request. The latency of each request is also logged.

Change-Id: I8198b1206d04564e86b782e3e94964e829d5cc9b
Reviewed-on: https://go-review.googlesource.com/c/gddo/+/209223
Reviewed-by: Tuo Shan <shantuo@google.com>
diff --git a/gddo-server/logging.go b/gddo-server/logging.go
index f32fe3b..edce700 100644
--- a/gddo-server/logging.go
+++ b/gddo-server/logging.go
@@ -27,6 +27,11 @@
 	cli *logging.Logger
 }
 
+// Log creates an entry in Cloud Logging using the given log entry.
+func (g *GCELogger) Log(l logging.Entry) {
+	g.cli.Log(l)
+}
+
 // LogEvent creates an entry in Cloud Logging to record user's behavior. We should only
 // use this to log events we are interested in. General request logs are handled by GAE
 // automatically in request_log and stderr.
diff --git a/gddo-server/main.go b/gddo-server/main.go
index 635c641..52186dc 100644
--- a/gddo-server/main.go
+++ b/gddo-server/main.go
@@ -986,7 +986,35 @@
 }
 
 func (s *server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	start := time.Now()
+	s.logRequestStart(r)
 	s.root.ServeHTTP(w, r)
+	s.logRequestEnd(r, time.Since(start))
+}
+
+func (s *server) logRequestStart(req *http.Request) {
+	if s.gceLogger == nil {
+		return
+	}
+	s.gceLogger.Log(logging.Entry{
+		HTTPRequest: &logging.HTTPRequest{Request: req},
+		Payload:     fmt.Sprintf("%s request start", req.Host),
+		Severity:    logging.Info,
+	})
+}
+
+func (s *server) logRequestEnd(req *http.Request, latency time.Duration) {
+	if s.gceLogger == nil {
+		return
+	}
+	s.gceLogger.Log(logging.Entry{
+		HTTPRequest: &logging.HTTPRequest{
+			Request: req,
+			Latency: latency,
+		},
+		Payload:  fmt.Sprintf("%s request end", req.Host),
+		Severity: logging.Info,
+	})
 }
 
 func main() {