From 1235441556e3049941f646a7a87d898e3e72b388 Mon Sep 17 00:00:00 2001 From: Matthias Radestock Date: Tue, 13 Jan 2015 15:47:23 +0000 Subject: [PATCH 1/3] 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 | 35 ++++++++++++++++++----------------- router/local_peer.go | 4 +++- router/router.go | 4 +++- router/types.go | 2 +- 4 files changed, 25 insertions(+), 20 deletions(-) diff --git a/router/connection.go b/router/connection.go index 6a9564c2..68c1ae2b 100644 --- a/router/connection.go +++ b/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 diff --git a/router/local_peer.go b/router/local_peer.go index b4b27239..5bebd85c 100644 --- a/router/local_peer.go +++ b/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()) } diff --git a/router/router.go b/router/router.go index f9736641..3b240076 100644 --- a/router/router.go +++ b/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) } diff --git a/router/types.go b/router/types.go index 616e364b..850767ac 100644 --- a/router/types.go +++ b/router/types.go @@ -30,7 +30,7 @@ type Connection interface { Remote() *Peer RemoteTCPAddr() string Established() bool - Shutdown() + Shutdown(error) } type RemoteConnection struct { From cc8fad47dd829227acf81a509ad7ca9198bfcb80 Mon Sep 17 00:00:00 2001 From: Matthias Radestock Date: Tue, 13 Jan 2015 16:30:13 +0000 Subject: [PATCH 2/3] more connection logging consistency --- router/connection_maker.go | 4 ++-- router/router.go | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/router/connection_maker.go b/router/connection_maker.go index 9564a61c..00ea25f2 100644 --- a/router/connection_maker.go +++ b/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", err) cm.ConnectionTerminated(address) } } diff --git a/router/router.go b/router/router.go index 3b240076..a8b833d3 100644 --- a/router/router.go +++ b/router/router.go @@ -157,7 +157,7 @@ func (router *Router) acceptTCP(tcpConn *net.TCPConn) { // on Port and we wait for them to send us something on UDP to // start. remoteAddrStr := tcpConn.RemoteAddr().String() - log.Printf("->[%s] connection accepted", remoteAddrStr) + log.Printf("->[%s] connection accepted\n", remoteAddrStr) connRemote := NewRemoteConnection(router.Ourself.Peer, nil, remoteAddrStr) NewLocalConnection(connRemote, true, tcpConn, nil, router) } From 0befe997c13a47d6be267e181d61f175df7c8cac Mon Sep 17 00:00:00 2001 From: Matthias Radestock Date: Tue, 13 Jan 2015 16:38:58 +0000 Subject: [PATCH 3/3] oops --- router/connection_maker.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/router/connection_maker.go b/router/connection_maker.go index 00ea25f2..191d7dae 100644 --- a/router/connection_maker.go +++ b/router/connection_maker.go @@ -200,7 +200,7 @@ func (cm *ConnectionMaker) status() string { func (cm *ConnectionMaker) attemptConnection(address string, acceptNewPeer bool) { log.Printf("->[%s] attempting connection\n", address) if err := cm.ourself.CreateConnection(address, acceptNewPeer); err != nil { - log.Printf("->[%s] error during connection attempt: %v\n", err) + log.Printf("->[%s] error during connection attempt: %v\n", address, err) cm.ConnectionTerminated(address) } }