logging: Add subsystem to log API (#19002)

Create new code paths for multiple subsystems in the code. This will
make maintaing this easier later.

Also introduce bugLogIf() for errors that should not happen in the first
place.
This commit is contained in:
Anis Eleuch
2024-04-04 13:04:40 +01:00
committed by GitHub
parent 2228eb61cb
commit 95bf4a57b6
123 changed files with 972 additions and 786 deletions

View File

@@ -47,6 +47,18 @@ import (
"github.com/zeebo/xxh3"
)
func gridLogIf(ctx context.Context, err error, errKind ...interface{}) {
logger.LogIf(ctx, "grid", err, errKind...)
}
func gridLogIfNot(ctx context.Context, err error, ignored ...error) {
logger.LogIfNot(ctx, "grid", err, ignored...)
}
func gridLogOnceIf(ctx context.Context, err error, id string, errKind ...interface{}) {
logger.LogOnceIf(ctx, "grid", err, id, errKind...)
}
// A Connection is a remote connection.
// There is no distinction externally whether the connection was initiated from
// this server or from the remote.
@@ -667,7 +679,7 @@ func (c *Connection) connect() {
if gotState != StateConnecting {
// Don't print error on first attempt,
// and after that only once per hour.
logger.LogOnceIf(c.ctx, fmt.Errorf("grid: %s connecting to %s: %w (%T) Sleeping %v (%v)", c.Local, toDial, err, err, sleep, gotState), toDial)
gridLogOnceIf(c.ctx, fmt.Errorf("grid: %s connecting to %s: %w (%T) Sleeping %v (%v)", c.Local, toDial, err, err, sleep, gotState), toDial)
}
c.updateState(StateConnectionError)
time.Sleep(sleep)
@@ -898,7 +910,7 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
go func() {
defer func() {
if rec := recover(); rec != nil {
logger.LogIf(ctx, fmt.Errorf("handleMessages: panic recovered: %v", rec))
gridLogIf(ctx, fmt.Errorf("handleMessages: panic recovered: %v", rec))
debug.PrintStack()
}
c.connChange.L.Lock()
@@ -960,7 +972,7 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
msg, err = readDataInto(msg, conn, c.side, ws.OpBinary)
if err != nil {
cancel(ErrDisconnected)
logger.LogIfNot(ctx, fmt.Errorf("ws read: %w", err), net.ErrClosed, io.EOF)
gridLogIfNot(ctx, fmt.Errorf("ws read: %w", err), net.ErrClosed, io.EOF)
return
}
if c.incomingBytes != nil {
@@ -971,7 +983,7 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
var m message
subID, remain, err := m.parse(msg)
if err != nil {
logger.LogIf(ctx, fmt.Errorf("ws parse package: %w", err))
gridLogIf(ctx, fmt.Errorf("ws parse package: %w", err))
cancel(ErrDisconnected)
return
}
@@ -992,7 +1004,7 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
var next []byte
next, remain, err = msgp.ReadBytesZC(remain)
if err != nil {
logger.LogIf(ctx, fmt.Errorf("ws read merged: %w", err))
gridLogIf(ctx, fmt.Errorf("ws read merged: %w", err))
cancel(ErrDisconnected)
return
}
@@ -1000,7 +1012,7 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
m.Payload = nil
subID, _, err = m.parse(next)
if err != nil {
logger.LogIf(ctx, fmt.Errorf("ws parse merged: %w", err))
gridLogIf(ctx, fmt.Errorf("ws parse merged: %w", err))
cancel(ErrDisconnected)
return
}
@@ -1012,7 +1024,7 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
// Write function.
defer func() {
if rec := recover(); rec != nil {
logger.LogIf(ctx, fmt.Errorf("handleMessages: panic recovered: %v", rec))
gridLogIf(ctx, fmt.Errorf("handleMessages: panic recovered: %v", rec))
debug.PrintStack()
}
if debugPrint {
@@ -1058,14 +1070,14 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
if lastPong > 0 {
lastPongTime := time.Unix(lastPong, 0)
if d := time.Since(lastPongTime); d > connPingInterval*2 {
logger.LogIf(ctx, fmt.Errorf("host %s last pong too old (%v); disconnecting", c.Remote, d.Round(time.Millisecond)))
gridLogIf(ctx, fmt.Errorf("host %s last pong too old (%v); disconnecting", c.Remote, d.Round(time.Millisecond)))
return
}
}
var err error
toSend, err = pingFrame.MarshalMsg(GetByteBuffer()[:0])
if err != nil {
logger.LogIf(ctx, err)
gridLogIf(ctx, err)
// Fake it...
atomic.StoreInt64(&c.LastPong, time.Now().Unix())
continue
@@ -1107,18 +1119,18 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
buf.Reset()
err := wsw.writeMessage(&buf, c.side, ws.OpBinary, toSend)
if err != nil {
logger.LogIf(ctx, fmt.Errorf("ws writeMessage: %w", err))
gridLogIf(ctx, fmt.Errorf("ws writeMessage: %w", err))
return
}
PutByteBuffer(toSend)
err = conn.SetWriteDeadline(time.Now().Add(connWriteTimeout))
if err != nil {
logger.LogIf(ctx, fmt.Errorf("conn.SetWriteDeadline: %w", err))
gridLogIf(ctx, fmt.Errorf("conn.SetWriteDeadline: %w", err))
return
}
_, err = buf.WriteTo(conn)
if err != nil {
logger.LogIf(ctx, fmt.Errorf("ws write: %w", err))
gridLogIf(ctx, fmt.Errorf("ws write: %w", err))
return
}
continue
@@ -1135,7 +1147,7 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
var err error
toSend, err = m.MarshalMsg(toSend)
if err != nil {
logger.LogIf(ctx, fmt.Errorf("msg.MarshalMsg: %w", err))
gridLogIf(ctx, fmt.Errorf("msg.MarshalMsg: %w", err))
return
}
// Append as byte slices.
@@ -1151,18 +1163,18 @@ func (c *Connection) handleMessages(ctx context.Context, conn net.Conn) {
buf.Reset()
err = wsw.writeMessage(&buf, c.side, ws.OpBinary, toSend)
if err != nil {
logger.LogIf(ctx, fmt.Errorf("ws writeMessage: %w", err))
gridLogIf(ctx, fmt.Errorf("ws writeMessage: %w", err))
return
}
// buf is our local buffer, so we can reuse it.
err = conn.SetWriteDeadline(time.Now().Add(connWriteTimeout))
if err != nil {
logger.LogIf(ctx, fmt.Errorf("conn.SetWriteDeadline: %w", err))
gridLogIf(ctx, fmt.Errorf("conn.SetWriteDeadline: %w", err))
return
}
_, err = buf.WriteTo(conn)
if err != nil {
logger.LogIf(ctx, fmt.Errorf("ws write: %w", err))
gridLogIf(ctx, fmt.Errorf("ws write: %w", err))
return
}
@@ -1202,7 +1214,7 @@ func (c *Connection) handleMsg(ctx context.Context, m message, subID *subHandler
case OpMuxConnectError:
c.handleConnectMuxError(ctx, m)
default:
logger.LogIf(ctx, fmt.Errorf("unknown message type: %v", m.Op))
gridLogIf(ctx, fmt.Errorf("unknown message type: %v", m.Op))
}
}
@@ -1211,7 +1223,7 @@ func (c *Connection) handleConnectMux(ctx context.Context, m message, subID *sub
if m.Flags&FlagStateless != 0 {
// Reject for now, so we can safely add it later.
if true {
logger.LogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Stateless streams not supported"}))
gridLogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Stateless streams not supported"}))
return
}
@@ -1222,7 +1234,7 @@ func (c *Connection) handleConnectMux(ctx context.Context, m message, subID *sub
handler = c.handlers.subStateless[*subID]
}
if handler == nil {
logger.LogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler for type"}))
gridLogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler for type"}))
return
}
_, _ = c.inStream.LoadOrCompute(m.MuxID, func() *muxServer {
@@ -1233,7 +1245,7 @@ func (c *Connection) handleConnectMux(ctx context.Context, m message, subID *sub
var handler *StreamHandler
if subID == nil {
if !m.Handler.valid() {
logger.LogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler"}))
gridLogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler"}))
return
}
handler = c.handlers.streams[m.Handler]
@@ -1241,7 +1253,7 @@ func (c *Connection) handleConnectMux(ctx context.Context, m message, subID *sub
handler = c.handlers.subStreams[*subID]
}
if handler == nil {
logger.LogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler for type"}))
gridLogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler for type"}))
return
}
@@ -1257,7 +1269,7 @@ func (c *Connection) handleConnectMuxError(ctx context.Context, m message) {
if v, ok := c.outgoing.Load(m.MuxID); ok {
var cErr muxConnectError
_, err := cErr.UnmarshalMsg(m.Payload)
logger.LogIf(ctx, err)
gridLogIf(ctx, err)
v.error(RemoteErr(cErr.Error))
return
}
@@ -1269,7 +1281,7 @@ func (c *Connection) handleAckMux(ctx context.Context, m message) {
v, ok := c.outgoing.Load(m.MuxID)
if !ok {
if m.Flags&FlagEOF == 0 {
logger.LogIf(ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: m.MuxID}, nil))
gridLogIf(ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: m.MuxID}, nil))
}
return
}
@@ -1281,7 +1293,7 @@ func (c *Connection) handleAckMux(ctx context.Context, m message) {
func (c *Connection) handleRequest(ctx context.Context, m message, subID *subHandlerID) {
if !m.Handler.valid() {
logger.LogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler"}))
gridLogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler"}))
return
}
if debugReqs {
@@ -1295,7 +1307,7 @@ func (c *Connection) handleRequest(ctx context.Context, m message, subID *subHan
handler = c.handlers.subSingle[*subID]
}
if handler == nil {
logger.LogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler for type"}))
gridLogIf(ctx, c.queueMsg(m, muxConnectError{Error: "Invalid Handler for type"}))
return
}
@@ -1313,7 +1325,7 @@ func (c *Connection) handleRequest(ctx context.Context, m message, subID *subHan
if rec := recover(); rec != nil {
err = NewRemoteErrString(fmt.Sprintf("handleMessages: panic recovered: %v", rec))
debug.PrintStack()
logger.LogIf(ctx, err)
gridLogIf(ctx, err)
}
}()
b, err = handler(m.Payload)
@@ -1346,7 +1358,7 @@ func (c *Connection) handleRequest(ctx context.Context, m message, subID *subHan
m.Payload = b
m.setZeroPayloadFlag()
}
logger.LogIf(ctx, c.queueMsg(m, nil))
gridLogIf(ctx, c.queueMsg(m, nil))
}(m)
}
@@ -1354,7 +1366,7 @@ func (c *Connection) handlePong(ctx context.Context, m message) {
var pong pongMsg
_, err := pong.UnmarshalMsg(m.Payload)
PutByteBuffer(m.Payload)
logger.LogIf(ctx, err)
gridLogIf(ctx, err)
if m.MuxID == 0 {
atomic.StoreInt64(&c.LastPong, time.Now().Unix())
return
@@ -1364,22 +1376,22 @@ func (c *Connection) handlePong(ctx context.Context, m message) {
} else {
// We don't care if the client was removed in the meantime,
// but we send a disconnect message to the server just in case.
logger.LogIf(ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: m.MuxID}, nil))
gridLogIf(ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: m.MuxID}, nil))
}
}
func (c *Connection) handlePing(ctx context.Context, m message) {
if m.MuxID == 0 {
logger.LogIf(ctx, c.queueMsg(m, &pongMsg{}))
gridLogIf(ctx, c.queueMsg(m, &pongMsg{}))
return
}
// Single calls do not support pinging.
if v, ok := c.inStream.Load(m.MuxID); ok {
pong := v.ping(m.Seq)
logger.LogIf(ctx, c.queueMsg(m, &pong))
gridLogIf(ctx, c.queueMsg(m, &pong))
} else {
pong := pongMsg{NotFound: true}
logger.LogIf(ctx, c.queueMsg(m, &pong))
gridLogIf(ctx, c.queueMsg(m, &pong))
}
return
}
@@ -1442,7 +1454,7 @@ func (c *Connection) handleMuxClientMsg(ctx context.Context, m message) {
if debugPrint {
fmt.Println(c.Local, "OpMuxClientMsg: Unknown Mux:", m.MuxID)
}
logger.LogIf(ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: m.MuxID}, nil))
gridLogIf(ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: m.MuxID}, nil))
PutByteBuffer(m.Payload)
return
}
@@ -1486,7 +1498,7 @@ func (c *Connection) handleMuxServerMsg(ctx context.Context, m message) {
v, ok := c.outgoing.Load(m.MuxID)
if !ok {
if m.Flags&FlagEOF == 0 {
logger.LogIf(ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: m.MuxID}, nil))
gridLogIf(ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: m.MuxID}, nil))
}
PutByteBuffer(m.Payload)
return
@@ -1522,7 +1534,7 @@ func (c *Connection) deleteMux(incoming bool, muxID uint64) {
}
v, loaded := c.inStream.LoadAndDelete(muxID)
if loaded && v != nil {
logger.LogIf(c.ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: muxID}, nil))
gridLogIf(c.ctx, c.queueMsg(message{Op: OpDisconnectClientMux, MuxID: muxID}, nil))
v.close()
}
} else {
@@ -1535,7 +1547,7 @@ func (c *Connection) deleteMux(incoming bool, muxID uint64) {
fmt.Println(muxID, c.String(), "deleteMux: DELETING MUX")
}
v.close()
logger.LogIf(c.ctx, c.queueMsg(message{Op: OpDisconnectServerMux, MuxID: muxID}, nil))
gridLogIf(c.ctx, c.queueMsg(message{Op: OpDisconnectServerMux, MuxID: muxID}, nil))
}
}
}