device: change logging interface to use functions

This commit overhauls wireguard-go's logging.

The primary, motivating change is to use a function instead
of a *log.Logger as the basic unit of logging.
Using functions provides a lot more flexibility for
people to bring their own logging system.

It also introduces logging helper methods on Device.
These reduce line noise at the call site.
They also allow for log functions to be nil;
when nil, instead of generating a log line and throwing it away,
we don't bother generating it at all.
This spares allocation and pointless work.

This is a breaking change, although the fix required
of clients is fairly straightforward.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>

1 files changed, 23 insertions, 34 deletions

diff --git a/device/send.go b/device/send.go
index 1d27799..8cf985d 100644
--- a/device/send.go
+++ b/device/send.go
@@ -99,7 +99,7 @@ func (peer *Peer) SendKeepalive() bool {
 	elem.packet = nil
 	select {
 	case peer.queue.nonce <- elem:
-		peer.device.log.Debug.Println(peer, "- Sending keepalive packet")
+		peer.device.debugf("%v - Sending keepalive packet", peer)
 		return true
 	default:
 		peer.device.PutMessageBuffer(elem.buffer)
@@ -128,11 +128,11 @@ func (peer *Peer) SendHandshakeInitiation(isRetry bool) error {
 	peer.handshake.lastSentHandshake = time.Now()
 	peer.handshake.mutex.Unlock()
 
-	peer.device.log.Debug.Println(peer, "- Sending handshake initiation")
+	peer.device.debugf("%v - Sending handshake initiation", peer)
 
 	msg, err := peer.device.CreateMessageInitiation(peer)
 	if err != nil {
-		peer.device.log.Error.Println(peer, "- Failed to create initiation message:", err)
+		peer.device.errorf("%v - Failed to create initiation message: %v", peer, err)
 		return err
 	}
 
@@ -147,7 +147,7 @@ func (peer *Peer) SendHandshakeInitiation(isRetry bool) error {
 
 	err = peer.SendBuffer(packet)
 	if err != nil {
-		peer.device.log.Error.Println(peer, "- Failed to send handshake initiation:", err)
+		peer.device.errorf("%v - Failed to send handshake initiation: %v", peer, err)
 	}
 	peer.timersHandshakeInitiated()
 
@@ -159,11 +159,11 @@ func (peer *Peer) SendHandshakeResponse() error {
 	peer.handshake.lastSentHandshake = time.Now()
 	peer.handshake.mutex.Unlock()
 
-	peer.device.log.Debug.Println(peer, "- Sending handshake response")
+	peer.device.debugf("%v - Sending handshake response", peer)
 
 	response, err := peer.device.CreateMessageResponse(peer)
 	if err != nil {
-		peer.device.log.Error.Println(peer, "- Failed to create response message:", err)
+		peer.device.errorf("%v - Failed to create response message: %v", peer, err)
 		return err
 	}
 
@@ -175,7 +175,7 @@ func (peer *Peer) SendHandshakeResponse() error {
 
 	err = peer.BeginSymmetricSession()
 	if err != nil {
-		peer.device.log.Error.Println(peer, "- Failed to derive keypair:", err)
+		peer.device.errorf("%v - Failed to derive keypair: %v", peer, err)
 		return err
 	}
 
@@ -185,19 +185,19 @@ func (peer *Peer) SendHandshakeResponse() error {
 
 	err = peer.SendBuffer(packet)
 	if err != nil {
-		peer.device.log.Error.Println(peer, "- Failed to send handshake response:", err)
+		peer.device.errorf("%v - Failed to send handshake response: %v", peer, err)
 	}
 	return err
 }
 
 func (device *Device) SendHandshakeCookie(initiatingElem *QueueHandshakeElement) error {
 
-	device.log.Debug.Println("Sending cookie response for denied handshake message for", initiatingElem.endpoint.DstToString())
+	device.debugf("Sending cookie response for denied handshake message for %v", initiatingElem.endpoint.DstToString())
 
 	sender := binary.LittleEndian.Uint32(initiatingElem.packet[4:8])
 	reply, err := device.cookieChecker.CreateReply(initiatingElem.packet, sender, initiatingElem.endpoint.DstToBytes())
 	if err != nil {
-		device.log.Error.Println("Failed to create cookie reply:", err)
+		device.errorf("Failed to create cookie reply: %v", err)
 		return err
 	}
 
@@ -225,16 +225,12 @@ func (peer *Peer) keepKeyFreshSending() {
  * Obs. Single instance per TUN device
  */
 func (device *Device) RoutineReadFromTUN() {
-
-	logDebug := device.log.Debug
-	logError := device.log.Error
-
 	defer func() {
-		logDebug.Println("Routine: TUN reader - stopped")
+		device.debugf("Routine: TUN reader - stopped")
 		device.state.stopping.Done()
 	}()
 
-	logDebug.Println("Routine: TUN reader - started")
+	device.debugf("Routine: TUN reader - started")
 
 	var elem *QueueOutboundElement
 
@@ -252,7 +248,7 @@ func (device *Device) RoutineReadFromTUN() {
 
 		if err != nil {
 			if !device.isClosed.Get() {
-				logError.Println("Failed to read packet from TUN device:", err)
+				device.errorf("Failed to read packet from TUN device: %v", err)
 				device.Close()
 			}
 			device.PutMessageBuffer(elem.buffer)
@@ -285,7 +281,7 @@ func (device *Device) RoutineReadFromTUN() {
 			peer = device.allowedips.LookupIPv6(dst)
 
 		default:
-			logDebug.Println("Received packet with unknown IP version")
+			device.debugf("Received packet with unknown IP version")
 		}
 
 		if peer == nil {
@@ -321,9 +317,7 @@ func (peer *Peer) FlushNonceQueue() {
  */
 func (peer *Peer) RoutineNonce() {
 	var keypair *Keypair
-
 	device := peer.device
-	logDebug := device.log.Debug
 
 	flush := func() {
 		for {
@@ -339,14 +333,14 @@ func (peer *Peer) RoutineNonce() {
 
 	defer func() {
 		flush()
-		logDebug.Println(peer, "- Routine: nonce worker - stopped")
+		device.debugf("%v - Routine: nonce worker - stopped", peer)
 		peer.queue.packetInNonceQueueIsAwaitingKey.Set(false)
 		device.queue.encryption.wg.Done() // no more writes from us
 		close(peer.queue.outbound)        // no more writes to this channel
 		peer.routines.stopping.Done()
 	}()
 
-	logDebug.Println(peer, "- Routine: nonce worker - started")
+	device.debugf("%v - Routine: nonce worker - started", peer)
 
 NextPacket:
 	for {
@@ -391,11 +385,11 @@ NextPacket:
 
 				// wait for key to be established
 
-				logDebug.Println(peer, "- Awaiting keypair")
+				device.debugf("%v - Awaiting keypair", peer)
 
 				select {
 				case <-peer.signals.newKeypairArrived:
-					logDebug.Println(peer, "- Obtained awaited keypair")
+					device.debugf("%v - Obtained awaited keypair", peer)
 
 				case <-peer.signals.flushNonceQueue:
 					device.PutMessageBuffer(elem.buffer)
@@ -459,10 +453,8 @@ func (device *Device) RoutineEncryption() {
 
 	var nonce [chacha20poly1305.NonceSize]byte
 
-	logDebug := device.log.Debug
-
-	defer logDebug.Println("Routine: encryption worker - stopped")
-	logDebug.Println("Routine: encryption worker - started")
+	defer device.debugf("Routine: encryption worker - stopped")
+	device.debugf("Routine: encryption worker - started")
 
 	for elem := range device.queue.encryption.c {
 		// populate header fields
@@ -505,11 +497,8 @@ func (peer *Peer) RoutineSequentialSender() {
 
 	device := peer.device
 
-	logDebug := device.log.Debug
-	logError := device.log.Error
-
-	defer logDebug.Println(peer, "- Routine: sequential sender - stopped")
-	logDebug.Println(peer, "- Routine: sequential sender - started")
+	defer device.debugf("%v - Routine: sequential sender - stopped", peer)
+	device.debugf("%v - Routine: sequential sender - started", peer)
 
 	for elem := range peer.queue.outbound {
 		elem.Lock()
@@ -537,7 +526,7 @@ func (peer *Peer) RoutineSequentialSender() {
 		device.PutMessageBuffer(elem.buffer)
 		device.PutOutboundElement(elem)
 		if err != nil {
-			logError.Println(peer, "- Failed to send data packet", err)
+			device.errorf("%v - Failed to send data packet: %v", peer, err)
 			continue
 		}