1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
|
// Copyright 2020 The Matrix.org Foundation C.I.C.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package sqlutil
import (
"context"
"database/sql/driver"
"fmt"
"io"
"os"
"runtime"
"strconv"
"strings"
"sync"
"time"
"github.com/ngrok/sqlmw"
"github.com/sirupsen/logrus"
)
var tracingEnabled = os.Getenv("DENDRITE_TRACE_SQL") == "1"
var goidToWriter sync.Map
type traceInterceptor struct {
sqlmw.NullInterceptor
}
func (in *traceInterceptor) StmtQueryContext(ctx context.Context, stmt driver.StmtQueryContext, query string, args []driver.NamedValue) (driver.Rows, error) {
startedAt := time.Now()
rows, err := stmt.QueryContext(ctx, args)
trackGoID(query)
logrus.WithField("duration", time.Since(startedAt)).WithField(logrus.ErrorKey, err).Debug("executed sql query ", query, " args: ", args)
return rows, err
}
func (in *traceInterceptor) StmtExecContext(ctx context.Context, stmt driver.StmtExecContext, query string, args []driver.NamedValue) (driver.Result, error) {
startedAt := time.Now()
result, err := stmt.ExecContext(ctx, args)
trackGoID(query)
logrus.WithField("duration", time.Since(startedAt)).WithField(logrus.ErrorKey, err).Debug("executed sql query ", query, " args: ", args)
return result, err
}
func (in *traceInterceptor) RowsNext(c context.Context, rows driver.Rows, dest []driver.Value) error {
err := rows.Next(dest)
if err == io.EOF {
// For all cases, we call Next() n+1 times, the first to populate the initial dest, then eventually
// it will io.EOF. If we log on each Next() call we log the last element twice, so don't.
return err
}
cols := rows.Columns()
logrus.Debug(strings.Join(cols, " | "))
b := strings.Builder{}
for i, val := range dest {
b.WriteString(fmt.Sprintf("%q", val))
if i+1 <= len(dest)-1 {
b.WriteString(" | ")
}
}
logrus.Debug(b.String())
return err
}
func trackGoID(query string) {
thisGoID := goid()
if _, ok := goidToWriter.Load(thisGoID); ok {
return // we're on a writer goroutine
}
q := strings.TrimSpace(query)
if strings.HasPrefix(q, "SELECT") {
return // SELECTs can go on other goroutines
}
logrus.Warnf("unsafe goid %d: SQL executed not on an ExclusiveWriter: %s", thisGoID, q)
}
func init() {
registerDrivers()
}
func goid() int {
var buf [64]byte
n := runtime.Stack(buf[:], false)
idField := strings.Fields(strings.TrimPrefix(string(buf[:n]), "goroutine "))[0]
id, err := strconv.Atoi(idField)
if err != nil {
panic(fmt.Sprintf("cannot get goroutine id: %v", err))
}
return id
}
|
