add logging guidelines to README.md and adjust logs to them

README.md

@@ -47,8 +47,36 @@ curl -XPOST localhost:8502/pingpong/4932309428148935717
 - Package pkg/p2p/libp2p and is only allowed to depend on go-libp2p packages given that it is just one pkg/p2p implementation. No other implementation should depend on go-libp2p packages.
 - Package pkg/p2p/protobuf provides all the helpers needed to make easer for protocol implementations to use protocol buffers for encoding.
 
+## Logging guidelines
+
+Log messages are categorized in five different severities: error, warning, info, debug and trace, with semantic meaning associated with each of them.
+
+Two types of application users are identified: regular user and developer. Regular user should not be presented with confusing technical implementation details in log messages, but only with meaningful information related to application operability in a form of meaningful statements. Developers are users that are aware of implementation details and they will benefit from technical details to help them debug the application problematic state.
+
+This means that the same problematic event may have two log lines but with different severities. This is the case with Error/Debug or Warning/Debug combo where Error or Warning is meant for the regular user and the Debug for developers to help them investigate the issue. Info and Trace log levels are informative about the expected state changes, but Info, with operable information, for regular user, and Trace, with technical details, for developer.
+
+### Error
+
+Error log messages are meant for regular users to be informed about the event that is happening which is not expected or may require intervention from the user for application to function properly. Log messages should be written as a statement, e.g. *unable to connect to peer 12345* and should not reveal technical details about internal implementation, such are package name, variable name or internal variable state. It should contain information only relevant to the user operating the application, concepts that can be operated on using exposed application interfaces.
+
+### Warning
+
+Warning log messages are also meant for regular users, as Error log messages, but are just informative about the state of the application that it can handle itself, by retry mechanism, for example. They should have the same form as the Error log messages.
+
+### Info
+
+Info log messages are informing users about the changes that are changing the application state in the expected manner, or presenting the user the information that can be used to operate the application, such as *node address: 12345*.
+
+### Debug
+
+Debug log messages are meant for developers to identify the problem that has happened. They should contain as much as possible internal technical information and applications state to be able to reproduce and debug the issue. Format of such log messages should be declarative with colon `:` as the separator between code concepts as nested call stacks, components or abstractions, e.g. *handshake: parse peer /p2p/Qm2313123 address 12345: encoding/hex: odd length hex string*, just like Go error values are chained with annotations.
+
+### Trace
+
+Trace log messages are meant to inform developers about expected successful operations that are not relevant for regular users, but may be useful for understanding states in which application is going through. The form should be the same as Debug log messages.
+
 ## TODO
 
 - P2P mock (protocol tester) implementation improvements
 - Figure out routing (whether to use libp2p Routing or to abstract hive on top of p2p package)
-- Instrumentation: logging, metrics, tracing, pprof...
+- Instrumentation: tracing

cmd/bee/cmd/start.go

