storage: log issued SQL query

Change-Id: I89a2ad20d0378077fb90cae45fcc8cab33c147ec
Reviewed-on: https://go-review.googlesource.com/36952
Run-TryBot: Quentin Smith <quentin@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>

storage/app/query.go

@@ -13,6 +13,8 @@ import (
 )
 
 func (a *App) search(w http.ResponseWriter, r *http.Request) {
+	ctx := requestContext(r)
+
 	if err := r.ParseForm(); err != nil {
 		http.Error(w, err.Error(), 500)
 		return
@@ -27,6 +29,8 @@ func (a *App) search(w http.ResponseWriter, r *http.Request) {
 	query := a.DB.Query(q)
 	defer query.Close()
 
+	infof(ctx, "query: %s", query.Debug())
+
 	w.Header().Set("Content-Type", "text/plain; charset=utf-8")
 	bw := benchfmt.NewPrinter(w)
 	for query.Next() {
@@ -36,6 +40,7 @@ func (a *App) search(w http.ResponseWriter, r *http.Request) {
 		}
 	}
 	if err := query.Err(); err != nil {
+		errorf(ctx, "query returned error: %v", err)
 		http.Error(w, err.Error(), 500)
 		return
 	}

storage/db/db.go

@@ -396,6 +396,8 @@ func parseQueryPart(part string) (sql string, args []interface{}, err error) {
 func (db *DB) Query(q string) *Query {
 	qparts := query.SplitWords(q)
 
+	ret := &Query{q: q}
+
 	var args []interface{}
 	query := "SELECT r.Content FROM "
 	for i, part := range qparts {
@@ -403,8 +405,9 @@ func (db *DB) Query(q string) *Query {
 			query += " INNER JOIN "
 		}
 		partSql, partArgs, err := parseQueryPart(part)
+		ret.err = err
 		if err != nil {
-			return &Query{err: err}
+			return ret
 		}
 		query += fmt.Sprintf("(%s) t%d", partSql, i)
 		args = append(args, partArgs...)
@@ -421,11 +424,9 @@ func (db *DB) Query(q string) *Query {
 		query += " USING (UploadID, RecordID)"
 	}
 
-	rows, err := db.sql.Query(query, args...)
-	if err != nil {
-		return &Query{err: err}
-	}
-	return &Query{rows: rows}
+	ret.sqlQuery, ret.sqlArgs = query, args
+	ret.rows, ret.err = db.sql.Query(query, args...)
+	return ret
 }
 
 // Query is the result of a query.
@@ -441,11 +442,27 @@ func (db *DB) Query(q string) *Query {
 //   ...
 type Query struct {
 	rows *sql.Rows
+	// for Debug
+	q        string
+	sqlQuery string
+	sqlArgs  []interface{}
 	// from last call to Next
 	br  *benchfmt.Reader
 	err error
 }
 
+// Debug returns the human-readable state of the query.
+func (q *Query) Debug() string {
+	ret := fmt.Sprintf("q=%q", q.q)
+	if q.sqlQuery != "" || len(q.sqlArgs) > 0 {
+		ret += fmt.Sprintf(" sql={%q %#v}", q.sqlQuery, q.sqlArgs)
+	}
+	if q.err != nil {
+		ret += fmt.Sprintf(" err=%v", q.err)
+	}
+	return ret
+}
+
 // Next prepares the next result for reading with the Result
 // method. It returns false when there are no more results, either by
 // reaching the end of the input or an error.

storage/db/db_test.go

@@ -6,7 +6,6 @@ package db_test
 
 import (
 	"bytes"
-	"context"
 	"fmt"
 	"reflect"
 	"sort"
@@ -15,6 +14,7 @@ import (
 	"testing"
 	"time"
 
+	"golang.org/x/net/context"
 	"golang.org/x/perf/internal/diff"
 	"golang.org/x/perf/storage/benchfmt"
 	. "golang.org/x/perf/storage/db"