improve connection logging

1) log more lifecycle events
  - acceptance
  - handshake completion
  - added & removed (from our connection map)
The latter is a bit verbose but may help us track down the cause for
going to introduce here, then this would fall in the 'debug' category.

2) better error logging
  - log error as part of "shutting down" log event rather than separately
  - indicate "blocked UDP connectivity" as a possible cause when
    getting a timeout on a not-fully-established connection.
The rationale for the latter is that inbound connections get
marked as established when first receiving a heartbeat frame over
UDP, which are the only frames that get transmitted prior to the
connection being fully established. Note that outbound
connections get marked as established when receiving the
ConnectionEstablished message over TCP, which is sent by the peer
when it first receives a heartbeat. See #342.

Closes #340.

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/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", 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 {