From 67151746b0f004ac031e4b0559f94467aa2f24c6 Mon Sep 17 00:00:00 2001 From: 9seconds Date: Sun, 8 Jul 2018 12:29:04 +0300 Subject: [PATCH] Rework logging --- wrappers/blockcipher.go | 20 +++++----------- wrappers/conn.go | 20 ++++------------ wrappers/mtproto_abridged.go | 39 +++++++++++-------------------- wrappers/mtproto_frame.go | 32 ++++++++----------------- wrappers/mtproto_intermediate.go | 40 +++++++++++--------------------- wrappers/mtproto_proxy.go | 39 +++++++++++-------------------- wrappers/streamcipher.go | 19 ++++----------- wrappers/wrap.go | 8 +++---- 8 files changed, 68 insertions(+), 149 deletions(-) diff --git a/wrappers/blockcipher.go b/wrappers/blockcipher.go index b4348c2..a4a7149 100644 --- a/wrappers/blockcipher.go +++ b/wrappers/blockcipher.go @@ -6,6 +6,8 @@ import ( "crypto/cipher" "net" + "go.uber.org/zap" + "github.com/9seconds/mtg/utils" "github.com/juju/errors" ) @@ -13,6 +15,7 @@ import ( type BlockCipher struct { buf *bytes.Buffer + logger *zap.SugaredLogger conn StreamReadWriteCloser encryptor cipher.BlockMode decryptor cipher.BlockMode @@ -60,20 +63,8 @@ func (b *BlockCipher) Write(p []byte) (int, error) { return b.conn.Write(encrypted) } -func (b *BlockCipher) LogDebug(msg string, data ...interface{}) { - b.conn.LogDebug(msg, data...) -} - -func (b *BlockCipher) LogInfo(msg string, data ...interface{}) { - b.conn.LogInfo(msg, data...) -} - -func (b *BlockCipher) LogWarn(msg string, data ...interface{}) { - b.conn.LogWarn(msg, data...) -} - -func (b *BlockCipher) LogError(msg string, data ...interface{}) { - b.conn.LogError(msg, data...) +func (b *BlockCipher) Logger() *zap.SugaredLogger { + return b.logger } func (b *BlockCipher) LocalAddr() *net.TCPAddr { @@ -92,6 +83,7 @@ func NewBlockCipher(conn StreamReadWriteCloser, encryptor, decryptor cipher.Bloc return &BlockCipher{ buf: &bytes.Buffer{}, conn: conn, + logger: conn.Logger().Named("block-cipher"), encryptor: encryptor, decryptor: decryptor, } diff --git a/wrappers/conn.go b/wrappers/conn.go index f5484c6..ad853af 100644 --- a/wrappers/conn.go +++ b/wrappers/conn.go @@ -57,7 +57,7 @@ func (c *Conn) Read(p []byte) (int, error) { } func (c *Conn) Close() error { - defer c.LogDebug("Closed connection") + defer c.logger.Debugw("Closed connection") return c.conn.Close() } @@ -80,20 +80,8 @@ func (c *Conn) RemoteAddr() *net.TCPAddr { return c.conn.RemoteAddr().(*net.TCPAddr) } -func (c *Conn) LogDebug(msg string, data ...interface{}) { - c.logger.Debugw(msg, data...) -} - -func (c *Conn) LogInfo(msg string, data ...interface{}) { - c.logger.Infow(msg, data...) -} - -func (c *Conn) LogWarn(msg string, data ...interface{}) { - c.logger.Warnw(msg, data...) -} - -func (c *Conn) LogError(msg string, data ...interface{}) { - c.logger.Errorw(msg, data...) +func (c *Conn) Logger() *zap.SugaredLogger { + return c.logger } func NewConn(conn net.Conn, connID string, purpose ConnPurpose, publicIPv4, publicIPv6 net.IP) StreamReadWriteCloser { @@ -102,7 +90,7 @@ func NewConn(conn net.Conn, connID string, purpose ConnPurpose, publicIPv4, publ "local_address", conn.LocalAddr(), "remote_address", conn.RemoteAddr(), "purpose", purpose, - ) + ).Named("conn") wrapper := Conn{ logger: logger, diff --git a/wrappers/mtproto_abridged.go b/wrappers/mtproto_abridged.go index 5a3803d..41f4e62 100644 --- a/wrappers/mtproto_abridged.go +++ b/wrappers/mtproto_abridged.go @@ -6,6 +6,7 @@ import ( "net" "github.com/juju/errors" + "go.uber.org/zap" "github.com/9seconds/mtg/mtproto" "github.com/9seconds/mtg/utils" @@ -18,15 +19,16 @@ const ( ) type MTProtoAbridged struct { - conn StreamReadWriteCloser - opts *mtproto.ConnectionOpts + conn StreamReadWriteCloser + opts *mtproto.ConnectionOpts + logger *zap.SugaredLogger readCounter uint32 writeCounter uint32 } func (m *MTProtoAbridged) Read() ([]byte, error) { - m.LogDebug("Read packet", + m.logger.Debugw("Read packet", "simple_ack", m.opts.ReadHacks.SimpleAck, "quick_ack", m.opts.ReadHacks.QuickAck, "counter", m.readCounter, @@ -41,7 +43,7 @@ func (m *MTProtoAbridged) Read() ([]byte, error) { msgLength := uint8(buf.Bytes()[0]) buf.Reset() - m.LogDebug("Packet first byte", + m.logger.Debugw("Packet first byte", "byte", msgLength, "counter", m.readCounter, "simple_ack", m.opts.ReadHacks.SimpleAck, @@ -64,7 +66,7 @@ func (m *MTProtoAbridged) Read() ([]byte, error) { } msgLength32 *= 4 - m.LogDebug("Packet length", + m.logger.Debugw("Packet length", "length", msgLength32, "simple_ack", m.opts.ReadHacks.SimpleAck, "quick_ack", m.opts.ReadHacks.QuickAck, @@ -83,7 +85,7 @@ func (m *MTProtoAbridged) Read() ([]byte, error) { } func (m *MTProtoAbridged) Write(p []byte) (int, error) { - m.LogDebug("Write packet", + m.logger.Debugw("Write packet", "length", len(p), "simple_ack", m.opts.WriteHacks.SimpleAck, "quick_ack", m.opts.WriteHacks.QuickAck, @@ -124,24 +126,8 @@ func (m *MTProtoAbridged) Write(p []byte) (int, error) { return 0, errors.Errorf("Packet is too big %d", len(p)) } -func (m *MTProtoAbridged) LogDebug(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "abridged"}...) - m.conn.LogDebug(msg, data...) -} - -func (m *MTProtoAbridged) LogInfo(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "abridged"}...) - m.conn.LogInfo(msg, data...) -} - -func (m *MTProtoAbridged) LogWarn(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "abridged"}...) - m.conn.LogWarn(msg, data...) -} - -func (m *MTProtoAbridged) LogError(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "abridged"}...) - m.conn.LogError(msg, data...) +func (m *MTProtoAbridged) Logger() *zap.SugaredLogger { + return m.logger } func (m *MTProtoAbridged) LocalAddr() *net.TCPAddr { @@ -158,7 +144,8 @@ func (m *MTProtoAbridged) Close() error { func NewMTProtoAbridged(conn StreamReadWriteCloser, opts *mtproto.ConnectionOpts) PacketReadWriteCloser { return &MTProtoAbridged{ - conn: conn, - opts: opts, + conn: conn, + opts: opts, + logger: conn.Logger().Named("mtproto-abridged"), } } diff --git a/wrappers/mtproto_frame.go b/wrappers/mtproto_frame.go index ad54941..71ee084 100644 --- a/wrappers/mtproto_frame.go +++ b/wrappers/mtproto_frame.go @@ -10,6 +10,7 @@ import ( "net" "github.com/juju/errors" + "go.uber.org/zap" ) const ( @@ -20,7 +21,9 @@ const ( var mtprotoFramePadding = []byte{0x04, 0x00, 0x00, 0x00} type MTProtoFrame struct { - conn StreamReadWriteCloser + conn StreamReadWriteCloser + logger *zap.SugaredLogger + readSeqNo int32 writeSeqNo int32 } @@ -42,7 +45,7 @@ func (m *MTProtoFrame) Read() ([]byte, error) { } messageLength := binary.LittleEndian.Uint32(buf.Bytes()) - m.LogDebug("Read MTProto frame", + m.logger.Debugw("Read MTProto frame", "messageLength", messageLength, "sequence_number", m.readSeqNo, ) @@ -75,7 +78,7 @@ func (m *MTProtoFrame) Read() ([]byte, error) { return nil, errors.Errorf("CRC32 checksum mismatch. Wait for %d, got %d", sum.Sum32(), checksum) } - m.LogDebug("Read MTProto frame", + m.logger.Debugw("Read MTProto frame", "messageLength", messageLength, "sequence_number", m.readSeqNo, "dataLength", len(data), @@ -101,7 +104,7 @@ func (m *MTProtoFrame) Write(p []byte) (int, error) { binary.Write(buf, binary.LittleEndian, checksum) buf.Write(bytes.Repeat(mtprotoFramePadding, paddingLength/4)) - m.LogDebug("Write MTProto frame", + m.logger.Debugw("Write MTProto frame", "length", len(p), "sequence_number", m.writeSeqNo, "crc32", checksum, @@ -114,24 +117,8 @@ func (m *MTProtoFrame) Write(p []byte) (int, error) { return len(p), err } -func (m *MTProtoFrame) LogDebug(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "frame"}...) - m.conn.LogDebug(msg, data...) -} - -func (m *MTProtoFrame) LogInfo(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "frame"}...) - m.conn.LogInfo(msg, data...) -} - -func (m *MTProtoFrame) LogWarn(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "frame"}...) - m.conn.LogWarn(msg, data...) -} - -func (m *MTProtoFrame) LogError(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "frame"}...) - m.conn.LogError(msg, data...) +func (m *MTProtoFrame) Logger() *zap.SugaredLogger { + return m.logger } func (m *MTProtoFrame) LocalAddr() *net.TCPAddr { @@ -149,6 +136,7 @@ func (m *MTProtoFrame) Close() error { func NewMTProtoFrame(conn StreamReadWriteCloser, seqNo int32) PacketReadWriteCloser { return &MTProtoFrame{ conn: conn, + logger: conn.Logger().Named("mtproto-frame"), readSeqNo: seqNo, writeSeqNo: seqNo, } diff --git a/wrappers/mtproto_intermediate.go b/wrappers/mtproto_intermediate.go index 9ef9673..5ed8e00 100644 --- a/wrappers/mtproto_intermediate.go +++ b/wrappers/mtproto_intermediate.go @@ -6,22 +6,25 @@ import ( "io" "net" - "github.com/9seconds/mtg/mtproto" "github.com/juju/errors" + "go.uber.org/zap" + + "github.com/9seconds/mtg/mtproto" ) const mtprotoIntermediateQuickAckLength = 0x80000000 type MTProtoIntermediate struct { - conn StreamReadWriteCloser - opts *mtproto.ConnectionOpts + conn StreamReadWriteCloser + opts *mtproto.ConnectionOpts + logger *zap.SugaredLogger readCounter uint32 writeCounter uint32 } func (m *MTProtoIntermediate) Read() ([]byte, error) { - m.LogDebug("Read packet", + m.logger.Debugw("Read packet", "simple_ack", m.opts.ReadHacks.SimpleAck, "quick_ack", m.opts.ReadHacks.QuickAck, "counter", m.readCounter, @@ -35,7 +38,7 @@ func (m *MTProtoIntermediate) Read() ([]byte, error) { } length := binary.LittleEndian.Uint32(buf.Bytes()) - m.LogDebug("Packet message length", + m.logger.Debugw("Packet message length", "simple_ack", m.opts.ReadHacks.SimpleAck, "quick_ack", m.opts.ReadHacks.QuickAck, "counter", m.readCounter, @@ -62,7 +65,7 @@ func (m *MTProtoIntermediate) Read() ([]byte, error) { } func (m *MTProtoIntermediate) Write(p []byte) (int, error) { - m.LogDebug("Write packet", + m.logger.Debugw("Write packet", "simple_ack", m.opts.WriteHacks.SimpleAck, "quick_ack", m.opts.WriteHacks.QuickAck, "counter", m.writeCounter, @@ -79,24 +82,8 @@ func (m *MTProtoIntermediate) Write(p []byte) (int, error) { return m.conn.Write(append(length[:], p...)) } -func (m *MTProtoIntermediate) LogDebug(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "intermediate"}...) - m.conn.LogDebug(msg, data...) -} - -func (m *MTProtoIntermediate) LogInfo(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "intermediate"}...) - m.conn.LogInfo(msg, data...) -} - -func (m *MTProtoIntermediate) LogWarn(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "intermediate"}...) - m.conn.LogWarn(msg, data...) -} - -func (m *MTProtoIntermediate) LogError(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "intermediate"}...) - m.conn.LogError(msg, data...) +func (m *MTProtoIntermediate) Logger() *zap.SugaredLogger { + return m.logger } func (m *MTProtoIntermediate) LocalAddr() *net.TCPAddr { @@ -113,7 +100,8 @@ func (m *MTProtoIntermediate) Close() error { func NewMTProtoIntermediate(conn StreamReadWriteCloser, opts *mtproto.ConnectionOpts) PacketReadWriteCloser { return &MTProtoIntermediate{ - conn: conn, - opts: opts, + conn: conn, + logger: conn.Logger().Named("mtproto-intermediate"), + opts: opts, } } diff --git a/wrappers/mtproto_proxy.go b/wrappers/mtproto_proxy.go index b12e00e..d6ffcef 100644 --- a/wrappers/mtproto_proxy.go +++ b/wrappers/mtproto_proxy.go @@ -5,21 +5,23 @@ import ( "net" "github.com/juju/errors" + "go.uber.org/zap" "github.com/9seconds/mtg/mtproto" "github.com/9seconds/mtg/mtproto/rpc" ) type MTProtoProxy struct { - conn PacketReadWriteCloser - req *rpc.ProxyRequest + conn PacketReadWriteCloser + req *rpc.ProxyRequest + logger *zap.SugaredLogger readCounter uint32 writeCounter uint32 } func (m *MTProtoProxy) Read() ([]byte, error) { - m.LogDebug("Read packet", + m.logger.Debugw("Read packet", "counter", m.readCounter, "simple_ack", m.req.Options.WriteHacks.SimpleAck, "quick_ack", m.req.Options.WriteHacks.QuickAck, @@ -29,7 +31,7 @@ func (m *MTProtoProxy) Read() ([]byte, error) { if err != nil { return nil, errors.Annotate(err, "Cannot read packet") } - m.LogDebug("Read packet length", + m.logger.Debugw("Read packet length", "counter", m.readCounter, "simple_ack", m.req.Options.WriteHacks.SimpleAck, "quick_ack", m.req.Options.WriteHacks.QuickAck, @@ -41,7 +43,7 @@ func (m *MTProtoProxy) Read() ([]byte, error) { } tag, packet := packet[:4], packet[4:] - m.LogDebug("Read RPC tag", + m.logger.Debugw("Read RPC tag", "counter", m.readCounter, "simple_ack", m.req.Options.WriteHacks.SimpleAck, "quick_ack", m.req.Options.WriteHacks.QuickAck, @@ -82,7 +84,7 @@ func (m *MTProtoProxy) readCloseExt(data []byte) ([]byte, error) { } func (m *MTProtoProxy) Write(p []byte) (int, error) { - m.LogDebug("Write packet", + m.logger.Debugw("Write packet", "length", len(p), "counter", m.writeCounter, "simple_ack", m.req.Options.ReadHacks.SimpleAck, @@ -97,24 +99,8 @@ func (m *MTProtoProxy) Write(p []byte) (int, error) { return len(p), nil } -func (m *MTProtoProxy) LogDebug(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "proxy"}...) - m.conn.LogDebug(msg, data...) -} - -func (m *MTProtoProxy) LogInfo(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "proxy"}...) - m.conn.LogInfo(msg, data...) -} - -func (m *MTProtoProxy) LogWarn(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "proxy"}...) - m.conn.LogWarn(msg, data...) -} - -func (m *MTProtoProxy) LogError(msg string, data ...interface{}) { - data = append(data, []interface{}{"type", "proxy"}...) - m.conn.LogError(msg, data...) +func (m *MTProtoProxy) Logger() *zap.SugaredLogger { + return m.logger } func (m *MTProtoProxy) LocalAddr() *net.TCPAddr { @@ -136,7 +122,8 @@ func NewMTProtoProxy(conn PacketReadWriteCloser, connOpts *mtproto.ConnectionOpt } return &MTProtoProxy{ - conn: conn, - req: req, + conn: conn, + logger: conn.Logger().Named("mtproto-proxy"), + req: req, }, nil } diff --git a/wrappers/streamcipher.go b/wrappers/streamcipher.go index f7c6376..da89535 100644 --- a/wrappers/streamcipher.go +++ b/wrappers/streamcipher.go @@ -5,12 +5,14 @@ import ( "net" "github.com/juju/errors" + "go.uber.org/zap" ) type StreamCipher struct { encryptor cipher.Stream decryptor cipher.Stream conn StreamReadWriteCloser + logger *zap.SugaredLogger } func (s *StreamCipher) Read(p []byte) (int, error) { @@ -30,20 +32,8 @@ func (s *StreamCipher) Write(p []byte) (int, error) { return s.conn.Write(encrypted) } -func (s *StreamCipher) LogDebug(msg string, data ...interface{}) { - s.conn.LogDebug(msg, data...) -} - -func (s *StreamCipher) LogInfo(msg string, data ...interface{}) { - s.conn.LogInfo(msg, data...) -} - -func (s *StreamCipher) LogWarn(msg string, data ...interface{}) { - s.conn.LogWarn(msg, data...) -} - -func (s *StreamCipher) LogError(msg string, data ...interface{}) { - s.conn.LogError(msg, data...) +func (s *StreamCipher) Logger() *zap.SugaredLogger { + return s.logger } func (s *StreamCipher) LocalAddr() *net.TCPAddr { @@ -61,6 +51,7 @@ func (s *StreamCipher) Close() error { func NewStreamCipher(conn StreamReadWriteCloser, encryptor, decryptor cipher.Stream) StreamReadWriteCloser { return &StreamCipher{ conn: conn, + logger: conn.Logger().Named("stream-cipher"), encryptor: encryptor, decryptor: decryptor, } diff --git a/wrappers/wrap.go b/wrappers/wrap.go index 20cf7a0..923bb20 100644 --- a/wrappers/wrap.go +++ b/wrappers/wrap.go @@ -3,14 +3,12 @@ package wrappers import ( "io" "net" + + "go.uber.org/zap" ) type Wrap interface { - LogDebug(msg string, data ...interface{}) - LogInfo(msg string, data ...interface{}) - LogWarn(msg string, data ...interface{}) - LogError(msg string, data ...interface{}) - + Logger() *zap.SugaredLogger LocalAddr() *net.TCPAddr RemoteAddr() *net.TCPAddr }