From 72fc88f33da3e67c327c0fee57d996fdf8b8d49a Mon Sep 17 00:00:00 2001 From: luke Date: Wed, 15 Dec 2021 18:33:20 -0600 Subject: [PATCH 1/6] mysql: Batch select queries when required. This commit updates the mysql package to batch SELECT queries if the number of records being requested exceedes the MySQL limit for the maximum number placeholders that can be included in a prepared statement. --- .../backendv2/tstorebe/store/mysql/mysql.go | 171 ++++++++++++------ .../tstorebe/store/mysql/mysql_test.go | 111 ++++++++++++ unittest/unittest.go | 29 ++- 3 files changed, 258 insertions(+), 53 deletions(-) create mode 100644 politeiad/backendv2/tstorebe/store/mysql/mysql_test.go diff --git a/politeiad/backendv2/tstorebe/store/mysql/mysql.go b/politeiad/backendv2/tstorebe/store/mysql/mysql.go index 629c597ba..3f6329d7e 100644 --- a/politeiad/backendv2/tstorebe/store/mysql/mysql.go +++ b/politeiad/backendv2/tstorebe/store/mysql/mysql.go @@ -8,11 +8,13 @@ import ( "context" "database/sql" "fmt" + "strings" "sync/atomic" "time" "github.com/decred/politeia/politeiad/backendv2/tstorebe/store" "github.com/decred/politeia/util" + "github.com/pkg/errors" // MySQL driver. _ "github.com/go-sql-driver/mysql" @@ -28,6 +30,11 @@ const ( // Database table names tableNameKeyValue = "kv" tableNameNonce = "nonce" + + // maxPlaceholders is the maximum number of placeholders, "(?, ?, ?)", that + // can be used in a prepared statement. MySQL uses an uint16 for this, so + // the limit is the the maximum value of an uint16. + maxPlaceholders = 65536 ) // tableKeyValue defines the key-value table. @@ -201,66 +208,49 @@ func (s *mysql) Get(keys []string) (map[string][]byte, error) { return nil, store.ErrShutdown } - ctx, cancel := ctxWithTimeout() - defer cancel() + // Build the select statements + statements := buildSelectStatements(keys, maxPlaceholders) - // Build query. A placeholder parameter (?) is required for each - // key being requested. - // - // Ex 3 keys: "SELECT k, v FROM kv WHERE k IN (?, ?, ?)" - sql := "SELECT k, v FROM kv WHERE k IN (" - for i := 0; i < len(keys); i++ { - sql += "?" - // Don't add a comma on the last one - if i < len(keys)-1 { - sql += "," - } - } - sql += ");" - - log.Tracef("%v", sql) - - // The keys must be converted to []interface{} for the query method - // to accept them. - args := make([]interface{}, len(keys)) - for i, v := range keys { - args[i] = v - } + // Execute the statements + reply := make(map[string][]byte, len(keys)) + for i, e := range statements { + log.Debugf("Executing select statement %v/%v", i, len(statements)) - // Get blobs - rows, err := s.db.QueryContext(ctx, sql, args...) - if err != nil { - return nil, fmt.Errorf("query: %v", err) - } - defer rows.Close() + ctx, cancel := ctxWithTimeout() + defer cancel() - reply := make(map[string][]byte, len(keys)) - for rows.Next() { - var k string - var v []byte - err = rows.Scan(&k, &v) + rows, err := s.db.QueryContext(ctx, e.Query, e.Args...) if err != nil { - return nil, fmt.Errorf("scan: %v", err) + return nil, errors.WithStack(err) } - reply[k] = v - } - err = rows.Err() - if err != nil { - return nil, fmt.Errorf("next: %v", err) - } + defer rows.Close() + + // Unpack the reply + reply := make(map[string][]byte, len(keys)) + for rows.Next() { + var k string + var v []byte + err = rows.Scan(&k, &v) + if err != nil { + return nil, errors.WithStack(err) + } + + // Decrypt the blob if required + if isEncrypted(v) { + log.Tracef("Encrypted blob: %v", k) + v, _, err = s.decrypt(v) + if err != nil { + return nil, err + } + } - // Decrypt data blobs - for k, v := range reply { - encrypted := isEncrypted(v) - log.Tracef("Blob is encrypted: %v", encrypted) - if !encrypted { - continue + // Save the blob + reply[k] = v } - b, _, err := s.decrypt(v) + err = rows.Err() if err != nil { - return nil, fmt.Errorf("decrypt: %v", err) + return nil, errors.WithStack(err) } - reply[k] = b } return reply, nil @@ -279,6 +269,85 @@ func (s *mysql) Close() { s.db.Close() } +// selectStatement contains the query string and arguments for a SELECT +// statement. +type selectStatement struct { + Query string + Args []interface{} +} + +// buildSelectStatements builds the SELECT statements that can be executed +// against the MySQL key-value store. The maximum number of records that will +// be retrieved in any individual SELECT statement is determined by the size +// argument. The keys are split up into multiple statements if they exceed this +// limit. +func buildSelectStatements(keys []string, size int) []selectStatement { + statements := make([]selectStatement, 0, (len(keys)/size)+1) + var startIdx int + for startIdx < len(keys) { + // Find the end index + endIdx := startIdx + size + if endIdx > len(keys) { + // We've reached the end of the slice + endIdx = len(keys) + } + + // startIdx is included. endIdx is excluded. + statementKeys := keys[startIdx:endIdx] + + // Build the query + q := buildSelectQuery(len(statementKeys)) + log.Tracef("%v", q) + + // Convert the keys to interfaces. The sql query + // methods require arguments be interfaces. + args := make([]interface{}, len(statementKeys)) + for i, v := range statementKeys { + args[i] = v + } + + // Save the statement + statements = append(statements, selectStatement{ + Query: q, + Args: args, + }) + + // Update the start index + startIdx = endIdx + } + + return statements +} + +// buildSelectQuery returns a query string for the MySQL key-value store. +// +// Example: "SELECT k, v FROM kv WHERE k IN (?,?);" +func buildSelectQuery(placeholders int) string { + return fmt.Sprintf("SELECT k, v FROM kv WHERE k IN %v;", + buildPlaceholders(placeholders)) +} + +// buildPlaceholders builds and returns a parameter placeholder string with the +// specified number of placeholders. +// +// Input: 1 Output: "(?)" +// Input: 3 Output: "(?,?,?)" +func buildPlaceholders(placeholders int) string { + var b strings.Builder + + b.WriteString("(") + for i := 0; i < placeholders; i++ { + b.WriteString("?") + // Don't add a comma on the last one + if i < placeholders-1 { + b.WriteString(",") + } + } + b.WriteString(")") + + return b.String() +} + // New connects to a mysql instance using the given connection params, // and returns pointer to the created mysql struct. func New(host, user, password, dbname string) (*mysql, error) { diff --git a/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go b/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go new file mode 100644 index 000000000..d3f10f75b --- /dev/null +++ b/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go @@ -0,0 +1,111 @@ +// Copyright (c) 2021 The Decred developers +// Use of this source code is governed by an ISC +// license that can be found in the LICENSE file. + +package mysql + +import ( + "testing" + + "github.com/decred/politeia/unittest" +) + +func TestBuildSelectStatements(t *testing.T) { + var ( + // sizeLimit is the max number of placeholders + // that the function will include in a single + // select statement. + sizeLimit = 2 + + // Test keys + key1 = "key1" + key2 = "key2" + key3 = "key3" + key4 = "key4" + ) + var tests = []struct { + name string + keys []string + statements []selectStatement + }{ + { + "one statement under the size limit", + []string{key1}, + []selectStatement{ + { + Query: buildSelectQuery(1), + Args: []interface{}{key1, key2}, + }, + }, + }, + { + "one statement at the size limit", + []string{key1, key2}, + []selectStatement{ + { + Query: buildSelectQuery(2), + Args: []interface{}{key1, key2}, + }, + }, + }, + { + "second statement under the size limit", + []string{key1, key2, key3}, + []selectStatement{ + { + Query: buildSelectQuery(2), + Args: []interface{}{key1, key2}, + }, + { + Query: buildSelectQuery(1), + Args: []interface{}{key3}, + }, + }, + }, + { + "second statement at the size limit", + []string{key1, key2, key3, key4}, + []selectStatement{ + { + Query: buildSelectQuery(2), + Args: []interface{}{key1, key2}, + }, + { + Query: buildSelectQuery(2), + Args: []interface{}{key3, key4}, + }, + }, + }, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + // Run the test + statements := buildSelectStatements(tc.keys, sizeLimit) + + // Verify the output + diff := unittest.DeepEqual(statements, tc.statements) + if diff != "" { + t.Error(diff) + } + }) + } +} + +func TestBuildPlaceholders(t *testing.T) { + var tests = []struct { + placeholders int + output string + }{ + {0, "()"}, + {1, "(?)"}, + {3, "(?,?,?)"}, + } + for _, tc := range tests { + t.Run("", func(t *testing.T) { + output := buildPlaceholders(tc.placeholders) + if output != tc.output { + t.Errorf("got %v, want %v", output, tc.output) + } + }) + } +} diff --git a/unittest/unittest.go b/unittest/unittest.go index 742ed6407..83169241e 100644 --- a/unittest/unittest.go +++ b/unittest/unittest.go @@ -1,12 +1,15 @@ // Copyright (c) 2021 The Decred developers -// Use of this source code is governed by an ISC license that can be found in -// the LICENSE file. +// Use of this source code is governed by an ISC +// license that can be found in the LICENSE file. package unittest import ( "fmt" "reflect" + "strings" + + "github.com/go-test/deep" ) // TestGenericConstMap tests a map of an error constant type and verifies that @@ -49,3 +52,25 @@ func TestGenericConstMap(errorsMap interface{}, lastError uint64) error { return nil } + +// DeepEqual checks for deep equality between the provided structures. An empty +// string is returned if the structures are deeply equal. A pretty printed +// string that contains the differences is returned if the structures are not +// deeply equal. The equality check goes a max of 10 levels deep. +func DeepEqual(got, want interface{}) string { + diffs := deep.Equal(got, want) + if diffs == nil { + // got and want are deeply equal + return "" + } + + // Not deeply equal. Pretty print the diffs. + var b strings.Builder + b.WriteString("value are not deeply equal; got != want: \n") + for _, v := range diffs { + b.WriteString(v) + b.WriteString("\n") + } + + return b.String() +} From a6af7d9bc35d53073ba53e978d9240b536f62b4c Mon Sep 17 00:00:00 2001 From: luke Date: Wed, 15 Dec 2021 18:50:41 -0600 Subject: [PATCH 2/6] Fix test. --- politeiad/backendv2/tstorebe/store/mysql/mysql_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go b/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go index d3f10f75b..819b86bac 100644 --- a/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go +++ b/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go @@ -34,7 +34,7 @@ func TestBuildSelectStatements(t *testing.T) { []selectStatement{ { Query: buildSelectQuery(1), - Args: []interface{}{key1, key2}, + Args: []interface{}{key1}, }, }, }, From 5433721790507506d37866bb90a14124721187c6 Mon Sep 17 00:00:00 2001 From: luke Date: Thu, 16 Dec 2021 19:20:10 -0600 Subject: [PATCH 3/6] Add sql mock test for single query. --- .../tstorebe/store/mysql/encrypt_test.go | 11 +-- .../backendv2/tstorebe/store/mysql/mysql.go | 7 +- .../tstorebe/store/mysql/mysql_test.go | 90 +++++++++++++++++++ 3 files changed, 98 insertions(+), 10 deletions(-) diff --git a/politeiad/backendv2/tstorebe/store/mysql/encrypt_test.go b/politeiad/backendv2/tstorebe/store/mysql/encrypt_test.go index c40cda6da..005852e8a 100644 --- a/politeiad/backendv2/tstorebe/store/mysql/encrypt_test.go +++ b/politeiad/backendv2/tstorebe/store/mysql/encrypt_test.go @@ -3,19 +3,14 @@ package mysql import ( "bytes" "testing" - - "github.com/decred/politeia/util" ) func TestEncryptDecrypt(t *testing.T) { - password := "passwordsosikrit" blob := []byte("encryptmeyo") - // setup fake context - s := &mysql{ - testing: true, - } - s.argon2idKey(password, util.NewArgon2Params()) + // Setup a mysql struct + s, cleanup := newTestMySQL(t) + defer cleanup() // Encrypt and make sure cleartext isn't the same as the encypted blob. eb, err := s.encrypt(nil, nil, blob) diff --git a/politeiad/backendv2/tstorebe/store/mysql/mysql.go b/politeiad/backendv2/tstorebe/store/mysql/mysql.go index 3f6329d7e..d8b4fbdc1 100644 --- a/politeiad/backendv2/tstorebe/store/mysql/mysql.go +++ b/politeiad/backendv2/tstorebe/store/mysql/mysql.go @@ -12,6 +12,7 @@ import ( "sync/atomic" "time" + "github.com/DATA-DOG/go-sqlmock" "github.com/decred/politeia/politeiad/backendv2/tstorebe/store" "github.com/decred/politeia/util" "github.com/pkg/errors" @@ -57,7 +58,10 @@ type mysql struct { shutdown uint64 db *sql.DB key [32]byte - testing bool // Only set during unit tests + + // The following fields are only used during unit tests. + testing bool + mock sqlmock.Sqlmock } func ctxWithTimeout() (context.Context, func()) { @@ -226,7 +230,6 @@ func (s *mysql) Get(keys []string) (map[string][]byte, error) { defer rows.Close() // Unpack the reply - reply := make(map[string][]byte, len(keys)) for rows.Next() { var k string var v []byte diff --git a/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go b/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go index 819b86bac..40e47d80e 100644 --- a/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go +++ b/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go @@ -5,11 +5,101 @@ package mysql import ( + "bytes" "testing" + "github.com/DATA-DOG/go-sqlmock" "github.com/decred/politeia/unittest" + "github.com/decred/politeia/util" ) +// newTestMySQL returns a new mysql structure that has been setup for testing. +func newTestMySQL(t *testing.T) (*mysql, func()) { + t.Helper() + + // Setup the mock sql database + opt := sqlmock.QueryMatcherOption(sqlmock.QueryMatcherEqual) + db, mock, err := sqlmock.New(opt) + if err != nil { + t.Fatal(err) + } + cleanup := func() { + defer db.Close() + } + + // Setup the mysql struct + s := &mysql{ + db: db, + testing: true, + mock: mock, + } + + // Derive a test encryption key + password := "passwordsosikrit" + s.argon2idKey(password, util.NewArgon2Params()) + + return s, cleanup +} + +func TestGet(t *testing.T) { + // Setup the mysql test struct + s, cleanup := newTestMySQL(t) + defer cleanup() + + // Test the single query code path + testGetSingleQuery(t, s) + + // Test the multiple query code path +} + +// testGetSingleQuery tests the mysql Get() method when the number of records +// being retrieved can be fit into a single MySQL SELECT statement. +func testGetSingleQuery(t *testing.T, s *mysql) { + var ( + // Test params + key1 = "key1" + key2 = "key2" + value1 = []byte("value1") + value2 = []byte("value2") + + // rows contains the rows that will be returned from the mocked sql query. + rows = sqlmock.NewRows([]string{"k", "v"}). + AddRow(key1, value1). + AddRow(key2, value2) + ) + + // Setup the sql expectations + s.mock.ExpectQuery("SELECT k, v FROM kv WHERE k IN (?,?);"). + WithArgs(key1, key2). + WillReturnRows(rows). + RowsWillBeClosed() + + // Run the test + blobs, err := s.Get([]string{key1, key2}) + if err != nil { + t.Error(err) + } + + // Verify the sql expectations + err = s.mock.ExpectationsWereMet() + if err != nil { + t.Error(err) + } + + // Verify the returned value + if len(blobs) != 2 { + t.Errorf("got %v blobs, want 2", len(blobs)) + } + v1 := blobs[key1] + if !bytes.Equal(v1, value1) { + t.Errorf("got '%s' for value 1; want '%s'", v1, value1) + } + v2 := blobs[key2] + if !bytes.Equal(v2, value2) { + t.Errorf("got '%s' for value 2; want '%s'", v2, value2) + } +} + func TestBuildSelectStatements(t *testing.T) { var ( // sizeLimit is the max number of placeholders From 38b78cc9258107a39d5fcb1d2fc7688b5da8f6aa Mon Sep 17 00:00:00 2001 From: luke Date: Fri, 17 Dec 2021 13:09:11 -0600 Subject: [PATCH 4/6] Add multi query get test. --- .../tstorebe/store/mysql/mysql_test.go | 94 ++++++++++++++++++- 1 file changed, 91 insertions(+), 3 deletions(-) diff --git a/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go b/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go index 40e47d80e..a04296dda 100644 --- a/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go +++ b/politeiad/backendv2/tstorebe/store/mysql/mysql_test.go @@ -6,6 +6,7 @@ package mysql import ( "bytes" + "fmt" "testing" "github.com/DATA-DOG/go-sqlmock" @@ -47,9 +48,14 @@ func TestGet(t *testing.T) { defer cleanup() // Test the single query code path - testGetSingleQuery(t, s) + t.Run("single query", func(t *testing.T) { + testGetSingleQuery(t, s) + }) // Test the multiple query code path + t.Run("multi query", func(t *testing.T) { + testGetMultiQuery(t, s) + }) } // testGetSingleQuery tests the mysql Get() method when the number of records @@ -62,7 +68,8 @@ func testGetSingleQuery(t *testing.T, s *mysql) { value1 = []byte("value1") value2 = []byte("value2") - // rows contains the rows that will be returned from the mocked sql query. + // rows contains the rows that will be returned + // from the mocked sql query. rows = sqlmock.NewRows([]string{"k", "v"}). AddRow(key1, value1). AddRow(key2, value2) @@ -100,6 +107,86 @@ func testGetSingleQuery(t *testing.T, s *mysql) { } } +// testGetMultiQuery tests the mysql Get() method when the number of records +// being retrieved cannot fit into a single MySQL SELECT statement and must +// be broken up into multiple SELECT statements. +func testGetMultiQuery(t *testing.T, s *mysql) { + // Prepare the test data. The maximum number of records + // that can be returned in a single SELECT statement is + // limited by the maxPlaceholders variable. We multiply + // this by 2 in order to ensure that multiple queries + // are required. + var ( + keysCount = maxPlaceholders * 2 + keys = make([]string, 0, keysCount) + + // These variables contain the rows that will be + // returned from each mocked sql query. + rows1 = sqlmock.NewRows([]string{"k", "v"}) + rows2 = sqlmock.NewRows([]string{"k", "v"}) + ) + for i := 0; i < keysCount; i++ { + key := fmt.Sprintf("key%v", i) + value := []byte(fmt.Sprintf("value%v", i)) + keys = append(keys, key) + + if i < keysCount/2 { + // Add to the first query results + rows1.AddRow(key, value) + } else { + // Add to the second query results + rows2.AddRow(key, value) + } + } + + // Setup the sql expectations for both queries + query := buildSelectQuery(keysCount / 2) + s.mock.ExpectQuery(query). + WillReturnRows(rows1). + RowsWillBeClosed() + s.mock.ExpectQuery(query). + WillReturnRows(rows2). + RowsWillBeClosed() + + // Run the test + blobs, err := s.Get(keys) + if err != nil { + t.Errorf("multi query get failed; skipped printing " + + "the error for readability") + } + + // Verify the sql expectations + err = s.mock.ExpectationsWereMet() + if err != nil { + t.Errorf("multi query sql expectations were not ; " + + "met; skipped printing the error for readability") + } + + // Verify the returned values contain entries from both + // queries. + var ( + idx1 = keysCount/2 - 1 + idx2 = keysCount/2 + 2 + + key1 = fmt.Sprintf("key%v", idx1) + key2 = fmt.Sprintf("key%v", idx2) + + value1 = []byte(fmt.Sprintf("value%v", idx1)) + value2 = []byte(fmt.Sprintf("value%v", idx2)) + ) + if len(blobs) != keysCount { + t.Errorf("got %v blobs, want %v", len(blobs), keysCount) + } + v1 := blobs[key1] + if !bytes.Equal(v1, value1) { + t.Errorf("got '%s' for value 1; want '%s'", v1, value1) + } + v2 := blobs[key2] + if !bytes.Equal(v2, value2) { + t.Errorf("got '%s' for value 2; want '%s'", v2, value2) + } +} + func TestBuildSelectStatements(t *testing.T) { var ( // sizeLimit is the max number of placeholders @@ -191,7 +278,8 @@ func TestBuildPlaceholders(t *testing.T) { {3, "(?,?,?)"}, } for _, tc := range tests { - t.Run("", func(t *testing.T) { + name := fmt.Sprintf("%v placeholders", tc.placeholders) + t.Run(name, func(t *testing.T) { output := buildPlaceholders(tc.placeholders) if output != tc.output { t.Errorf("got %v, want %v", output, tc.output) From d9b03b439ad7dc25c7deb1e2bcd36a486ca4333c Mon Sep 17 00:00:00 2001 From: luke Date: Fri, 17 Dec 2021 16:14:46 -0600 Subject: [PATCH 5/6] Improve debug logging. --- politeiad/backendv2/tstorebe/store/mysql/mysql.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/politeiad/backendv2/tstorebe/store/mysql/mysql.go b/politeiad/backendv2/tstorebe/store/mysql/mysql.go index d8b4fbdc1..52665b22b 100644 --- a/politeiad/backendv2/tstorebe/store/mysql/mysql.go +++ b/politeiad/backendv2/tstorebe/store/mysql/mysql.go @@ -215,10 +215,13 @@ func (s *mysql) Get(keys []string) (map[string][]byte, error) { // Build the select statements statements := buildSelectStatements(keys, maxPlaceholders) + log.Debugf("Get %v blobs using %v prepared statements", + len(keys), len(statements)) + // Execute the statements reply := make(map[string][]byte, len(keys)) for i, e := range statements { - log.Debugf("Executing select statement %v/%v", i, len(statements)) + log.Debugf("Executing select statement %v/%v", i+1, len(statements)) ctx, cancel := ctxWithTimeout() defer cancel() From c42dba6b4cdc57aebcf966c553b0326205d08788 Mon Sep 17 00:00:00 2001 From: luke Date: Fri, 17 Dec 2021 17:36:20 -0600 Subject: [PATCH 6/6] Off by one error. --- politeiad/backendv2/tstorebe/store/mysql/mysql.go | 2 +- politeiad/v2.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/politeiad/backendv2/tstorebe/store/mysql/mysql.go b/politeiad/backendv2/tstorebe/store/mysql/mysql.go index 52665b22b..fedcbfb97 100644 --- a/politeiad/backendv2/tstorebe/store/mysql/mysql.go +++ b/politeiad/backendv2/tstorebe/store/mysql/mysql.go @@ -35,7 +35,7 @@ const ( // maxPlaceholders is the maximum number of placeholders, "(?, ?, ?)", that // can be used in a prepared statement. MySQL uses an uint16 for this, so // the limit is the the maximum value of an uint16. - maxPlaceholders = 65536 + maxPlaceholders = 65535 ) // tableKeyValue defines the key-value table. diff --git a/politeiad/v2.go b/politeiad/v2.go index 6aba55fc6..1ecbf273a 100644 --- a/politeiad/v2.go +++ b/politeiad/v2.go @@ -602,7 +602,7 @@ func (p *politeia) handlePluginReads(w http.ResponseWriter, r *http.Request) { // Internal server error. Log it and return a 500. t := time.Now().Unix() e := fmt.Sprintf("PluginRead %v %v %v: %v", - v.cmd.ID, v.cmd.Command, v.cmd.Payload, err) + v.cmd.ID, v.cmd.Command, v.cmd.Payload, v.err) log.Errorf("%v %v %v %v Internal error %v: %v", util.RemoteAddr(r), r.Method, r.URL, r.Proto, t, e) log.Errorf("Stacktrace (NOT A REAL CRASH): %s", debug.Stack())