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  }