From ceccd394200b9152f4df57e5bbe7d7e9002b8704 Mon Sep 17 00:00:00 2001 From: Mathias Hall-Andersen Date: Sun, 4 Feb 2018 19:18:44 +0100 Subject: [PATCH] Work on logging format --- device.go | 1 - peer.go | 12 ++++++++++-- receive.go | 16 +++++++++------- send.go | 14 +++++++++----- signal.go | 8 +++++++- timer.go | 6 ++---- timers.go | 26 ++++++++++++++------------ 7 files changed, 51 insertions(+), 32 deletions(-) diff --git a/device.go b/device.go index 22e0990..e288ebe 100644 --- a/device.go +++ b/device.go @@ -339,7 +339,6 @@ func (device *Device) RemoveAllPeers() { defer device.peers.mutex.Unlock() for key, peer := range device.peers.keyMap { - println("rm", peer.String()) unsafeRemovePeer(device, peer, key) } diff --git a/peer.go b/peer.go index d8bb2bf..1170720 100644 --- a/peer.go +++ b/peer.go @@ -200,7 +200,8 @@ func (peer *Peer) Start() { return } - peer.device.log.Debug.Println("Starting:", peer.String()) + device := peer.device + device.log.Debug.Println(peer.String(), ": Starting...") // sanity check : these should be 0 @@ -247,7 +248,7 @@ func (peer *Peer) Stop() { } device := peer.device - device.log.Debug.Println("Stopping:", peer.String()) + device.log.Debug.Println(peer.String(), ": Stopping...") // stop & wait for ongoing peer routines @@ -270,6 +271,13 @@ func (peer *Peer) Stop() { close(peer.queue.outbound) close(peer.queue.inbound) + // close signals + + peer.signal.newKeyPair.Close() + peer.signal.handshakeBegin.Close() + peer.signal.handshakeCompleted.Close() + peer.signal.flushNonceQueue.Close() + // clear key pairs kp := &peer.keyPairs diff --git a/receive.go b/receive.go index 1f44df2..fbaf77d 100644 --- a/receive.go +++ b/receive.go @@ -430,7 +430,7 @@ func (device *Device) RoutineHandshake() { peer.TimerEphemeralKeyCreated() peer.NewKeyPair() - logDebug.Println("Creating response message for", peer.String()) + logDebug.Println(peer.String(), "Creating handshake response") writer := bytes.NewBuffer(temp[:0]) binary.Write(writer, binary.LittleEndian, response) @@ -443,7 +443,7 @@ func (device *Device) RoutineHandshake() { if err == nil { peer.TimerAnyAuthenticatedPacketTraversal() } else { - logError.Println("Failed to send response to:", peer.String(), err) + logError.Println(peer.String(), "Failed to send handshake response", err) } case MessageResponseType: @@ -495,14 +495,17 @@ func (device *Device) RoutineHandshake() { func (peer *Peer) RoutineSequentialReceiver() { - defer peer.routines.stopping.Done() - device := peer.device - logInfo := device.log.Info logError := device.log.Error logDebug := device.log.Debug - logDebug.Println("Routine, sequential receiver, started for peer", peer.String()) + + func() { + defer peer.routines.stopping.Done() + logDebug.Println(peer.String(), ": Routine, Sequential Receiver, Stopped") + }() + + logDebug.Println(peer.String(), ": Routine, Sequential Receiver, Started") peer.routines.starting.Done() @@ -511,7 +514,6 @@ func (peer *Peer) RoutineSequentialReceiver() { select { case <-peer.routines.stop.Wait(): - logDebug.Println("Routine, sequential receiver, stopped for peer", peer.String()) return case elem := <-peer.queue.inbound: diff --git a/send.go b/send.go index 7488d3a..5a59f6e 100644 --- a/send.go +++ b/send.go @@ -187,13 +187,16 @@ func (device *Device) RoutineReadFromTUN() { func (peer *Peer) RoutineNonce() { var keyPair *KeyPair - defer peer.routines.stopping.Done() - device := peer.device logDebug := device.log.Debug - logDebug.Println("Routine, nonce worker, started for peer", peer.String()) + + defer func() { + peer.routines.stopping.Done() + logDebug.Println(peer.String(), ": Routine, Nonce Worker, Stopped") + }() peer.routines.starting.Done() + logDebug.Println(peer.String(), ": Routine, Nonce Worker, Started") for { NextPacket: @@ -215,12 +218,13 @@ func (peer *Peer) RoutineNonce() { peer.signal.handshakeBegin.Send() - logDebug.Println("Awaiting key-pair for", peer.String()) + logDebug.Println(peer.String(), ": Awaiting key-pair") select { case <-peer.signal.newKeyPair.Wait(): + logDebug.Println(peer.String(), ": Obtained awaited key-pair") case <-peer.signal.flushNonceQueue.Wait(): - logDebug.Println("Clearing queue for", peer.String()) + logDebug.Println(peer.String(), ": Flushing nonce queue") peer.FlushNonceQueue() goto NextPacket case <-peer.routines.stop.Wait(): diff --git a/signal.go b/signal.go index 2cefad4..1505593 100644 --- a/signal.go +++ b/signal.go @@ -11,6 +11,10 @@ func NewSignal() (s Signal) { return } +func (s *Signal) Close() { + close(s.C) +} + func (s *Signal) Disable() { s.enabled.Set(false) s.Clear() @@ -43,7 +47,9 @@ func (s Signal) Clear() { /* Unblocks all listeners (forever) */ func (s Signal) Broadcast() { - close(s.C) + if s.enabled.Get() { + close(s.C) + } } /* Wait for the signal diff --git a/timer.go b/timer.go index f00ca49..6cac40d 100644 --- a/timer.go +++ b/timer.go @@ -12,8 +12,7 @@ type Timer struct { /* Starts the timer if not already pending */ func (t *Timer) Start(dur time.Duration) bool { - set := t.pending.Swap(true) - if !set { + if !t.pending.Swap(true) { t.timer.Reset(dur) return true } @@ -23,8 +22,7 @@ func (t *Timer) Start(dur time.Duration) bool { /* Stops the timer */ func (t *Timer) Stop() { - set := t.pending.Swap(true) - if set { + if t.pending.Swap(true) { t.timer.Stop() select { case <-t.timer.C: diff --git a/timers.go b/timers.go index 7092688..798d629 100644 --- a/timers.go +++ b/timers.go @@ -227,14 +227,14 @@ func (peer *Peer) RoutineTimerHandler() { interval := atomic.LoadUint64(&peer.persistentKeepaliveInterval) if interval > 0 { - logDebug.Println("Sending keep-alive to", peer.String()) + logDebug.Println(peer.String(), ": Send keep-alive (persistent)") peer.timer.keepalivePassive.Stop() peer.SendKeepAlive() } case <-peer.timer.keepalivePassive.Wait(): - logDebug.Println("Sending keep-alive to", peer.String()) + logDebug.Println(peer.String(), ": Send keep-alive (passive)") peer.SendKeepAlive() @@ -247,7 +247,7 @@ func (peer *Peer) RoutineTimerHandler() { case <-peer.timer.zeroAllKeys.Wait(): - logDebug.Println("Clearing all key material for", peer.String()) + logDebug.Println(peer.String(), ": Clear all key-material (timer event)") hs := &peer.handshake hs.mutex.Lock() @@ -280,7 +280,7 @@ func (peer *Peer) RoutineTimerHandler() { // handshake timers case <-peer.timer.handshakeNew.Wait(): - logInfo.Println("Retrying handshake with", peer.String()) + logInfo.Println(peer.String(), ": Retrying handshake (timer event)") peer.signal.handshakeBegin.Send() case <-peer.timer.handshakeTimeout.Wait(): @@ -296,17 +296,18 @@ func (peer *Peer) RoutineTimerHandler() { // send new handshake err := peer.sendNewHandshake() + if err != nil { - logInfo.Println( - "Failed to send handshake to peer:", peer.String(), "(", err, ")") + logInfo.Println(peer.String(), ": Failed to send handshake initiation", err) + } else { + logDebug.Println(peer.String(), ": Send handshake initiation (subsequent)") } case <-peer.timer.handshakeDeadline.Wait(): // clear all queued packets and stop keep-alive - logInfo.Println( - "Handshake negotiation timed out for:", peer.String()) + logInfo.Println(peer.String(), ": Handshake negotiation timed-out") peer.signal.flushNonceQueue.Send() peer.timer.keepalivePersistent.Stop() @@ -319,17 +320,18 @@ func (peer *Peer) RoutineTimerHandler() { peer.signal.handshakeBegin.Disable() err := peer.sendNewHandshake() + if err != nil { - logInfo.Println( - "Failed to send handshake to peer:", peer.String(), "(", err, ")") + logInfo.Println(peer.String(), ": Failed to send handshake initiation", err) + } else { + logDebug.Println(peer.String(), ": Send handshake initiation (initial)") } peer.timer.handshakeDeadline.Reset(RekeyAttemptTime) case <-peer.signal.handshakeCompleted.Wait(): - logInfo.Println( - "Handshake completed for:", peer.String()) + logInfo.Println(peer.String(), ": Handshake completed") atomic.StoreInt64( &peer.stats.lastHandshakeNano,