Log client and server Bolt messages

fbiville · fbiville · commit ba062545b93f · 2021-05-04T10:33:56.000+02:00
diff --git a/neo4j/internal/bolt/bolt3.go b/neo4j/internal/bolt/bolt3.go
@@ -90,7 +90,13 @@ func NewBolt3(serverName string, conn net.Conn, log log.Logger) *bolt3 {
 		state:      bolt3_unauthorized,
 		conn:       conn,
 		serverName: serverName,
-		in:         &incoming{buf: make([]byte, 4096)},
+		in:         &incoming{
+			buf: make([]byte, 4096),
+			hyd: hydrator{
+				logger: log,
+				logId: "S",
+			},
+		},
 		birthDate:  time.Now(),
 		log:        log,
 	}
@@ -103,6 +109,8 @@ func NewBolt3(serverName string, conn net.Conn, log log.Logger) *bolt3 {
 			}
 			b.state = bolt3_dead
 		},
+		logger: log,
+		logId: "C",
 	}
 	return b
 }
@@ -186,7 +194,10 @@ func (b *bolt3) connect(auth map[string]interface{}, userAgent string) error {
 	}
 
 	b.connId = succ.connectionId
-	b.logId = fmt.Sprintf("%s@%s", b.connId, b.serverName)
+	connectionLogId := fmt.Sprintf("%s@%s", b.connId, b.serverName)
+	b.logId = connectionLogId
+	b.in.hyd.logId = fmt.Sprintf("%s %s", b.in.hyd.logId, connectionLogId)
+	b.out.logId = fmt.Sprintf("%s %s", b.out.logId, connectionLogId)
 	b.serverVersion = succ.server
 
 	// Transition into ready state
diff --git a/neo4j/internal/bolt/bolt4.go b/neo4j/internal/bolt/bolt4.go
@@ -103,12 +103,20 @@ func NewBolt4(serverName string, conn net.Conn, log log.Logger) *bolt4 {
 		birthDate:  time.Now(),
 		log:        log,
 		streams:    openstreams{},
-		in:         incoming{buf: make([]byte, 4096)},
+		in:         incoming{
+			buf: make([]byte, 4096),
+			hyd: hydrator{
+				logger: log,
+				logId: "S",
+			},
+		},
 	}
 	b.out = outgoing{
 		chunker: newChunker(),
 		packer:  packstream.Packer{},
 		onErr:   func(err error) { b.setError(err, true) },
+		logger: log,
+		logId: "C",
 	}
 
 	return b
@@ -239,7 +247,10 @@ func (b *bolt4) connect(minor int, auth map[string]interface{}, userAgent string
 	b.serverVersion = succ.server
 
 	// Construct log identity
-	b.logId = fmt.Sprintf("%s@%s", b.connId, b.serverName)
+	connectionLogId := fmt.Sprintf("%s@%s", b.connId, b.serverName)
+	b.logId = connectionLogId
+	b.in.hyd.logId = fmt.Sprintf("%s %s", b.in.hyd.logId, connectionLogId)
+	b.out.logId = fmt.Sprintf("%s %s", b.out.logId, connectionLogId)
 
 	// Transition into ready state
 	b.state = bolt4_ready
diff --git a/neo4j/internal/bolt/hydrator.go b/neo4j/internal/bolt/hydrator.go
@@ -22,6 +22,7 @@ package bolt
 import (
 	"errors"
 	"fmt"
+	"github.com/neo4j/neo4j-go-driver/v4/neo4j/log"
 	"time"
 
 	"github.com/neo4j/neo4j-go-driver/v4/neo4j/db"
@@ -87,6 +88,8 @@ type hydrator struct {
 	err           error
 	cachedIgnored ignored
 	cachedSuccess success
+	logger        log.Logger
+	logId         string
 }
 
 func (h *hydrator) setErr(err error) {
@@ -142,6 +145,7 @@ func (h *hydrator) ignored(n uint32) *ignored {
 	if h.getErr() != nil {
 		return nil
 	}
+	h.logger.Debugf(log.BoltTrace, h.logId, "IGNORED")
 	return &h.cachedIgnored
 }
 
@@ -166,6 +170,7 @@ func (h *hydrator) failure(n uint32) *db.Neo4jError {
 			h.trash()
 		}
 	}
+	h.logger.Debugf(log.BoltTrace, h.logId, "FAILURE %s", loggableFailure(dberr))
 	return &dberr
 }
 
@@ -236,6 +241,7 @@ func (h *hydrator) success(n uint32) *success {
 			h.trash()
 		}
 	}
