vitess.io/vitess@v0.16.2/go/vt/vtgate/logstats/logstats.go (about) 1 /* 2 Copyright 2019 The Vitess Authors. 3 4 Licensed under the Apache License, Version 2.0 (the "License"); 5 you may not use this file except in compliance with the License. 6 You may obtain a copy of the License at 7 8 http://www.apache.org/licenses/LICENSE-2.0 9 10 Unless required by applicable law or agreed to in writing, software 11 distributed under the License is distributed on an "AS IS" BASIS, 12 WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 See the License for the specific language governing permissions and 14 limitations under the License. 15 */ 16 17 package logstats 18 19 import ( 20 "context" 21 "encoding/json" 22 "fmt" 23 "html/template" 24 "io" 25 "net/url" 26 "time" 27 28 "vitess.io/vitess/go/sqltypes" 29 "vitess.io/vitess/go/streamlog" 30 "vitess.io/vitess/go/tb" 31 "vitess.io/vitess/go/vt/callerid" 32 "vitess.io/vitess/go/vt/callinfo" 33 "vitess.io/vitess/go/vt/log" 34 35 querypb "vitess.io/vitess/go/vt/proto/query" 36 ) 37 38 // LogStats records the stats for a single vtgate query 39 type LogStats struct { 40 Ctx context.Context 41 Method string 42 TabletType string 43 StmtType string 44 SQL string 45 BindVariables map[string]*querypb.BindVariable 46 StartTime time.Time 47 EndTime time.Time 48 ShardQueries uint64 49 RowsAffected uint64 50 RowsReturned uint64 51 PlanTime time.Duration 52 ExecuteTime time.Duration 53 CommitTime time.Duration 54 Error error 55 TablesUsed []string 56 SessionUUID string 57 CachedPlan bool 58 ActiveKeyspace string // ActiveKeyspace is the selected keyspace `use ks` 59 } 60 61 // NewLogStats constructs a new LogStats with supplied Method and ctx 62 // field values, and the StartTime field set to the present time. 63 func NewLogStats(ctx context.Context, methodName, sql, sessionUUID string, bindVars map[string]*querypb.BindVariable) *LogStats { 64 return &LogStats{ 65 Ctx: ctx, 66 Method: methodName, 67 SQL: sql, 68 SessionUUID: sessionUUID, 69 BindVariables: bindVars, 70 StartTime: time.Now(), 71 } 72 } 73 74 // SaveEndTime sets the end time of this request to now 75 func (stats *LogStats) SaveEndTime() { 76 stats.EndTime = time.Now() 77 } 78 79 // ImmediateCaller returns the immediate caller stored in LogStats.Ctx 80 func (stats *LogStats) ImmediateCaller() string { 81 return callerid.GetUsername(callerid.ImmediateCallerIDFromContext(stats.Ctx)) 82 } 83 84 // EffectiveCaller returns the effective caller stored in LogStats.Ctx 85 func (stats *LogStats) EffectiveCaller() string { 86 return callerid.GetPrincipal(callerid.EffectiveCallerIDFromContext(stats.Ctx)) 87 } 88 89 // EventTime returns the time the event was created. 90 func (stats *LogStats) EventTime() time.Time { 91 return stats.EndTime 92 } 93 94 // TotalTime returns how long this query has been running 95 func (stats *LogStats) TotalTime() time.Duration { 96 return stats.EndTime.Sub(stats.StartTime) 97 } 98 99 // ContextHTML returns the HTML version of the context that was used, or "". 100 // This is a method on LogStats instead of a field so that it doesn't need 101 // to be passed by value everywhere. 102 func (stats *LogStats) ContextHTML() template.HTML { 103 return callinfo.HTMLFromContext(stats.Ctx) 104 } 105 106 // ErrorStr returns the error string or "" 107 func (stats *LogStats) ErrorStr() string { 108 if stats.Error != nil { 109 return stats.Error.Error() 110 } 111 return "" 112 } 113 114 // RemoteAddrUsername returns some parts of CallInfo if set 115 func (stats *LogStats) RemoteAddrUsername() (string, string) { 116 ci, ok := callinfo.FromContext(stats.Ctx) 117 if !ok { 118 return "", "" 119 } 120 return ci.RemoteAddr(), ci.Username() 121 } 122 123 // Logf formats the log record to the given writer, either as 124 // tab-separated list of logged fields or as JSON. 125 func (stats *LogStats) Logf(w io.Writer, params url.Values) error { 126 if !streamlog.ShouldEmitLog(stats.SQL, stats.RowsAffected, stats.RowsReturned) { 127 return nil 128 } 129 130 // FormatBindVariables call might panic so we're going to catch it here 131 // and print out the stack trace for debugging. 132 defer func() { 133 if x := recover(); x != nil { 134 log.Errorf("Uncaught panic:\n%v\n%s", x, tb.Stack(4)) 135 } 136 }() 137 138 formattedBindVars := "\"[REDACTED]\"" 139 if !streamlog.GetRedactDebugUIQueries() { 140 _, fullBindParams := params["full"] 141 formattedBindVars = sqltypes.FormatBindVariables( 142 stats.BindVariables, 143 fullBindParams, 144 streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON, 145 ) 146 } 147 148 // TODO: remove username here we fully enforce immediate caller id 149 remoteAddr, username := stats.RemoteAddrUsername() 150 151 var fmtString string 152 switch streamlog.GetQueryLogFormat() { 153 case streamlog.QueryLogFormatText: 154 fmtString = "%v\t%v\t%v\t'%v'\t'%v'\t%v\t%v\t%.6f\t%.6f\t%.6f\t%.6f\t%v\t%q\t%v\t%v\t%v\t%q\t%q\t%q\t%v\t%v\t%q\n" 155 case streamlog.QueryLogFormatJSON: 156 fmtString = "{\"Method\": %q, \"RemoteAddr\": %q, \"Username\": %q, \"ImmediateCaller\": %q, \"Effective Caller\": %q, \"Start\": \"%v\", \"End\": \"%v\", \"TotalTime\": %.6f, \"PlanTime\": %v, \"ExecuteTime\": %v, \"CommitTime\": %v, \"StmtType\": %q, \"SQL\": %q, \"BindVars\": %v, \"ShardQueries\": %v, \"RowsAffected\": %v, \"Error\": %q, \"TabletType\": %q, \"SessionUUID\": %q, \"Cached Plan\": %v, \"TablesUsed\": %v, \"ActiveKeyspace\": %q}\n" 157 } 158 159 tables := stats.TablesUsed 160 if tables == nil { 161 tables = []string{} 162 } 163 tablesUsed, marshalErr := json.Marshal(tables) 164 if marshalErr != nil { 165 return marshalErr 166 } 167 _, err := fmt.Fprintf( 168 w, 169 fmtString, 170 stats.Method, 171 remoteAddr, 172 username, 173 stats.ImmediateCaller(), 174 stats.EffectiveCaller(), 175 stats.StartTime.Format("2006-01-02 15:04:05.000000"), 176 stats.EndTime.Format("2006-01-02 15:04:05.000000"), 177 stats.TotalTime().Seconds(), 178 stats.PlanTime.Seconds(), 179 stats.ExecuteTime.Seconds(), 180 stats.CommitTime.Seconds(), 181 stats.StmtType, 182 stats.SQL, 183 formattedBindVars, 184 stats.ShardQueries, 185 stats.RowsAffected, 186 stats.ErrorStr(), 187 stats.TabletType, 188 stats.SessionUUID, 189 stats.CachedPlan, 190 string(tablesUsed), 191 stats.ActiveKeyspace, 192 ) 193 194 return err 195 }