From c67a07b469d4e6a016348cb84766595dee36403a Mon Sep 17 00:00:00 2001 From: Aliaksandr Valialkin <valyala@gmail.com> Date: Tue, 2 Mar 2021 21:18:32 +0200 Subject: [PATCH] lib/handshake: log read/write operation duration on connection errors This improve debuggability of network errors --- app/vmstorage/transport/server.go | 2 +- lib/handshake/buffered_conn.go | 16 ++++++++++++++-- 2 files changed, 15 insertions(+), 3 deletions(-) diff --git a/app/vmstorage/transport/server.go b/app/vmstorage/transport/server.go index 059882a52d..458b079aab 100644 --- a/app/vmstorage/transport/server.go +++ b/app/vmstorage/transport/server.go @@ -311,7 +311,7 @@ func (s *Server) processVMInsertConn(bc *handshake.BufferedConn) error { } reqBuf = bytesutil.Resize(reqBuf, int(packetSize)) if n, err := io.ReadFull(bc, reqBuf); err != nil { - return fmt.Errorf("cannot read packet with size %d: %w; read only %d bytes", packetSize, err, n) + return fmt.Errorf("cannot read packet with size %d bytes: %w; read only %d bytes", packetSize, err, n) } // Send `ack` to vminsert that the packet has been received. deadline := time.Now().Add(5 * time.Second) diff --git a/lib/handshake/buffered_conn.go b/lib/handshake/buffered_conn.go index 50fbafb4b4..5fedd1b17d 100644 --- a/lib/handshake/buffered_conn.go +++ b/lib/handshake/buffered_conn.go @@ -2,8 +2,10 @@ package handshake import ( "bufio" + "fmt" "io" "net" + "time" "github.com/VictoriaMetrics/VictoriaMetrics/lib/encoding/zstd" ) @@ -43,14 +45,24 @@ func newBufferedConn(c net.Conn, compressionLevel int, isReadCompressed bool) *B // Read reads up to len(p) from bc to p. func (bc *BufferedConn) Read(p []byte) (int, error) { - return bc.br.Read(p) + startTime := time.Now() + n, err := bc.br.Read(p) + if err != nil { + err = fmt.Errorf("cannot read data in %.3f seconds: %w", time.Since(startTime).Seconds(), err) + } + return n, err } // Write writes p to bc. // // Do not forget to call Flush if needed. func (bc *BufferedConn) Write(p []byte) (int, error) { - return bc.bw.Write(p) + startTime := time.Now() + n, err := bc.bw.Write(p) + if err != nil { + err = fmt.Errorf("cannot write data in %.3f seconds: %w", time.Since(startTime).Seconds(), err) + } + return n, err } // Close closes bc.