diff --git a/pgproto3/trace.go b/pgproto3/trace.go index c09f68d1..6cc7d3e3 100644 --- a/pgproto3/trace.go +++ b/pgproto3/trace.go @@ -6,15 +6,18 @@ import ( "io" "strconv" "strings" + "sync" "time" ) // tracer traces the messages send to and from a Backend or Frontend. The format it produces roughly mimics the // format produced by the libpq C function PQtrace. type tracer struct { + TracerOptions + + mux sync.Mutex w io.Writer buf *bytes.Buffer - TracerOptions } // TracerOptions controls tracing behavior. It is roughly equivalent to the libpq function PQsetTraceFlags. @@ -119,278 +122,255 @@ func (t *tracer) traceMessage(sender byte, encodedLen int32, msg Message) { case *Terminate: t.traceTerminate(sender, encodedLen, msg) default: - t.beginTrace(sender, encodedLen, "Unknown") - t.finishTrace() + t.writeTrace(sender, encodedLen, "Unknown", nil) } } func (t *tracer) traceAuthenticationCleartextPassword(sender byte, encodedLen int32, msg *AuthenticationCleartextPassword) { - t.beginTrace(sender, encodedLen, "AuthenticationCleartextPassword") - t.finishTrace() + t.writeTrace(sender, encodedLen, "AuthenticationCleartextPassword", nil) } func (t *tracer) traceAuthenticationGSS(sender byte, encodedLen int32, msg *AuthenticationGSS) { - t.beginTrace(sender, encodedLen, "AuthenticationGSS") - t.finishTrace() + t.writeTrace(sender, encodedLen, "AuthenticationGSS", nil) } func (t *tracer) traceAuthenticationGSSContinue(sender byte, encodedLen int32, msg *AuthenticationGSSContinue) { - t.beginTrace(sender, encodedLen, "AuthenticationGSSContinue") - t.finishTrace() + t.writeTrace(sender, encodedLen, "AuthenticationGSSContinue", nil) } func (t *tracer) traceAuthenticationMD5Password(sender byte, encodedLen int32, msg *AuthenticationMD5Password) { - t.beginTrace(sender, encodedLen, "AuthenticationMD5Password") - t.finishTrace() + t.writeTrace(sender, encodedLen, "AuthenticationMD5Password", nil) } func (t *tracer) traceAuthenticationOk(sender byte, encodedLen int32, msg *AuthenticationOk) { - t.beginTrace(sender, encodedLen, "AuthenticationOk") - t.finishTrace() + t.writeTrace(sender, encodedLen, "AuthenticationOk", nil) } func (t *tracer) traceAuthenticationSASL(sender byte, encodedLen int32, msg *AuthenticationSASL) { - t.beginTrace(sender, encodedLen, "AuthenticationSASL") - t.finishTrace() + t.writeTrace(sender, encodedLen, "AuthenticationSASL", nil) } func (t *tracer) traceAuthenticationSASLContinue(sender byte, encodedLen int32, msg *AuthenticationSASLContinue) { - t.beginTrace(sender, encodedLen, "AuthenticationSASLContinue") - t.finishTrace() + t.writeTrace(sender, encodedLen, "AuthenticationSASLContinue", nil) } func (t *tracer) traceAuthenticationSASLFinal(sender byte, encodedLen int32, msg *AuthenticationSASLFinal) { - t.beginTrace(sender, encodedLen, "AuthenticationSASLFinal") - t.finishTrace() + t.writeTrace(sender, encodedLen, "AuthenticationSASLFinal", nil) } func (t *tracer) traceBackendKeyData(sender byte, encodedLen int32, msg *BackendKeyData) { - t.beginTrace(sender, encodedLen, "BackendKeyData") - if t.RegressMode { - t.buf.WriteString("\t NNNN NNNN") - } else { - fmt.Fprintf(t.buf, "\t %d %d", msg.ProcessID, msg.SecretKey) - } - t.finishTrace() + t.writeTrace(sender, encodedLen, "BackendKeyData", func() { + if t.RegressMode { + t.buf.WriteString("\t NNNN NNNN") + } else { + fmt.Fprintf(t.buf, "\t %d %d", msg.ProcessID, msg.SecretKey) + } + }) } func (t *tracer) traceBind(sender byte, encodedLen int32, msg *Bind) { - t.beginTrace(sender, encodedLen, "Bind") - fmt.Fprintf(t.buf, "\t %s %s %d", traceDoubleQuotedString([]byte(msg.DestinationPortal)), traceDoubleQuotedString([]byte(msg.PreparedStatement)), len(msg.ParameterFormatCodes)) - for _, fc := range msg.ParameterFormatCodes { - fmt.Fprintf(t.buf, " %d", fc) - } - fmt.Fprintf(t.buf, " %d", len(msg.Parameters)) - for _, p := range msg.Parameters { - fmt.Fprintf(t.buf, " %s", traceSingleQuotedString(p)) - } - fmt.Fprintf(t.buf, " %d", len(msg.ResultFormatCodes)) - for _, fc := range msg.ResultFormatCodes { - fmt.Fprintf(t.buf, " %d", fc) - } - t.finishTrace() + t.writeTrace(sender, encodedLen, "Bind", func() { + fmt.Fprintf(t.buf, "\t %s %s %d", traceDoubleQuotedString([]byte(msg.DestinationPortal)), traceDoubleQuotedString([]byte(msg.PreparedStatement)), len(msg.ParameterFormatCodes)) + for _, fc := range msg.ParameterFormatCodes { + fmt.Fprintf(t.buf, " %d", fc) + } + fmt.Fprintf(t.buf, " %d", len(msg.Parameters)) + for _, p := range msg.Parameters { + fmt.Fprintf(t.buf, " %s", traceSingleQuotedString(p)) + } + fmt.Fprintf(t.buf, " %d", len(msg.ResultFormatCodes)) + for _, fc := range msg.ResultFormatCodes { + fmt.Fprintf(t.buf, " %d", fc) + } + }) } func (t *tracer) traceBindComplete(sender byte, encodedLen int32, msg *BindComplete) { - t.beginTrace(sender, encodedLen, "BindComplete") - t.finishTrace() + t.writeTrace(sender, encodedLen, "BindComplete", nil) } func (t *tracer) traceCancelRequest(sender byte, encodedLen int32, msg *CancelRequest) { - t.beginTrace(sender, encodedLen, "CancelRequest") - t.finishTrace() + t.writeTrace(sender, encodedLen, "CancelRequest", nil) } func (t *tracer) traceClose(sender byte, encodedLen int32, msg *Close) { - t.beginTrace(sender, encodedLen, "Close") - t.finishTrace() + t.writeTrace(sender, encodedLen, "Close", nil) } func (t *tracer) traceCloseComplete(sender byte, encodedLen int32, msg *CloseComplete) { - t.beginTrace(sender, encodedLen, "CloseComplete") - t.finishTrace() + t.writeTrace(sender, encodedLen, "CloseComplete", nil) } func (t *tracer) traceCommandComplete(sender byte, encodedLen int32, msg *CommandComplete) { - t.beginTrace(sender, encodedLen, "CommandComplete") - fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString(msg.CommandTag)) - t.finishTrace() + t.writeTrace(sender, encodedLen, "CommandComplete", func() { + fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString(msg.CommandTag)) + }) } func (t *tracer) traceCopyBothResponse(sender byte, encodedLen int32, msg *CopyBothResponse) { - t.beginTrace(sender, encodedLen, "CopyBothResponse") - t.finishTrace() + t.writeTrace(sender, encodedLen, "CopyBothResponse", nil) } func (t *tracer) traceCopyData(sender byte, encodedLen int32, msg *CopyData) { - t.beginTrace(sender, encodedLen, "CopyData") - t.finishTrace() + t.writeTrace(sender, encodedLen, "CopyData", nil) } func (t *tracer) traceCopyDone(sender byte, encodedLen int32, msg *CopyDone) { - t.beginTrace(sender, encodedLen, "CopyDone") - t.finishTrace() + t.writeTrace(sender, encodedLen, "CopyDone", nil) } func (t *tracer) traceCopyFail(sender byte, encodedLen int32, msg *CopyFail) { - t.beginTrace(sender, encodedLen, "CopyFail") - fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString([]byte(msg.Message))) - t.finishTrace() + t.writeTrace(sender, encodedLen, "CopyFail", func() { + fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString([]byte(msg.Message))) + }) } func (t *tracer) traceCopyInResponse(sender byte, encodedLen int32, msg *CopyInResponse) { - t.beginTrace(sender, encodedLen, "CopyInResponse") - t.finishTrace() + t.writeTrace(sender, encodedLen, "CopyInResponse", nil) } func (t *tracer) traceCopyOutResponse(sender byte, encodedLen int32, msg *CopyOutResponse) { - t.beginTrace(sender, encodedLen, "CopyOutResponse") - t.finishTrace() + t.writeTrace(sender, encodedLen, "CopyOutResponse", nil) } func (t *tracer) traceDataRow(sender byte, encodedLen int32, msg *DataRow) { - t.beginTrace(sender, encodedLen, "DataRow") - fmt.Fprintf(t.buf, "\t %d", len(msg.Values)) - for _, v := range msg.Values { - if v == nil { - t.buf.WriteString(" -1") - } else { - fmt.Fprintf(t.buf, " %d %s", len(v), traceSingleQuotedString(v)) + t.writeTrace(sender, encodedLen, "DataRow", func() { + fmt.Fprintf(t.buf, "\t %d", len(msg.Values)) + for _, v := range msg.Values { + if v == nil { + t.buf.WriteString(" -1") + } else { + fmt.Fprintf(t.buf, " %d %s", len(v), traceSingleQuotedString(v)) + } } - } - t.finishTrace() + }) } func (t *tracer) traceDescribe(sender byte, encodedLen int32, msg *Describe) { - t.beginTrace(sender, encodedLen, "Describe") - fmt.Fprintf(t.buf, "\t %c %s", msg.ObjectType, traceDoubleQuotedString([]byte(msg.Name))) - t.finishTrace() + t.writeTrace(sender, encodedLen, "Describe", func() { + fmt.Fprintf(t.buf, "\t %c %s", msg.ObjectType, traceDoubleQuotedString([]byte(msg.Name))) + }) } func (t *tracer) traceEmptyQueryResponse(sender byte, encodedLen int32, msg *EmptyQueryResponse) { - t.beginTrace(sender, encodedLen, "EmptyQueryResponse") - t.finishTrace() + t.writeTrace(sender, encodedLen, "EmptyQueryResponse", nil) } func (t *tracer) traceErrorResponse(sender byte, encodedLen int32, msg *ErrorResponse) { - t.beginTrace(sender, encodedLen, "ErrorResponse") - t.finishTrace() + t.writeTrace(sender, encodedLen, "ErrorResponse", nil) } func (t *tracer) TraceQueryute(sender byte, encodedLen int32, msg *Execute) { - t.beginTrace(sender, encodedLen, "Execute") - fmt.Fprintf(t.buf, "\t %s %d", traceDoubleQuotedString([]byte(msg.Portal)), msg.MaxRows) - t.finishTrace() + t.writeTrace(sender, encodedLen, "Execute", func() { + fmt.Fprintf(t.buf, "\t %s %d", traceDoubleQuotedString([]byte(msg.Portal)), msg.MaxRows) + }) } func (t *tracer) traceFlush(sender byte, encodedLen int32, msg *Flush) { - t.beginTrace(sender, encodedLen, "Flush") - t.finishTrace() + t.writeTrace(sender, encodedLen, "Flush", nil) } func (t *tracer) traceFunctionCall(sender byte, encodedLen int32, msg *FunctionCall) { - t.beginTrace(sender, encodedLen, "FunctionCall") - t.finishTrace() + t.writeTrace(sender, encodedLen, "FunctionCall", nil) } func (t *tracer) traceFunctionCallResponse(sender byte, encodedLen int32, msg *FunctionCallResponse) { - t.beginTrace(sender, encodedLen, "FunctionCallResponse") - t.finishTrace() + t.writeTrace(sender, encodedLen, "FunctionCallResponse", nil) } func (t *tracer) traceGSSEncRequest(sender byte, encodedLen int32, msg *GSSEncRequest) { - t.beginTrace(sender, encodedLen, "GSSEncRequest") - t.finishTrace() + t.writeTrace(sender, encodedLen, "GSSEncRequest", nil) } func (t *tracer) traceNoData(sender byte, encodedLen int32, msg *NoData) { - t.beginTrace(sender, encodedLen, "NoData") - t.finishTrace() + t.writeTrace(sender, encodedLen, "NoData", nil) } func (t *tracer) traceNoticeResponse(sender byte, encodedLen int32, msg *NoticeResponse) { - t.beginTrace(sender, encodedLen, "NoticeResponse") - t.finishTrace() + t.writeTrace(sender, encodedLen, "NoticeResponse", nil) } func (t *tracer) traceNotificationResponse(sender byte, encodedLen int32, msg *NotificationResponse) { - t.beginTrace(sender, encodedLen, "NotificationResponse") - fmt.Fprintf(t.buf, "\t %d %s %s", msg.PID, traceDoubleQuotedString([]byte(msg.Channel)), traceDoubleQuotedString([]byte(msg.Payload))) - t.finishTrace() + t.writeTrace(sender, encodedLen, "NotificationResponse", func() { + fmt.Fprintf(t.buf, "\t %d %s %s", msg.PID, traceDoubleQuotedString([]byte(msg.Channel)), traceDoubleQuotedString([]byte(msg.Payload))) + }) } func (t *tracer) traceParameterDescription(sender byte, encodedLen int32, msg *ParameterDescription) { - t.beginTrace(sender, encodedLen, "ParameterDescription") - t.finishTrace() + t.writeTrace(sender, encodedLen, "ParameterDescription", nil) } func (t *tracer) traceParameterStatus(sender byte, encodedLen int32, msg *ParameterStatus) { - t.beginTrace(sender, encodedLen, "ParameterStatus") - fmt.Fprintf(t.buf, "\t %s %s", traceDoubleQuotedString([]byte(msg.Name)), traceDoubleQuotedString([]byte(msg.Value))) - t.finishTrace() + t.writeTrace(sender, encodedLen, "ParameterStatus", func() { + fmt.Fprintf(t.buf, "\t %s %s", traceDoubleQuotedString([]byte(msg.Name)), traceDoubleQuotedString([]byte(msg.Value))) + }) } func (t *tracer) traceParse(sender byte, encodedLen int32, msg *Parse) { - t.beginTrace(sender, encodedLen, "Parse") - fmt.Fprintf(t.buf, "\t %s %s %d", traceDoubleQuotedString([]byte(msg.Name)), traceDoubleQuotedString([]byte(msg.Query)), len(msg.ParameterOIDs)) - for _, oid := range msg.ParameterOIDs { - fmt.Fprintf(t.buf, " %d", oid) - } - t.finishTrace() + t.writeTrace(sender, encodedLen, "Parse", func() { + fmt.Fprintf(t.buf, "\t %s %s %d", traceDoubleQuotedString([]byte(msg.Name)), traceDoubleQuotedString([]byte(msg.Query)), len(msg.ParameterOIDs)) + for _, oid := range msg.ParameterOIDs { + fmt.Fprintf(t.buf, " %d", oid) + } + }) } func (t *tracer) traceParseComplete(sender byte, encodedLen int32, msg *ParseComplete) { - t.beginTrace(sender, encodedLen, "ParseComplete") - t.finishTrace() + t.writeTrace(sender, encodedLen, "ParseComplete", nil) } func (t *tracer) tracePortalSuspended(sender byte, encodedLen int32, msg *PortalSuspended) { - t.beginTrace(sender, encodedLen, "PortalSuspended") - t.finishTrace() + t.writeTrace(sender, encodedLen, "PortalSuspended", nil) } func (t *tracer) traceQuery(sender byte, encodedLen int32, msg *Query) { - t.beginTrace(sender, encodedLen, "Query") - fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString([]byte(msg.String))) - t.finishTrace() + t.writeTrace(sender, encodedLen, "Query", func() { + fmt.Fprintf(t.buf, "\t %s", traceDoubleQuotedString([]byte(msg.String))) + }) } func (t *tracer) traceReadyForQuery(sender byte, encodedLen int32, msg *ReadyForQuery) { - t.beginTrace(sender, encodedLen, "ReadyForQuery") - fmt.Fprintf(t.buf, "\t %c", msg.TxStatus) - t.finishTrace() + t.writeTrace(sender, encodedLen, "ReadyForQuery", func() { + fmt.Fprintf(t.buf, "\t %c", msg.TxStatus) + }) } func (t *tracer) traceRowDescription(sender byte, encodedLen int32, msg *RowDescription) { - t.beginTrace(sender, encodedLen, "RowDescription") - fmt.Fprintf(t.buf, "\t %d", len(msg.Fields)) - for _, fd := range msg.Fields { - 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) - } - t.finishTrace() + t.writeTrace(sender, encodedLen, "RowDescription", func() { + fmt.Fprintf(t.buf, "\t %d", len(msg.Fields)) + for _, fd := range msg.Fields { + 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) + } + }) } func (t *tracer) traceSSLRequest(sender byte, encodedLen int32, msg *SSLRequest) { - t.beginTrace(sender, encodedLen, "SSLRequest") - t.finishTrace() + t.writeTrace(sender, encodedLen, "SSLRequest", nil) } func (t *tracer) traceStartupMessage(sender byte, encodedLen int32, msg *StartupMessage) { - t.beginTrace(sender, encodedLen, "StartupMessage") - t.finishTrace() + t.writeTrace(sender, encodedLen, "StartupMessage", nil) } func (t *tracer) traceSync(sender byte, encodedLen int32, msg *Sync) { - t.beginTrace(sender, encodedLen, "Sync") - t.finishTrace() + t.writeTrace(sender, encodedLen, "Sync", nil) } func (t *tracer) traceTerminate(sender byte, encodedLen int32, msg *Terminate) { - t.beginTrace(sender, encodedLen, "Terminate") - t.finishTrace() + t.writeTrace(sender, encodedLen, "Terminate", nil) } -func (t *tracer) beginTrace(sender byte, encodedLen int32, msgType string) { +func (t *tracer) writeTrace(sender byte, encodedLen int32, msgType string, writeDetails func()) { + t.mux.Lock() + defer t.mux.Unlock() + defer func() { + if t.buf.Cap() > 1024 { + t.buf = &bytes.Buffer{} + } else { + t.buf.Reset() + } + }() + if !t.SuppressTimestamps { now := time.Now() t.buf.WriteString(now.Format("2006-01-02 15:04:05.000000")) @@ -402,17 +382,13 @@ func (t *tracer) beginTrace(sender byte, encodedLen int32, msgType string) { t.buf.WriteString(msgType) t.buf.WriteByte('\t') t.buf.WriteString(strconv.FormatInt(int64(encodedLen), 10)) -} -func (t *tracer) finishTrace() { + if writeDetails != nil { + writeDetails() + } + t.buf.WriteByte('\n') t.buf.WriteTo(t.w) - - if t.buf.Cap() > 1024 { - t.buf = &bytes.Buffer{} - } else { - t.buf.Reset() - } } // traceDoubleQuotedString returns t.buf as a double-quoted string without any escaping. It is roughly equivalent to