Merge pull request #343 from rade/340_improve_connection_logging

LGTM.  Closes #340 - I tested with UDP blocked and got desired log.

router/connection.go

@@ -30,7 +30,7 @@ func (conn *RemoteConnection) RemoteTCPAddr() string {
 	return conn.remoteTCPAddr
 }
 
-func (conn *RemoteConnection) Shutdown() {
+func (conn *RemoteConnection) Shutdown(error) {
 }
 
 func (conn *RemoteConnection) Established() bool {
@@ -86,11 +86,9 @@ func (conn *LocalConnection) RemoteUDPAddr() *net.UDPAddr {
 // peer actor process. Do not call this from the connection's actor
 // process itself.
 func (conn *LocalConnection) CheckFatal(err error) error {
-	if err == nil {
-		return nil
+	if err != nil {
+		conn.Shutdown(err)
 	}
-	conn.log("error:", err)
-	conn.Shutdown()
 	return err
 }
 
@@ -130,8 +128,10 @@ const (
 )
 
 // Async
-func (conn *LocalConnection) Shutdown() {
-	conn.queryChan <- &ConnectionInteraction{Interaction: Interaction{code: CShutdown}}
+func (conn *LocalConnection) Shutdown(err error) {
+	conn.queryChan <- &ConnectionInteraction{
+		Interaction: Interaction{code: CShutdown},
+	    payload:     err}
 }
 
 // Async
@@ -161,10 +161,11 @@ func (conn *LocalConnection) SendTCP(msg []byte) {
 func (conn *LocalConnection) queryLoop(queryChan <-chan *ConnectionInteraction, acceptNewPeer bool) {
 	err := conn.handshake(acceptNewPeer)
 	if err != nil {
-		log.Printf("->[%s] encountered error during handshake: %v\n", conn.remoteTCPAddr, err)
+		log.Printf("->[%s] connection shutting down due to error during handshake: %v\n", conn.remoteTCPAddr, err)
 		conn.handleShutdown()
 		return
 	}
+	log.Printf("->[%s] completed handshake with %s\n", conn.remoteTCPAddr, conn.remote.Name)
 	conn.Router.Ourself.AddConnection(conn)
 	if conn.remoteUDPAddr != nil {
 		if err = conn.ensureForwarders(); err == nil {
@@ -173,11 +174,7 @@ func (conn *LocalConnection) queryLoop(queryChan <-chan *ConnectionInteraction,
 		}
 	}
 	terminate := false
-	for !terminate {
-		if err != nil {
-			conn.log("error:", err)
-			break
-		}
+	for !terminate && err == nil {
 		select {
 		case query, ok := <-queryChan:
 			if !ok {
@@ -185,6 +182,7 @@ func (conn *LocalConnection) queryLoop(queryChan <-chan *ConnectionInteraction,
 			}
 			switch query.code {
 			case CShutdown:
+				err = query.payload.(error)
 				terminate = true
 			case CSetEstablished:
 				err = conn.handleSetEstablished()
@@ -203,6 +201,13 @@ func (conn *LocalConnection) queryLoop(queryChan <-chan *ConnectionInteraction,
 
 		}
 	}
+	if netErr, ok := err.(net.Error); ok && netErr.Timeout() && !conn.established {
+		conn.log("connection shutting down due to timeout; possibly caused by blocked UDP connectivity")
+	} else if err != nil {
+		conn.log("connection shutting down due to error:", err)
+	} else {
+		conn.log("connection shutting down")
+	}
 	conn.handleShutdown()
 }
 
@@ -258,10 +263,6 @@ func (conn *LocalConnection) handleSendTCP(msg []byte) error {
 }
 
 func (conn *LocalConnection) handleShutdown() {
-	if conn.remote != nil {
-		conn.log("connection shutting down")
-	}
-
 	// Whilst some of these elements may have been written to whilst
 	// holding locks, they were only written to by the connection
 	// actor process. handleShutdown is only called by the connection

router/connection_maker.go

@@ -198,9 +198,9 @@ func (cm *ConnectionMaker) status() string {
 }
 
 func (cm *ConnectionMaker) attemptConnection(address string, acceptNewPeer bool) {
-	log.Println("Attempting connection to", address)
+	log.Printf("->[%s] attempting connection\n", address)
 	if err := cm.ourself.CreateConnection(address, acceptNewPeer); err != nil {
-		log.Println(err)
+		log.Printf("->[%s] error during connection attempt: %v\n", address, err)
 		cm.ConnectionTerminated(address)
 	}
 }

router/local_peer.go

@@ -210,6 +210,7 @@ func (peer *LocalPeer) handleAddConnection(conn *LocalConnection) {
 	peer.Lock()
 	peer.connections[toName] = conn
 	peer.Unlock()
+	conn.log("connection added")
 }
 
 func (peer *LocalPeer) handleDeleteConnection(conn *LocalConnection) {
@@ -226,6 +227,7 @@ func (peer *LocalPeer) handleDeleteConnection(conn *LocalConnection) {
 	peer.Lock()
 	delete(peer.connections, toName)
 	peer.Unlock()
+	conn.log("connection deleted")
 	broadcast := false
 	if conn.Established() {
 		peer.Lock()
@@ -252,7 +254,7 @@ func (peer *LocalPeer) handleConnectionEstablished(conn *LocalConnection) {
 	peer.Lock()
 	peer.version += 1
 	peer.Unlock()
-	log.Println("Peer", peer.Name, "established active connection to remote peer", conn.Remote().Name, "at", conn.RemoteTCPAddr())
+	conn.log("connection fully established")
 	peer.broadcastPeerUpdate(conn.Remote())
 }
 

router/router.go

@@ -156,7 +156,9 @@ func (router *Router) acceptTCP(tcpConn *net.TCPConn) {
 	// someone else is dialing us, so our udp sender is the conn
 	// on Port and we wait for them to send us something on UDP to
 	// start.
-	connRemote := NewRemoteConnection(router.Ourself.Peer, nil, tcpConn.RemoteAddr().String())
+	remoteAddrStr := tcpConn.RemoteAddr().String()
+	log.Printf("->[%s] connection accepted\n", remoteAddrStr)
+	connRemote := NewRemoteConnection(router.Ourself.Peer, nil, remoteAddrStr)
 	NewLocalConnection(connRemote, true, tcpConn, nil, router)
 }
 

router/types.go

@@ -30,7 +30,7 @@ type Connection interface {
 	Remote() *Peer
 	RemoteTCPAddr() string
 	Established() bool
-	Shutdown()
+	Shutdown(error)
 }
 
 type RemoteConnection struct {