trace.go

Documentation: github.com/jackc/pgx/v5/pgproto3

     1  package pgproto3
     2  
     3  import (
     4  	"bytes"
     5  	"fmt"
     6  	"io"
     7  	"strconv"
     8  	"strings"
     9  	"sync"
    10  	"time"
    11  )
    12  
    13  // tracer traces the messages send to and from a Backend or Frontend. The format it produces roughly mimics the
    14  // format produced by the libpq C function PQtrace.
    15  type tracer struct {
    16  	TracerOptions
    17  
    18  	mux sync.Mutex
    19  	w   io.Writer
    20  	buf *bytes.Buffer
    21  }
    22  
    23  // TracerOptions controls tracing behavior. It is roughly equivalent to the libpq function PQsetTraceFlags.
    24  type TracerOptions struct {
    25  	// SuppressTimestamps prevents printing of timestamps.
    26  	SuppressTimestamps bool
    27  
    28  	// RegressMode redacts fields that may be vary between executions.
    29  	RegressMode bool
    30  }
    31  
    32  func (t *tracer) traceMessage(sender byte, encodedLen int32, msg Message) {
    33  	switch msg := msg.(type) {
    34  	case *AuthenticationCleartextPassword:
    35  		t.traceAuthenticationCleartextPassword(sender, encodedLen, msg)
    36  	case *AuthenticationGSS:
    37  		t.traceAuthenticationGSS(sender, encodedLen, msg)
    38  	case *AuthenticationGSSContinue:
    39  		t.traceAuthenticationGSSContinue(sender, encodedLen, msg)
    40  	case *AuthenticationMD5Password:
    41  		t.traceAuthenticationMD5Password(sender, encodedLen, msg)
    42  	case *AuthenticationOk:
    43  		t.traceAuthenticationOk(sender, encodedLen, msg)
    44  	case *AuthenticationSASL:
    45  		t.traceAuthenticationSASL(sender, encodedLen, msg)
    46  	case *AuthenticationSASLContinue:
    47  		t.traceAuthenticationSASLContinue(sender, encodedLen, msg)
    48  	case *AuthenticationSASLFinal:
    49  		t.traceAuthenticationSASLFinal(sender, encodedLen, msg)
    50  	case *BackendKeyData:
    51  		t.traceBackendKeyData(sender, encodedLen, msg)
    52  	case *Bind:
    53  		t.traceBind(sender, encodedLen, msg)
    54  	case *BindComplete:
    55  		t.traceBindComplete(sender, encodedLen, msg)
    56  	case *CancelRequest:
    57  		t.traceCancelRequest(sender, encodedLen, msg)
    58  	case *Close:
    59  		t.traceClose(sender, encodedLen, msg)
    60  	case *CloseComplete:
    61  		t.traceCloseComplete(sender, encodedLen, msg)
    62  	case *CommandComplete:
    63  		t.traceCommandComplete(sender, encodedLen, msg)
    64  	case *CopyBothResponse:
    65  		t.traceCopyBothResponse(sender, encodedLen, msg)
    66  	case *CopyData:
    67  		t.traceCopyData(sender, encodedLen, msg)
    68  	case *CopyDone:
    69  		t.traceCopyDone(sender, encodedLen, msg)
    70  	case *CopyFail:
    71  		t.traceCopyFail(sender, encodedLen, msg)
    72  	case *CopyInResponse:
    73  		t.traceCopyInResponse(sender, encodedLen, msg)
    74  	case *CopyOutResponse:
    75  		t.traceCopyOutResponse(sender, encodedLen, msg)
    76  	case *DataRow:
    77  		t.traceDataRow(sender, encodedLen, msg)
    78  	case *Describe:
    79  		t.traceDescribe(sender, encodedLen, msg)
    80  	case *EmptyQueryResponse:
    81  		t.traceEmptyQueryResponse(sender, encodedLen, msg)
    82  	case *ErrorResponse:
    83  		t.traceErrorResponse(sender, encodedLen, msg)
    84  	case *Execute:
    85  		t.TraceQueryute(sender, encodedLen, msg)
    86  	case *Flush:
    87  		t.traceFlush(sender, encodedLen, msg)
    88  	case *FunctionCall:
    89  		t.traceFunctionCall(sender, encodedLen, msg)
    90  	case *FunctionCallResponse:
    91  		t.traceFunctionCallResponse(sender, encodedLen, msg)
    92  	case *GSSEncRequest:
    93  		t.traceGSSEncRequest(sender, encodedLen, msg)
    94  	case *NoData:
    95  		t.traceNoData(sender, encodedLen, msg)
    96  	case *NoticeResponse:
    97  		t.traceNoticeResponse(sender, encodedLen, msg)
    98  	case *NotificationResponse:
    99  		t.traceNotificationResponse(sender, encodedLen, msg)
   100  	case *ParameterDescription:
   101  		t.traceParameterDescription(sender, encodedLen, msg)
   102  	case *ParameterStatus:
   103  		t.traceParameterStatus(sender, encodedLen, msg)
   104  	case *Parse:
   105  		t.traceParse(sender, encodedLen, msg)
   106  	case *ParseComplete:
   107  		t.traceParseComplete(sender, encodedLen, msg)
   108  	case *PortalSuspended:
   109  		t.tracePortalSuspended(sender, encodedLen, msg)
   110  	case *Query:
   111  		t.traceQuery(sender, encodedLen, msg)
   112  	case *ReadyForQuery:
   113  		t.traceReadyForQuery(sender, encodedLen, msg)
   114  	case *RowDescription:
   115  		t.traceRowDescription(sender, encodedLen, msg)
   116  	case *SSLRequest:
   117  		t.traceSSLRequest(sender, encodedLen, msg)
   118  	case *StartupMessage:
   119  		t.traceStartupMessage(sender, encodedLen, msg)
   120  	case *Sync:
   121  		t.traceSync(sender, encodedLen, msg)
   122  	case *Terminate:
   123  		t.traceTerminate(sender, encodedLen, msg)
   124  	default:
   125  		t.writeTrace(sender, encodedLen, "Unknown", nil)
   126  	}
   127  }
   128  
   129  func (t *tracer) traceAuthenticationCleartextPassword(sender byte, encodedLen int32, msg *AuthenticationCleartextPassword) {
   130  	t.writeTrace(sender, encodedLen, "AuthenticationCleartextPassword", nil)
   131  }
   132  
   133  func (t *tracer) traceAuthenticationGSS(sender byte, encodedLen int32, msg *AuthenticationGSS) {
   134  	t.writeTrace(sender, encodedLen, "AuthenticationGSS", nil)
   135  }
   136  
   137  func (t *tracer) traceAuthenticationGSSContinue(sender byte, encodedLen int32, msg *AuthenticationGSSContinue) {
   138  	t.writeTrace(sender, encodedLen, "AuthenticationGSSContinue", nil)
   139  }
   140  
   141  func (t *tracer) traceAuthenticationMD5Password(sender byte, encodedLen int32, msg *AuthenticationMD5Password) {
   142  	t.writeTrace(sender, encodedLen, "AuthenticationMD5Password", nil)
   143  }
   144  
   145  func (t *tracer) traceAuthenticationOk(sender byte, encodedLen int32, msg *AuthenticationOk) {
   146  	t.writeTrace(sender, encodedLen, "AuthenticationOk", nil)
   147  }
   148  
   149  func (t *tracer) traceAuthenticationSASL(sender byte, encodedLen int32, msg *AuthenticationSASL) {
   150  	t.writeTrace(sender, encodedLen, "AuthenticationSASL", nil)
   151  }
   152  
   153  func (t *tracer) traceAuthenticationSASLContinue(sender byte, encodedLen int32, msg *AuthenticationSASLContinue) {
   154  	t.writeTrace(sender, encodedLen, "AuthenticationSASLContinue", nil)
   155  }
   156  
   157  func (t *tracer) traceAuthenticationSASLFinal(sender byte, encodedLen int32, msg *AuthenticationSASLFinal) {
   158  	t.writeTrace(sender, encodedLen, "AuthenticationSASLFinal", nil)
   159  }
   160  
   161  func (t *tracer) traceBackendKeyData(sender byte, encodedLen int32, msg *BackendKeyData) {
   162  	t.writeTrace(sender, encodedLen, "BackendKeyData", func() {
   163  		if t.RegressMode {
   164  			t.buf.WriteString("\t NNNN NNNN")
   165  		} else {
   166  			fmt.Fprintf(t.buf, "\t %d %d", msg.ProcessID, msg.SecretKey)
   167  		}
   168  	})
   169  }
   170  
   171  func (t *tracer) traceBind(sender byte, encodedLen int32, msg *Bind) {
   172  	t.writeTrace(sender, encodedLen, "Bind", func() {
   173  		fmt.Fprintf(t.buf, "\t %s %s %d", traceDoubleQuotedString([]byte(msg.DestinationPortal)), traceDoubleQuotedString([]byte(msg.PreparedStatement)), len(msg.ParameterFormatCodes))
   174  		for _, fc := range msg.ParameterFormatCodes {
   175  			fmt.Fprintf(t.buf, " %d", fc)
   176  		}
   177  		fmt.Fprintf(t.buf, " %d", len(msg.Parameters))
   178  		for _, p := range msg.Parameters {
   179  			fmt.Fprintf(t.buf, " %s", traceSingleQuotedString(p))
   180  		}
   181  		fmt.Fprintf(t.buf, " %d", len(msg.ResultFormatCodes))
   182  		for _, fc := range msg.ResultFormatCodes {
   183  			fmt.Fprintf(t.buf, " %d", fc)
   184  		}
   185  	})
   186  }
   187  
   188  func (t *tracer) traceBindComplete(sender byte, encodedLen int32, msg *BindComplete) {
   189  	t.writeTrace(sender, encodedLen, "BindComplete", nil)
   190  }
   191  
   192  func (t *tracer) traceCancelRequest(sender byte, encodedLen int32, msg *CancelRequest) {
   193  	t.writeTrace(sender, encodedLen, "CancelRequest", nil)
   194  }
   195  
   196  func (t *tracer) traceClose(sender byte, encodedLen int32, msg *Close) {
   197  	t.writeTrace(sender, encodedLen, "Close", nil)
   198  }
   199  
   200  func (t *tracer) traceCloseComplete(sender byte, encodedLen int32, msg *CloseComplete) {
   201  	t.writeTrace(sender, encodedLen, "CloseComplete", nil)
   202  }
   203  
   204  func (t *tracer) traceCommandComplete(sender byte, encodedLen int32, msg *CommandComplete) {
   205  	t.writeTrace(sender, encodedLen, "CommandComplete", func() {
   206  		fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString(msg.CommandTag))
   207  	})
   208  }
   209  
   210  func (t *tracer) traceCopyBothResponse(sender byte, encodedLen int32, msg *CopyBothResponse) {
   211  	t.writeTrace(sender, encodedLen, "CopyBothResponse", nil)
   212  }
   213  
   214  func (t *tracer) traceCopyData(sender byte, encodedLen int32, msg *CopyData) {
   215  	t.writeTrace(sender, encodedLen, "CopyData", nil)
   216  }
   217  
   218  func (t *tracer) traceCopyDone(sender byte, encodedLen int32, msg *CopyDone) {
   219  	t.writeTrace(sender, encodedLen, "CopyDone", nil)
   220  }
   221  
   222  func (t *tracer) traceCopyFail(sender byte, encodedLen int32, msg *CopyFail) {
   223  	t.writeTrace(sender, encodedLen, "CopyFail", func() {
   224  		fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString([]byte(msg.Message)))
   225  	})
   226  }
   227  
   228  func (t *tracer) traceCopyInResponse(sender byte, encodedLen int32, msg *CopyInResponse) {
   229  	t.writeTrace(sender, encodedLen, "CopyInResponse", nil)
   230  }
   231  
   232  func (t *tracer) traceCopyOutResponse(sender byte, encodedLen int32, msg *CopyOutResponse) {
   233  	t.writeTrace(sender, encodedLen, "CopyOutResponse", nil)
   234  }
   235  
   236  func (t *tracer) traceDataRow(sender byte, encodedLen int32, msg *DataRow) {
   237  	t.writeTrace(sender, encodedLen, "DataRow", func() {
   238  		fmt.Fprintf(t.buf, "\t %d", len(msg.Values))
   239  		for _, v := range msg.Values {
   240  			if v == nil {
   241  				t.buf.WriteString(" -1")
   242  			} else {
   243  				fmt.Fprintf(t.buf, " %d %s", len(v), traceSingleQuotedString(v))
   244  			}
   245  		}
   246  	})
   247  }
   248  
   249  func (t *tracer) traceDescribe(sender byte, encodedLen int32, msg *Describe) {
   250  	t.writeTrace(sender, encodedLen, "Describe", func() {
   251  		fmt.Fprintf(t.buf, "\t %c %s", msg.ObjectType, traceDoubleQuotedString([]byte(msg.Name)))
   252  	})
   253  }
   254  
   255  func (t *tracer) traceEmptyQueryResponse(sender byte, encodedLen int32, msg *EmptyQueryResponse) {
   256  	t.writeTrace(sender, encodedLen, "EmptyQueryResponse", nil)
   257  }
   258  
   259  func (t *tracer) traceErrorResponse(sender byte, encodedLen int32, msg *ErrorResponse) {
   260  	t.writeTrace(sender, encodedLen, "ErrorResponse", nil)
   261  }
   262  
   263  func (t *tracer) TraceQueryute(sender byte, encodedLen int32, msg *Execute) {
   264  	t.writeTrace(sender, encodedLen, "Execute", func() {
   265  		fmt.Fprintf(t.buf, "\t %s %d", traceDoubleQuotedString([]byte(msg.Portal)), msg.MaxRows)
   266  	})
   267  }
   268  
   269  func (t *tracer) traceFlush(sender byte, encodedLen int32, msg *Flush) {
   270  	t.writeTrace(sender, encodedLen, "Flush", nil)
   271  }
   272  
   273  func (t *tracer) traceFunctionCall(sender byte, encodedLen int32, msg *FunctionCall) {
   274  	t.writeTrace(sender, encodedLen, "FunctionCall", nil)
   275  }
   276  
   277  func (t *tracer) traceFunctionCallResponse(sender byte, encodedLen int32, msg *FunctionCallResponse) {
   278  	t.writeTrace(sender, encodedLen, "FunctionCallResponse", nil)
   279  }
   280  
   281  func (t *tracer) traceGSSEncRequest(sender byte, encodedLen int32, msg *GSSEncRequest) {
   282  	t.writeTrace(sender, encodedLen, "GSSEncRequest", nil)
   283  }
   284  
   285  func (t *tracer) traceNoData(sender byte, encodedLen int32, msg *NoData) {
   286  	t.writeTrace(sender, encodedLen, "NoData", nil)
   287  }
   288  
   289  func (t *tracer) traceNoticeResponse(sender byte, encodedLen int32, msg *NoticeResponse) {
   290  	t.writeTrace(sender, encodedLen, "NoticeResponse", nil)
   291  }
   292  
   293  func (t *tracer) traceNotificationResponse(sender byte, encodedLen int32, msg *NotificationResponse) {
   294  	t.writeTrace(sender, encodedLen, "NotificationResponse", func() {
   295  		fmt.Fprintf(t.buf, "\t %d %s %s", msg.PID, traceDoubleQuotedString([]byte(msg.Channel)), traceDoubleQuotedString([]byte(msg.Payload)))
   296  	})
   297  }
   298  
   299  func (t *tracer) traceParameterDescription(sender byte, encodedLen int32, msg *ParameterDescription) {
   300  	t.writeTrace(sender, encodedLen, "ParameterDescription", nil)
   301  }
   302  
   303  func (t *tracer) traceParameterStatus(sender byte, encodedLen int32, msg *ParameterStatus) {
   304  	t.writeTrace(sender, encodedLen, "ParameterStatus", func() {
   305  		fmt.Fprintf(t.buf, "\t %s %s", traceDoubleQuotedString([]byte(msg.Name)), traceDoubleQuotedString([]byte(msg.Value)))
   306  	})
   307  }
   308  
   309  func (t *tracer) traceParse(sender byte, encodedLen int32, msg *Parse) {
   310  	t.writeTrace(sender, encodedLen, "Parse", func() {
   311  		fmt.Fprintf(t.buf, "\t %s %s %d", traceDoubleQuotedString([]byte(msg.Name)), traceDoubleQuotedString([]byte(msg.Query)), len(msg.ParameterOIDs))
   312  		for _, oid := range msg.ParameterOIDs {
   313  			fmt.Fprintf(t.buf, " %d", oid)
   314  		}
   315  	})
   316  }
   317  
   318  func (t *tracer) traceParseComplete(sender byte, encodedLen int32, msg *ParseComplete) {
   319  	t.writeTrace(sender, encodedLen, "ParseComplete", nil)
   320  }
   321  
   322  func (t *tracer) tracePortalSuspended(sender byte, encodedLen int32, msg *PortalSuspended) {
   323  	t.writeTrace(sender, encodedLen, "PortalSuspended", nil)
   324  }
   325  
   326  func (t *tracer) traceQuery(sender byte, encodedLen int32, msg *Query) {
   327  	t.writeTrace(sender, encodedLen, "Query", func() {
   328  		fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString([]byte(msg.String)))
   329  	})
   330  }
   331  
   332  func (t *tracer) traceReadyForQuery(sender byte, encodedLen int32, msg *ReadyForQuery) {
   333  	t.writeTrace(sender, encodedLen, "ReadyForQuery", func() {
   334  		fmt.Fprintf(t.buf, "\t %c", msg.TxStatus)
   335  	})
   336  }
   337  
   338  func (t *tracer) traceRowDescription(sender byte, encodedLen int32, msg *RowDescription) {
   339  	t.writeTrace(sender, encodedLen, "RowDescription", func() {
   340  		fmt.Fprintf(t.buf, "\t %d", len(msg.Fields))
   341  		for _, fd := range msg.Fields {
   342  			fmt.Fprintf(t.buf, ` %s %d %d %d %d %d %d`, traceDoubleQuotedString(fd.Name), fd.TableOID, fd.TableAttributeNumber, fd.DataTypeOID, fd.DataTypeSize, fd.TypeModifier, fd.Format)
   343  		}
   344  	})
   345  }
   346  
   347  func (t *tracer) traceSSLRequest(sender byte, encodedLen int32, msg *SSLRequest) {
   348  	t.writeTrace(sender, encodedLen, "SSLRequest", nil)
   349  }
   350  
   351  func (t *tracer) traceStartupMessage(sender byte, encodedLen int32, msg *StartupMessage) {
   352  	t.writeTrace(sender, encodedLen, "StartupMessage", nil)
   353  }
   354  
   355  func (t *tracer) traceSync(sender byte, encodedLen int32, msg *Sync) {
   356  	t.writeTrace(sender, encodedLen, "Sync", nil)
   357  }
   358  
   359  func (t *tracer) traceTerminate(sender byte, encodedLen int32, msg *Terminate) {
   360  	t.writeTrace(sender, encodedLen, "Terminate", nil)
   361  }
   362  
   363  func (t *tracer) writeTrace(sender byte, encodedLen int32, msgType string, writeDetails func()) {
   364  	t.mux.Lock()
   365  	defer t.mux.Unlock()
   366  	defer func() {
   367  		if t.buf.Cap() > 1024 {
   368  			t.buf = &bytes.Buffer{}
   369  		} else {
   370  			t.buf.Reset()
   371  		}
   372  	}()
   373  
   374  	if !t.SuppressTimestamps {
   375  		now := time.Now()
   376  		t.buf.WriteString(now.Format("2006-01-02 15:04:05.000000"))
   377  		t.buf.WriteByte('\t')
   378  	}
   379  
   380  	t.buf.WriteByte(sender)
   381  	t.buf.WriteByte('\t')
   382  	t.buf.WriteString(msgType)
   383  	t.buf.WriteByte('\t')
   384  	t.buf.WriteString(strconv.FormatInt(int64(encodedLen), 10))
   385  
   386  	if writeDetails != nil {
   387  		writeDetails()
   388  	}
   389  
   390  	t.buf.WriteByte('\n')
   391  	t.buf.WriteTo(t.w)
   392  }
   393  
   394  // traceDoubleQuotedString returns t.buf as a double-quoted string without any escaping. It is roughly equivalent to
   395  // pqTraceOutputString in libpq.
   396  func traceDoubleQuotedString(buf []byte) string {
   397  	return `"` + string(buf) + `"`
   398  }
   399  
   400  // traceSingleQuotedString returns buf as a single-quoted string with non-printable characters hex-escaped. It is
   401  // roughly equivalent to pqTraceOutputNchar in libpq.
   402  func traceSingleQuotedString(buf []byte) string {
   403  	sb := &strings.Builder{}
   404  
   405  	sb.WriteByte('\'')
   406  	for _, b := range buf {
   407  		if b < 32 || b > 126 {
   408  			fmt.Fprintf(sb, `\x%x`, b)
   409  		} else {
   410  			sb.WriteByte(b)
   411  		}
   412  	}
   413  	sb.WriteByte('\'')
   414  
   415  	return sb.String()
   416  }
   417
View as plain text