+	h.logger.Debugf(log.BoltTrace, h.logId, "SUCCESS %s", loggableSuccess(*succ))
 	return succ
 }
 
@@ -356,6 +362,7 @@ func (h *hydrator) record(n uint32) *db.Record {
 		h.unp.Next()
 		rec.Values[i] = h.value()
 	}
+	h.logger.Debugf(log.BoltTrace, h.logId, "RECORD %s", loggableList(rec.Values))
 	return &rec
 }
 
diff --git a/neo4j/internal/bolt/logging.go b/neo4j/internal/bolt/logging.go
@@ -0,0 +1,94 @@
+package bolt
+
+import (
+	"encoding/json"
+	"github.com/neo4j/neo4j-go-driver/v4/neo4j/db"
+	"strconv"
+	"strings"
+)
+
+type loggableDictionary map[string]interface{}
+
+func (d loggableDictionary) String() string {
+	if credentials, ok := d["credentials"]; ok {
+		d["credentials"] = "<redacted>"
+		defer func() {
+			d["credentials"] = credentials
+		}()
+	}
+	return serializeTrace(d)
+}
+
+type loggableStringDictionary map[string]string
+
+func (sd loggableStringDictionary) String() string {
+	if credentials, ok := sd["credentials"]; ok {
+		sd["credentials"] = "<redacted>"
+		defer func() {
+			sd["credentials"] = credentials
+		}()
+	}
+	return serializeTrace(sd)
+}
+
+type loggableList []interface{}
+
+func (l loggableList) String() string {
+	return serializeTrace(l)
+}
+
+type loggableStringList []string
+
+func (s loggableStringList) String() string {
+	return serializeTrace(s)
+}
+
+type loggableSuccess success
+type loggedSuccess struct {
+	Server       string   `json:"server,omitempty"`
+	ConnectionId string   `json:"connection_id,omitempty"`
+	Fields       []string `json:"fields,omitempty"`
+	TFirst       string   `json:"t_first,omitempty"`
+	Bookmark     string   `json:"bookmark,omitempty"`
+	TLast        string   `json:"t_last,omitempty"`
+	HasMore      bool     `json:"has_more,omitempy"`
+	Db           string   `json:"db,omitempty"`
+}
+
+func (s loggableSuccess) String() string {
+	return serializeTrace(loggedSuccess{
+		Server:       s.server,
+		ConnectionId: s.connectionId,
+		Fields:       s.fields,
+		TFirst:       formatOmittingZero(s.tfirst),
+		Bookmark:     s.bookmark,
+		TLast:        formatOmittingZero(s.tlast),
+		HasMore:      s.hasMore,
+		Db:           s.db,
+	})
+}
+
+func formatOmittingZero(i int64) string {
+	if i == 0 {
+		return ""
+	}
+	return strconv.FormatInt(i, 10)
+}
+
+type loggableFailure db.Neo4jError
+
+func (f *loggableFailure) String() string {
+	return serializeTrace(map[string]interface{}{
+		"code":    f.Code,
+		"message": f.Msg,
+	})
+}
+
+func serializeTrace(v interface{}) string {
+	builder := strings.Builder{}
+	encoder := json.NewEncoder(&builder)
+	encoder.SetEscapeHTML(false)
+	_ = encoder.Encode(v)
+	return strings.TrimSpace(builder.String())
+}
+
diff --git a/neo4j/internal/bolt/outgoing.go b/neo4j/internal/bolt/outgoing.go
@@ -19,6 +19,7 @@
 package bolt
 
 import (
+	"github.com/neo4j/neo4j-go-driver/v4/neo4j/log"
 	"io"
 	"reflect"
 	"time"
@@ -32,6 +33,8 @@ type outgoing struct {
 	chunker chunker
 	packer  packstream.Packer
 	onErr   func(err error)
+	logger  log.Logger
+	logId   string
 }
 
 func (o *outgoing) begin() {
@@ -49,32 +52,37 @@ func (o *outgoing) end() {
 }
 
 func (o *outgoing) appendHello(hello map[string]interface{}) {
+	o.logger.Debugf(log.BoltTrace, o.logId, "HELLO %s", loggableDictionary(hello))
 	o.begin()
 	o.packer.StructHeader(byte(msgHello), 1)
 	o.packMap(hello)
 	o.end()
 }
 
 func (o *outgoing) appendBegin(meta map[string]interface{}) {
+	o.logger.Debugf(log.BoltTrace, o.logId, "BEGIN %s", loggableDictionary(meta))
 	o.begin()
 	o.packer.StructHeader(byte(msgBegin), 1)
 	o.packMap(meta)
 	o.end()
 }
 
 func (o *outgoing) appendCommit() {
+	o.logger.Debugf(log.BoltTrace, o.logId, "COMMIT")
 	o.begin()
 	o.packer.StructHeader(byte(msgCommit), 0)
 	o.end()
 }
 
 func (o *outgoing) appendRollback() {
+	o.logger.Debugf(log.BoltTrace, o.logId, "ROLLBACK")
 	o.begin()
 	o.packer.StructHeader(byte(msgRollback), 0)
 	o.end()
 }
 
 func (o *outgoing) appendRun(cypher string, params, meta map[string]interface{}) {
+	o.logger.Debugf(log.BoltTrace, o.logId, "RUN %q %s %s", cypher, loggableDictionary(params), loggableDictionary(meta))
 	o.begin()
 	o.packer.StructHeader(byte(msgRun), 3)
 	o.packer.String(cypher)
@@ -84,6 +92,7 @@ func (o *outgoing) appendRun(cypher string, params, meta map[string]interface{})
 }
 
 func (o *outgoing) appendPullN(n int) {
+	o.logger.Debugf(log.BoltTrace, o.logId, "PULL %s", loggableDictionary{"n": n})
 	o.begin()
 	o.packer.StructHeader(byte(msgPullN), 1)
 	o.packer.MapHeader(1)
@@ -93,6 +102,7 @@ func (o *outgoing) appendPullN(n int) {
 }
 
 func (o *outgoing) appendPullNQid(n int, qid int64) {
+	o.logger.Debugf(log.BoltTrace, o.logId, "PULL %s", loggableDictionary{"n": n, "qid": qid})
 	o.begin()
 	o.packer.StructHeader(byte(msgPullN), 1)
 	o.packer.MapHeader(2)
@@ -104,6 +114,7 @@ func (o *outgoing) appendPullNQid(n int, qid int64) {
 }
 
 func (o *outgoing) appendDiscardNQid(n int, qid int64) {
+	o.logger.Debugf(log.BoltTrace, o.logId, "DISCARD %s", loggableDictionary{"n": n, "qid": qid})
 	o.begin()
 	o.packer.StructHeader(byte(msgDiscardN), 1)
 	o.packer.MapHeader(2)
@@ -115,12 +126,14 @@ func (o *outgoing) appendDiscardNQid(n int, qid int64) {
 }
 
 func (o *outgoing) appendPullAll() {
+	o.logger.Debugf(log.BoltTrace, o.logId, "PULL ALL")
 	o.begin()
 	o.packer.StructHeader(byte(msgPullAll), 0)
 	o.end()
 }
 
 func (o *outgoing) appendRoute(context map[string]string, bookmarks []string, database string) {
+	o.logger.Debugf(log.BoltTrace, o.logId, "ROUTE %s %s %q", loggableStringDictionary(context), loggableStringList(bookmarks), database)
 	o.begin()
 	o.packer.StructHeader(byte(msgRoute), 3)
 	o.packer.MapHeader(len(context))
@@ -141,12 +154,14 @@ func (o *outgoing) appendRoute(context map[string]string, bookmarks []string, da
 }
 
 func (o *outgoing) appendReset() {
+	o.logger.Debugf(log.BoltTrace, o.logId, "RESET")
 	o.begin()
 	o.packer.StructHeader(byte(msgReset), 0)
 	o.end()
 }
 
 func (o *outgoing) appendGoodbye() {
+	o.logger.Debugf(log.BoltTrace, o.logId, "GOODBYE")
 	o.begin()
 	o.packer.StructHeader(byte(msgGoodbye), 0)
 	o.end()
@@ -336,4 +351,4 @@ func (o *outgoing) packX(x interface{}) {
 	default:
 		o.onErr(&db.UnsupportedTypeError{Type: reflect.TypeOf(x)})
 	}
-}
+}
diff --git a/neo4j/log/logger.go b/neo4j/log/logger.go
@@ -51,12 +51,13 @@ type Logger interface {
 
 // List of component names used as parameter to logger functions.
 const (
-	Bolt3   = "bolt3"
-	Bolt4   = "bolt4"
-	Driver  = "driver"
-	Pool    = "pool"
-	Router  = "router"
-	Session = "session"
+	Bolt3     = "bolt3"
+	Bolt4     = "bolt4"
+	BoltTrace = "bolt-trace"
+	Driver    = "driver"
+	Pool      = "pool"
+	Router    = "router"
+	Session   = "session"
 )
 
 // Last used component id

Original file line number	Diff line number	Diff line change
`@@ -22,6 +22,7 @@ package bolt`
`22`	`22`	`import (`
`23`	`23`	`"errors"`
`24`	`24`	`"fmt"`
	`25`	`+ "github.com/neo4j/neo4j-go-driver/v4/neo4j/log"`
`25`	`26`	`"time"`
`26`	`27`
`27`	`28`	`"github.com/neo4j/neo4j-go-driver/v4/neo4j/db"`
`@@ -87,6 +88,8 @@ type hydrator struct {`
`87`	`88`	`err error`
`88`	`89`	`cachedIgnored ignored`
`89`	`90`	`cachedSuccess success`
	`91`	`+ logger log.Logger`
	`92`	`+ logId string`
`90`	`93`	`}`
`91`	`94`
`92`	`95`	`func (h *hydrator) setErr(err error) {`
`@@ -142,6 +145,7 @@ func (h hydrator) ignored(n uint32) ignored {`
`142`	`145`	`if h.getErr() != nil {`
`143`	`146`	`return nil`
`144`	`147`	`}`
	`148`	`+ h.logger.Debugf(log.BoltTrace, h.logId, "IGNORED")`
`145`	`149`	`return &h.cachedIgnored`
`146`	`150`	`}`
`147`	`151`
`@@ -166,6 +170,7 @@ func (h hydrator) failure(n uint32) db.Neo4jError {`
`166`	`170`	`h.trash()`
`167`	`171`	`}`
`168`	`172`	`}`
	`173`	`+ h.logger.Debugf(log.BoltTrace, h.logId, "FAILURE %s", loggableFailure(dberr))`
`169`	`174`	`return &dberr`
`170`	`175`	`}`
`171`	`176`
`@@ -236,6 +241,7 @@ func (h hydrator) success(n uint32) success {`
`236`	`241`	`h.trash()`
`237`	`242`	`}`
`238`	`243`	`}`
	`244`	`+ h.logger.Debugf(log.BoltTrace, h.logId, "SUCCESS %s", loggableSuccess(*succ))`
`239`	`245`	`return succ`
`240`	`246`	`}`
`241`	`247`
`@@ -356,6 +362,7 @@ func (h hydrator) record(n uint32) db.Record {`
`356`	`362`	`h.unp.Next()`
`357`	`363`	`rec.Values[i] = h.value()`
`358`	`364`	`}`
	`365`	`+ h.logger.Debugf(log.BoltTrace, h.logId, "RECORD %s", loggableList(rec.Values))`
`359`	`366`	`return &rec`
`360`	`367`	`}`
`361`	`368`