@@ -116,6 +116,7 @@ func (c *command) initStartCmd() (err error) {
 			sig := <-interruptChannel
 
 			logger.Debugf("received signal: %v", sig)
+			logger.Info("shutting down")
 
 			// Shutdown
 			done := make(chan struct{})

pkg/api/pingpong.go

@@ -24,17 +24,19 @@ func (s *server) pingpongHandler(w http.ResponseWriter, r *http.Request) {
 
 	rtt, err := s.Pingpong.Ping(ctx, peerID, "hey", "there", ",", "how are", "you", "?")
 	if err != nil {
+		s.Logger.Debugf("pingpong: ping %s: %v", peerID, err)
 		if errors.Is(err, p2p.ErrPeerNotFound) {
-			s.Logger.Debugf("pingpong: ping %s: %v", peerID, err)
 			jsonhttp.NotFound(w, "peer not found")
 			return
 		}
-		s.Logger.Errorf("pingpong: ping %s: %v", peerID, err)
-		jsonhttp.InternalServerError(w, err)
+
+		s.Logger.Errorf("pingpong failed to peer %s", peerID)
+		jsonhttp.InternalServerError(w, nil)
 		return
 	}
 	s.metrics.PingRequestCount.Inc()
 
+	s.Logger.Infof("pingpong succeeded to peer %s", peerID)
 	jsonhttp.OK(w, pingpongResponse{
 		RTT: rtt,
 	})

pkg/api/pingpong_test.go

@@ -56,7 +56,7 @@ func TestPingpong(t *testing.T) {
 	t.Run("error", func(t *testing.T) {
 		jsonhttptest.ResponseDirect(t, client, http.MethodPost, "/pingpong/"+errorPeerID, nil, http.StatusInternalServerError, jsonhttp.StatusResponse{
 			Code:    http.StatusInternalServerError,
-			Message: testErr.Error(),
+			Message: http.StatusText(http.StatusInternalServerError), // do not leek internal error
 		})
 	})
 

pkg/debugapi/peer.go

@@ -26,7 +26,8 @@ func (s *server) peerConnectHandler(w http.ResponseWriter, r *http.Request) {
 
 	address, err := s.P2P.Connect(r.Context(), addr)
 	if err != nil {
-		s.Logger.Errorf("debug api: peer connect: %v", err)
+		s.Logger.Debugf("debug api: peer connect %s: %v", addr, err)
+		s.Logger.Errorf("unable to connect to peer %s", addr)
 		jsonhttp.InternalServerError(w, err)
 		return
 	}

pkg/node/node.go

@@ -96,7 +96,8 @@ func NewBee(o Options) (*Bee, error) {
 			logger.Infof("api address: %s", apiListener.Addr())
 
 			if err := apiServer.Serve(apiListener); err != nil && err != http.ErrServerClosed {
-				logger.Errorf("api server: %v", err)
+				logger.Debugf("api server: %v", err)
+				logger.Error("unable to serve api")
 			}
 		}()
 
@@ -133,7 +134,8 @@ func NewBee(o Options) (*Bee, error) {
 			logger.Infof("debug api address: %s", debugAPIListener.Addr())
 
 			if err := debugAPIServer.Serve(debugAPIListener); err != nil && err != http.ErrServerClosed {
-				logger.Errorf("debug api server: %v", err)
+				logger.Debugf("debug api server: %v", err)
+				logger.Error("unable to serve debug api")
 			}
 		}()
 

pkg/p2p/libp2p/internal/handshake/handshake.go

@@ -50,7 +50,7 @@ func (s *Service) Handshake(stream p2p.Stream) (i *Info, err error) {
 		return nil, fmt.Errorf("ack: write message: %w", err)
 	}
 
-	s.logger.Debugf("handshake finished for peer %s", resp.ShakeHand.Address)
+	s.logger.Tracef("handshake finished for peer %s", resp.ShakeHand.Address)
 
 	return &Info{
 		Address:   resp.ShakeHand.Address,
@@ -83,7 +83,7 @@ func (s *Service) Handle(stream p2p.Stream) (i *Info, err error) {
 		return nil, fmt.Errorf("ack: read message: %w", err)
 	}
 
-	s.logger.Debugf("handshake finished for peer %s", req.Address)
+	s.logger.Tracef("handshake finished for peer %s", req.Address)
 	return &Info{
 		Address:   req.Address,
 		NetworkID: req.NetworkID,

pkg/p2p/libp2p/libp2p.go

@@ -211,20 +211,21 @@ func New(ctx context.Context, o Options) (*Service, error) {
 		peerID := stream.Conn().RemotePeer()
 		i, err := s.handshakeService.Handle(stream)
 		if err != nil {
-			s.logger.Errorf("handshake with x %s: %w", peerID, err)
+			s.logger.Debugf("handshake: handle %s: %w", peerID, err)
+			s.logger.Errorf("unable to handshake with peer %v", peerID)
 			// todo: test connection close and refactor
 			_ = stream.Conn().Close()
 			return
 		}
 		if i.NetworkID != s.networkID {
-			s.logger.Errorf("handshake with peer %s: invalid network id %v", peerID, i.NetworkID)
+			s.logger.Warningf("peer %s has a different network id %v", peerID, i.NetworkID)
 			// todo: test connection close and refactor
 			_ = stream.Conn().Close()
 			return
 		}
 		s.peers.add(peerID, i.Address)
 		s.metrics.HandledStreamCount.Inc()
-		s.logger.Infof("peer %q connected", i.Address)
+		s.logger.Infof("peer %s connected", i.Address)
 	})
 
 	// TODO: be more resilient on connection errors and connect in parallel
@@ -275,7 +276,7 @@ func (s *Service) AddProtocol(p p2p.ProtocolSpec) (err error) {
 					_ = stream.Conn().Close()
 				}
 
-				s.logger.Errorf("%s: %s/%s: %w", p.Name, ss.Name, ss.Version, err)
+				s.logger.Debugf("handle protocol %s: stream %s/%s: peer %s: %w", p.Name, ss.Name, ss.Version, overlay, err)
 			}
 		})
 	}
@@ -324,7 +325,7 @@ func (s *Service) Connect(ctx context.Context, addr ma.Multiaddr) (overlay strin
 
 	s.peers.add(info.ID, i.Address)
 	s.metrics.CreatedConnectionCount.Inc()
-	s.logger.Infof("peer %q connected", i.Address)
+	s.logger.Infof("peer %s connected", i.Address)
 	return i.Address, nil
 }
 

pkg/pingpong/pingpong.go

@@ -84,7 +84,7 @@ func (s *Service) Ping(ctx context.Context, address string, msgs ...string) (rtt
 			return 0, fmt.Errorf("read message: %w", err)
 		}
 
-		s.logger.Debugf("got pong: %q", pong.Response)
+		s.logger.Tracef("got pong: %q", pong.Response)
 		s.metrics.PongReceivedCount.Inc()
 	}
 	return time.Since(start), nil
@@ -102,7 +102,7 @@ func (s *Service) Handler(peer p2p.Peer, stream p2p.Stream) error {
 			}
 			return fmt.Errorf("read message: %w", err)
 		}
-		s.logger.Debugf("got ping: %q", ping.Greeting)
+		s.logger.Tracef("got ping: %q", ping.Greeting)
 		s.metrics.PingReceivedCount.Inc()
 
 		if err := w.WriteMsg(&pb.Pong{