Fix data race when pgproto3 trace is enabled during CopyFrom

https://github.com/jackc/pgx/issues/1703
pull/1708/head
Jack Christensen 2023-08-05 07:30:59 -05:00
parent d626dfe94e
commit e9087eacb8
1 changed files with 118 additions and 142 deletions

View File

@ -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