From 31318fb260ac71de8befe5bbd1fb1529712f41e7 Mon Sep 17 00:00:00 2001 From: Utkarsh Mani Tripathi Date: Tue, 19 Feb 2019 18:46:42 +0530 Subject: [PATCH 1/2] fix(replica): add logs for io timeout in replica Recently we have observed that controller was logging an error if io timeout happened but in replica there was no sign of such error. So log has been added to replica also which compare the the time took for the request to complete with the operation timeout and print logs if required. Signed-off-by: Utkarsh Mani Tripathi --- rpc/server.go | 43 ++++++++++++++++++++++++++++++++++++++----- 1 file changed, 38 insertions(+), 5 deletions(-) diff --git a/rpc/server.go b/rpc/server.go index 5516f732..4c714e77 100644 --- a/rpc/server.go +++ b/rpc/server.go @@ -12,6 +12,7 @@ import ( "github.com/openebs/jiva/types" ) +type operation func(*Message) type Server struct { wire *Wire responses chan *Message @@ -78,6 +79,37 @@ func (s *Server) Handle() error { } } +// timed is wrapper over various operations to varify whether +// those operations took more than the expected time to complete. +func timed(f operation, msg *Message) { + msgType := msg.Type + start := time.Now() + f(msg) + timeSinceStart := time.Since(start) + switch msgType { + case TypeRead: + if timeSinceStart > opReadTimeout { + logrus.Warning("Read time: %d greater than read timeout: %d at controller", opReadTimeout) + } + case TypeWrite: + if timeSinceStart > opWriteTimeout { + logrus.Warning("Write time: %d greater than write timeout: %d at controller", opWriteTimeout) + } + case TypeSync: + if timeSinceStart > opSyncTimeout { + logrus.Warning("Sync time: %d greater than sync timeout: %d at controller", opSyncTimeout) + } + case TypeUnmap: + if timeSinceStart > opUnmapTimeout { + logrus.Warning("Unmap time: %d greater than unmap timeout: %d at controller", opUnmapTimeout) + } + case TypePing: + if timeSinceStart > opPingTimeout { + logrus.Warning("Ping time: %d greater than ping timeout: %d at controller", opPingTimeout) + } + } +} + func (s *Server) readWrite(ret chan<- error) { for { inject.AddPingTimeout() @@ -91,17 +123,18 @@ func (s *Server) readWrite(ret chan<- error) { ret <- err break } + switch msg.Type { case TypeRead: - s.handleRead(msg) + timed(s.handleRead, msg) case TypeWrite: - s.handleWrite(msg) + timed(s.handleWrite, msg) case TypePing: - s.handlePing(msg) + timed(s.handlePing, msg) case TypeSync: - s.handleSync(msg) + timed(s.handleSync, msg) case TypeUnmap: - s.handleUnmap(msg) + timed(s.handleUnmap, msg) /* case TypeUpdate: go s.handleUpdate(msg) From 622ef5cafdd3ffbd843a44718a3ee0205a63b81e Mon Sep 17 00:00:00 2001 From: Utkarsh Mani Tripathi Date: Tue, 19 Feb 2019 19:07:56 +0530 Subject: [PATCH 2/2] fix(replica): add formating in logs Signed-off-by: Utkarsh Mani Tripathi --- rpc/server.go | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/rpc/server.go b/rpc/server.go index 4c714e77..381d148b 100644 --- a/rpc/server.go +++ b/rpc/server.go @@ -89,23 +89,23 @@ func timed(f operation, msg *Message) { switch msgType { case TypeRead: if timeSinceStart > opReadTimeout { - logrus.Warning("Read time: %d greater than read timeout: %d at controller", opReadTimeout) + logrus.Warningf("Read time: %vs greater than read timeout: %v at controller", timeSinceStart.Seconds(), opReadTimeout) } case TypeWrite: if timeSinceStart > opWriteTimeout { - logrus.Warning("Write time: %d greater than write timeout: %d at controller", opWriteTimeout) + logrus.Warningf("Write time: %vs greater than write timeout: %v at controller", timeSinceStart.Seconds(), opWriteTimeout) } case TypeSync: if timeSinceStart > opSyncTimeout { - logrus.Warning("Sync time: %d greater than sync timeout: %d at controller", opSyncTimeout) + logrus.Warningf("Sync time: %vs greater than sync timeout: %v at controller", timeSinceStart.Seconds(), opSyncTimeout) } case TypeUnmap: if timeSinceStart > opUnmapTimeout { - logrus.Warning("Unmap time: %d greater than unmap timeout: %d at controller", opUnmapTimeout) + logrus.Warningf("Unmap time: %vs greater than unmap timeout: %v at controller", timeSinceStart.Seconds(), opUnmapTimeout) } case TypePing: if timeSinceStart > opPingTimeout { - logrus.Warning("Ping time: %d greater than ping timeout: %d at controller", opPingTimeout) + logrus.Warningf("Ping time: %vs greater than ping timeout: %v at controller", timeSinceStart.Seconds(), opPingTimeout) } } }