gddo-server: add search results and referer to logging.

Log a list of package served to learn what user goes to when searching.
Log referer to learn where does user come from, such as Google search,
github reference link, etc.
Remove unnecessary handler and response writer wrapper since both are
handled by GAE request log.

This fixes golang/gddo#390.

Change-Id: I7ac049ad7723edb229cea0dc8d0c64295981d368
Reviewed-on: https://go-review.googlesource.com/22261
Reviewed-by: Andrew Gerrand <adg@golang.org>
diff --git a/gddo-server/logging.go b/gddo-server/logging.go
index 77a4de7..c80c39d 100644
--- a/gddo-server/logging.go
+++ b/gddo-server/logging.go
@@ -13,33 +13,31 @@
 	"net/http"
 	"time"
 
+	"github.com/golang/gddo/database"
 	"google.golang.org/cloud/logging"
 )
 
-// NewLoggingHandler returns a handler that wraps h but logs each request
+// newGCELogger returns a handler that wraps h but logs each request
 // using Google Cloud Logging service.
-func NewLoggingHandler(h http.Handler, cli *logging.Client) http.Handler {
-	return &loggingHandler{h, cli}
+func newGCELogger(cli *logging.Client) *GCELogger {
+	return &GCELogger{cli}
 }
 
-type loggingHandler struct {
-	handler http.Handler
-	cli     *logging.Client
+type GCELogger struct {
+	cli *logging.Client
 }
 
-func (h *loggingHandler) ServeHTTP(resp http.ResponseWriter, req *http.Request) {
-	t := time.Now().UTC()
-
+// 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.
+func (g *GCELogger) LogEvent(w http.ResponseWriter, r *http.Request, content interface{}) {
 	const sessionCookieName = "GODOC_ORG_SESSION_ID"
-	cookie, err := req.Cookie(sessionCookieName)
+	cookie, err := r.Cookie(sessionCookieName)
 	if err != nil {
 		// Generates a random session id and sends it in response.
-		r, err := randomString()
+		rs, err := randomString()
 		if err != nil {
-			// If error happens during generating the session id, proceed
-			// without logging.
-			log.Println("generating a random session id:", err)
-			h.handler.ServeHTTP(resp, req)
+			log.Println("error generating a random session id: ", err)
 			return
 		}
 		// This cookie is intentionally short-lived and contains no information
@@ -47,34 +45,30 @@
 		// terms and destination pages together to measure search quality.
 		cookie = &http.Cookie{
 			Name:    sessionCookieName,
-			Value:   r,
+			Value:   rs,
 			Expires: time.Now().Add(time.Hour),
 		}
-		http.SetCookie(resp, cookie)
+		http.SetCookie(w, cookie)
 	}
 
-	w := &countingResponseWriter{
-		ResponseWriter: resp,
-		responseStatus: http.StatusOK,
+	// We must not record the client's IP address, or any other information
+	// that might compromise the user's privacy.
+	payload := map[string]interface{}{
+		sessionCookieName: cookie.Value,
+		"path":            r.URL.RequestURI(),
+		"method":          r.Method,
+		"referer":         r.Referer(),
 	}
-	h.handler.ServeHTTP(w, req)
+	if pkgs, ok := content.([]database.Package); ok {
+		payload["packages"] = pkgs
+	}
 
-	// We must not record the client's IP address, referrer URL, or any other
-	// information that might compromise the user's privacy.
-	entry := logging.Entry{
-		Time: t,
-		Payload: map[string]interface{}{
-			sessionCookieName: cookie.Value,
-			"latency":         time.Since(t),
-			"path":            req.URL.RequestURI(),
-			"method":          req.Method,
-			"responseBytes":   w.responseBytes,
-			"status":          w.responseStatus,
-		},
-	}
 	// Log queues the entry to its internal buffer, or discarding the entry
 	// if the buffer was full.
-	h.cli.Log(entry)
+	g.cli.Log(logging.Entry{
+		Time:    time.Now().UTC(),
+		Payload: payload,
+	})
 }
 
 func randomString() (string, error) {
@@ -82,23 +76,3 @@
 	_, err := rand.Read(b)
 	return hex.EncodeToString(b), err
 }
-
-// A countingResponseWriter is a wrapper around an http.ResponseWriter that
-// records the number of bytes written and the status of the response.
-type countingResponseWriter struct {
-	http.ResponseWriter
-
-	responseBytes  int64
-	responseStatus int
-}
-
-func (w *countingResponseWriter) Write(p []byte) (int, error) {
-	written, err := w.ResponseWriter.Write(p)
-	w.responseBytes += int64(written)
-	return written, err
-}
-
-func (w *countingResponseWriter) WriteHeader(status int) {
-	w.responseStatus = status
-	w.ResponseWriter.WriteHeader(status)
-}
diff --git a/gddo-server/main.go b/gddo-server/main.go
index 92907c6..5cb3ed5 100644
--- a/gddo-server/main.go
+++ b/gddo-server/main.go
@@ -302,6 +302,7 @@
 				log.Printf("ERROR db.IncrementPopularScore(%s): %v", pdoc.ImportPath, err)
 			}
 		}
+		gceLogger.LogEvent(resp, req, nil)
 
 		template := "dir"
 		switch {
@@ -573,6 +574,14 @@
 	if err != nil {
 		return err
 	}
+	if gceLogger != nil {
+		// Log up to top 10 packages we served upon a search.
+		logPkgs := pkgs
+		if len(pkgs) > 10 {
+			logPkgs = pkgs[:10]
+		}
+		gceLogger.LogEvent(resp, req, logPkgs)
+	}
 
 	return executeTemplate(resp, "results"+templateExt(req), http.StatusOK, nil,
 		map[string]interface{}{"q": q, "pkgs": pkgs})
@@ -832,6 +841,7 @@
 	httpClient            *http.Client
 	statusImageHandlerPNG http.Handler
 	statusImageHandlerSVG http.Handler
+	gceLogger             *GCELogger
 )
 
 var (
@@ -989,7 +999,7 @@
 		if err := logc.Ping(); err != nil {
 			log.Fatalf("Failed to ping Google Cloud Logging: %v", err)
 		}
-		root = NewLoggingHandler(root, logc)
+		gceLogger = newGCELogger(logc)
 	}
 
 	log.Fatal(http.ListenAndServe(*httpAddr, root))