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>

diff --git a/device/device.go b/device/device.go
index 5d11766601e60662321fd6c0012ede31ab2fc735..27c42f2cc018dc1f2b111001b29643a3f88f8b67 100644 (file)
--- a/device/device.go
+++ b/device/device.go
@@ -177,7 +177,7 @@ func deviceUpdateState(device *Device) {
        switch newIsUp {
        case true:
                if err := device.BindUpdate(); err != nil {
-                       device.log.Error.Println("Unable to update bind:", err)
+                       device.errorf("Unable to update bind: %v", err)
                        device.isUp.Set(false)
                        break
                }
@@ -303,7 +303,7 @@ func NewDevice(tunDevice tun.Device, logger *Logger) *Device {
        device.tun.device = tunDevice
        mtu, err := device.tun.device.MTU()
        if err != nil {
-               logger.Error.Println("Trouble determining MTU, assuming default:", err)
+               device.errorf("Trouble determining MTU, assuming default: %v", err)
                mtu = DefaultMTU
        }
        device.tun.mtu = int32(mtu)
@@ -397,7 +397,7 @@ func (device *Device) Close() {
                return
        }
 
-       device.log.Info.Println("Device closing")
+       device.infof("Device closing")
        device.state.changing.Set(true)
        device.state.Lock()
        defer device.state.Unlock()
@@ -422,7 +422,7 @@ func (device *Device) Close() {
        device.rate.limiter.Close()
 
        device.state.changing.Set(false)
-       device.log.Info.Println("Interface closed")
+       device.infof("Interface closed")
 }
 
 func (device *Device) Wait() chan struct{} {
@@ -562,7 +562,7 @@ func (device *Device) BindUpdate() error {
                go device.RoutineReceiveIncoming(ipv4.Version, netc.bind)
                go device.RoutineReceiveIncoming(ipv6.Version, netc.bind)
 
-               device.log.Debug.Println("UDP bind has been updated")
+               device.debugf("UDP bind has been updated")
        }
 
        return nil

diff --git a/device/logger.go b/device/logger.go
index 3c4d7445d1b2ac129937abfc22cea5af907d734b..6869a2433970604474159a801eef3088c95f3fdc 100644 (file)
--- a/device/logger.go
+++ b/device/logger.go
@@ -6,12 +6,22 @@
 package device
 
 import (
-       "io"
-       "io/ioutil"
        "log"
        "os"
 )
 
+// A Logger provides logging for a Device.
+// The functions are Printf-style functions.
+// They must be safe for concurrent use.
+// They do not require a trailing newline in the format.
+// If nil, that level of logging will be silent.
+type Logger struct {
+       Debugf func(format string, args ...interface{})
+       Infof  func(format string, args ...interface{})
+       Errorf func(format string, args ...interface{})
+}
+
+// Log levels for use with NewLogger.
 const (
        LogLevelSilent = iota
        LogLevelError
@@ -19,41 +29,40 @@ const (
        LogLevelDebug
 )
 
-type Logger struct {
-       Debug *log.Logger
-       Info  *log.Logger
-       Error *log.Logger
-}
-
+// NewLogger constructs a Logger that writes to stdout.
+// It logs at the specified log level and above.
+// It decorates log lines with the log level, date, time, and prepend.
 func NewLogger(level int, prepend string) *Logger {
-       output := os.Stdout
        logger := new(Logger)
-
-       logErr, logInfo, logDebug := func() (io.Writer, io.Writer, io.Writer) {
-               if level >= LogLevelDebug {
-                       return output, output, output
-               }
-               if level >= LogLevelInfo {
-                       return output, output, ioutil.Discard
-               }
-               if level >= LogLevelError {
-                       return output, ioutil.Discard, ioutil.Discard
-               }
-               return ioutil.Discard, ioutil.Discard, ioutil.Discard
-       }()
-
-       logger.Debug = log.New(logDebug,
-               "DEBUG: "+prepend,
-               log.Ldate|log.Ltime,
-       )
-
-       logger.Info = log.New(logInfo,
-               "INFO: "+prepend,
-               log.Ldate|log.Ltime,
-       )
-       logger.Error = log.New(logErr,
-               "ERROR: "+prepend,
-               log.Ldate|log.Ltime,
-       )
+       logf := func(prefix string) func(string, ...interface{}) {
+               return log.New(os.Stdout, prefix+": "+prepend, log.Ldate|log.Ltime).Printf
+       }
+       if level >= LogLevelDebug {
+               logger.Debugf = logf("DEBUG")
+       }
+       if level >= LogLevelInfo {
+               logger.Infof = logf("INFO")
+       }
+       if level >= LogLevelError {
+               logger.Errorf = logf("ERROR")
+       }
        return logger
 }
+
+func (device *Device) debugf(format string, args ...interface{}) {
+       if device.log.Debugf != nil {
+               device.log.Debugf(format, args...)
+       }
+}
+
+func (device *Device) infof(format string, args ...interface{}) {
+       if device.log.Infof != nil {
+               device.log.Infof(format, args...)
+       }
+}
+
+func (device *Device) errorf(format string, args ...interface{}) {
+       if device.log.Errorf != nil {
+               device.log.Errorf(format, args...)
+       }
+}

diff --git a/device/noise-protocol.go b/device/noise-protocol.go
index e34da8348d62f54f6fda855d7452b4870667e74e..df520d016e1f51de3e3380578db4631d4d27a758 100644 (file)
--- a/device/noise-protocol.go
+++ b/device/noise-protocol.go
@@ -319,11 +319,11 @@ func (device *Device) ConsumeMessageInitiation(msg *MessageInitiation) *Peer {
        flood := time.Since(handshake.lastInitiationConsumption) <= HandshakeInitationRate
        handshake.mutex.RUnlock()
        if replay {
-               device.log.Debug.Printf("%v - ConsumeMessageInitiation: handshake replay @ %v\n", peer, timestamp)
+               device.debugf("%v - ConsumeMessageInitiation: handshake replay @ %v", peer, timestamp)
                return nil
        }
        if flood {
-               device.log.Debug.Printf("%v - ConsumeMessageInitiation: handshake flood\n", peer)
+               device.debugf("%v - ConsumeMessageInitiation: handshake flood", peer)
                return nil
        }
 

diff --git a/device/peer.go b/device/peer.go
index 96040e6b6bc90243ebff66af643af0e6d78f78fd..46edaeb8e3745f780cfaeb82ba055c48c49e87e3 100644 (file)
--- a/device/peer.go
+++ b/device/peer.go
@@ -190,7 +190,7 @@ func (peer *Peer) Start() {
        }
 
        device := peer.device
-       device.log.Debug.Println(peer, "- Starting...")
+       device.debugf("%v - Starting...", peer)
 
        // reset routine state
 
@@ -278,7 +278,7 @@ func (peer *Peer) Stop() {
        peer.routines.Lock()
        defer peer.routines.Unlock()
 
-       peer.device.log.Debug.Println(peer, "- Stopping...")
+       peer.device.debugf("%v - Stopping...", peer)
 
        peer.timersStop()
 

diff --git a/device/receive.go b/device/receive.go
index 605303e6352d40b5af57529bfbe1a74f37eaf44c..38d018c022d3c3d50c9ab575b811c60d00f7e3bb 100644 (file)
--- a/device/receive.go
+++ b/device/receive.go
@@ -10,7 +10,6 @@ import (
        "encoding/binary"
        "errors"
        "net"
-       "strconv"
        "sync"
        "sync/atomic"
        "time"
@@ -79,15 +78,13 @@ func (peer *Peer) keepKeyFreshReceiving() {
  * IPv4 and IPv6 (separately)
  */
 func (device *Device) RoutineReceiveIncoming(IP int, bind conn.Bind) {
-
-       logDebug := device.log.Debug
        defer func() {
-               logDebug.Println("Routine: receive incoming IPv" + strconv.Itoa(IP) + " - stopped")
+               device.debugf("Routine: receive incoming IPv%d - stopped", IP)
                device.queue.decryption.wg.Done()
                device.net.stopping.Done()
        }()
 
-       logDebug.Println("Routine: receive incoming IPv" + strconv.Itoa(IP) + " - started")
+       device.debugf("Routine: receive incoming IPv%d - started", IP)
 
        // receive datagrams until conn is closed
 
@@ -115,7 +112,7 @@ func (device *Device) RoutineReceiveIncoming(IP int, bind conn.Bind) {
                        if errors.Is(err, conn.NetErrClosed) {
                                return
                        }
-                       device.log.Error.Printf("Failed to receive packet: %v", err)
+                       device.errorf("Failed to receive packet: %v", err)
                        if deathSpiral < 10 {
                                deathSpiral++
                                time.Sleep(time.Second / 3)
@@ -202,7 +199,7 @@ func (device *Device) RoutineReceiveIncoming(IP int, bind conn.Bind) {
                        okay = len(packet) == MessageCookieReplySize
 
                default:
-                       logDebug.Println("Received message with unknown type")
+                       device.debugf("Received message with unknown type")
                }
 
                if okay {
@@ -222,15 +219,12 @@ func (device *Device) RoutineReceiveIncoming(IP int, bind conn.Bind) {
 }
 
 func (device *Device) RoutineDecryption() {
-
        var nonce [chacha20poly1305.NonceSize]byte
-
-       logDebug := device.log.Debug
        defer func() {
-               logDebug.Println("Routine: decryption worker - stopped")
+               device.debugf("Routine: decryption worker - stopped")
                device.state.stopping.Done()
        }()
-       logDebug.Println("Routine: decryption worker - started")
+       device.debugf("Routine: decryption worker - started")
 
        for elem := range device.queue.decryption.c {
                // split message into fields
@@ -258,23 +252,18 @@ func (device *Device) RoutineDecryption() {
 /* Handles incoming packets related to handshake
  */
 func (device *Device) RoutineHandshake() {
-
-       logInfo := device.log.Info
-       logError := device.log.Error
-       logDebug := device.log.Debug
-
        var elem QueueHandshakeElement
        var ok bool
 
        defer func() {
-               logDebug.Println("Routine: handshake worker - stopped")
+               device.debugf("Routine: handshake worker - stopped")
                device.state.stopping.Done()
                if elem.buffer != nil {
                        device.PutMessageBuffer(elem.buffer)
                }
        }()
 
-       logDebug.Println("Routine: handshake worker - started")
+       device.debugf("Routine: handshake worker - started")
 
        for {
                if elem.buffer != nil {
@@ -304,7 +293,7 @@ func (device *Device) RoutineHandshake() {
                        reader := bytes.NewReader(elem.packet)
                        err := binary.Read(reader, binary.LittleEndian, &reply)
                        if err != nil {
-                               logDebug.Println("Failed to decode cookie reply")
+                               device.debugf("Failed to decode cookie reply")
                                return
                        }
 
@@ -319,9 +308,9 @@ func (device *Device) RoutineHandshake() {
                        // consume reply
 
                        if peer := entry.peer; peer.isRunning.Get() {
-                               logDebug.Println("Receiving cookie response from ", elem.endpoint.DstToString())
+                               device.debugf("Receiving cookie response from %s", elem.endpoint.DstToString())
                                if !peer.cookieGenerator.ConsumeReply(&reply) {
-                                       logDebug.Println("Could not decrypt invalid cookie response")
+                                       device.debugf("Could not decrypt invalid cookie response")
                                }
                        }
 
@@ -332,7 +321,7 @@ func (device *Device) RoutineHandshake() {
                        // check mac fields and maybe ratelimit
 
                        if !device.cookieChecker.CheckMAC1(elem.packet) {
-                               logDebug.Println("Received packet with invalid mac1")
+                               device.debugf("Received packet with invalid mac1")
                                continue
                        }
 
@@ -355,7 +344,7 @@ func (device *Device) RoutineHandshake() {
                        }
 
                default:
-                       logError.Println("Invalid packet ended up in the handshake queue")
+                       device.errorf("Invalid packet ended up in the handshake queue")
                        continue
                }
 
@@ -370,7 +359,7 @@ func (device *Device) RoutineHandshake() {
                        reader := bytes.NewReader(elem.packet)
                        err := binary.Read(reader, binary.LittleEndian, &msg)
                        if err != nil {
-                               logError.Println("Failed to decode initiation message")
+                               device.errorf("Failed to decode initiation message")
                                continue
                        }
 
@@ -378,10 +367,7 @@ func (device *Device) RoutineHandshake() {
 
                        peer := device.ConsumeMessageInitiation(&msg)
                        if peer == nil {
-                               logInfo.Println(
-                                       "Received invalid initiation message from",
-                                       elem.endpoint.DstToString(),
-                               )
+                               device.infof("Received invalid initiation message from %s", elem.endpoint.DstToString())
                                continue
                        }
 
@@ -393,7 +379,7 @@ func (device *Device) RoutineHandshake() {
                        // update endpoint
                        peer.SetEndpointFromPacket(elem.endpoint)
 
-                       logDebug.Println(peer, "- Received handshake initiation")
+                       device.debugf("%v - Received handshake initiation", peer)
                        atomic.AddUint64(&peer.stats.rxBytes, uint64(len(elem.packet)))
 
                        peer.SendHandshakeResponse()
@@ -406,7 +392,7 @@ func (device *Device) RoutineHandshake() {
                        reader := bytes.NewReader(elem.packet)
                        err := binary.Read(reader, binary.LittleEndian, &msg)
                        if err != nil {
-                               logError.Println("Failed to decode response message")
+                               device.errorf("Failed to decode response message")
                                continue
                        }
 
@@ -414,17 +400,14 @@ func (device *Device) RoutineHandshake() {
 
                        peer := device.ConsumeMessageResponse(&msg)
                        if peer == nil {
-                               logInfo.Println(
-                                       "Received invalid response message from",
-                                       elem.endpoint.DstToString(),
-                               )
+                               device.infof("Received invalid response message from %s", elem.endpoint.DstToString())
                                continue
                        }
 
                        // update endpoint
                        peer.SetEndpointFromPacket(elem.endpoint)
 
-                       logDebug.Println(peer, "- Received handshake response")
+                       device.debugf("%v - Received handshake response", peer)
                        atomic.AddUint64(&peer.stats.rxBytes, uint64(len(elem.packet)))
 
                        // update timers
@@ -437,7 +420,7 @@ func (device *Device) RoutineHandshake() {
                        err = peer.BeginSymmetricSession()
 
                        if err != nil {
-                               logError.Println(peer, "- Failed to derive keypair:", err)
+                               device.errorf("%v - Failed to derive keypair: %v", peer, err)
                                continue
                        }
 
@@ -453,16 +436,11 @@ func (device *Device) RoutineHandshake() {
 }
 
 func (peer *Peer) RoutineSequentialReceiver() {
-
        device := peer.device
-       logInfo := device.log.Info
-       logError := device.log.Error
-       logDebug := device.log.Debug
-
        var elem *QueueInboundElement
 
        defer func() {
-               logDebug.Println(peer, "- Routine: sequential receiver - stopped")
+               device.debugf("%v - Routine: sequential receiver - stopped", peer)
                peer.routines.stopping.Done()
                if elem != nil {
                        device.PutMessageBuffer(elem.buffer)
@@ -470,7 +448,7 @@ func (peer *Peer) RoutineSequentialReceiver() {
                }
        }()
 
-       logDebug.Println(peer, "- Routine: sequential receiver - started")
+       device.debugf("%v - Routine: sequential receiver - started", peer)
 
        for {
                if elem != nil {
@@ -521,7 +499,7 @@ func (peer *Peer) RoutineSequentialReceiver() {
                // check for keepalive
 
                if len(elem.packet) == 0 {
-                       logDebug.Println(peer, "- Receiving keepalive packet")
+                       device.debugf("%v - Receiving keepalive packet", peer)
                        continue
                }
                peer.timersDataReceived()
@@ -549,10 +527,7 @@ func (peer *Peer) RoutineSequentialReceiver() {
 
                        src := elem.packet[IPv4offsetSrc : IPv4offsetSrc+net.IPv4len]
                        if device.allowedips.LookupIPv4(src) != peer {
-                               logInfo.Println(
-                                       "IPv4 packet with disallowed source address from",
-                                       peer,
-                               )
+                               device.infof("IPv4 packet with disallowed source address from %v", peer)
                                continue
                        }
 
@@ -577,15 +552,12 @@ func (peer *Peer) RoutineSequentialReceiver() {
 
                        src := elem.packet[IPv6offsetSrc : IPv6offsetSrc+net.IPv6len]
                        if device.allowedips.LookupIPv6(src) != peer {
-                               logInfo.Println(
-                                       "IPv6 packet with disallowed source address from",
-                                       peer,
-                               )
+                               device.infof("IPv6 packet with disallowed source address from %v", peer)
                                continue
                        }
 
                default:
-                       logInfo.Println("Packet with invalid IP version from", peer)
+                       device.infof("Packet with invalid IP version from %v", peer)
                        continue
                }
 
@@ -594,12 +566,12 @@ func (peer *Peer) RoutineSequentialReceiver() {
                offset := MessageTransportOffsetContent
                _, err := device.tun.device.Write(elem.buffer[:offset+len(elem.packet)], offset)
                if err != nil && !device.isClosed.Get() {
-                       logError.Println("Failed to write packet to TUN device:", err)
+                       device.errorf("Failed to write packet to TUN device: %v", err)
                }
                if len(peer.queue.inbound) == 0 {
                        err := device.tun.device.Flush()
                        if err != nil {
-                               peer.device.log.Error.Printf("Unable to flush packets: %v", err)
+                               peer.device.errorf("Unable to flush packets: %v", err)
                        }
                }
        }

diff --git a/device/send.go b/device/send.go
index 1d27799bc336e4cfafeed802803000881cc86ff9..8cf985d2703c8bbdb698c6fca2622fec7ecc477d 100644 (file)
--- 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
                }
 

diff --git a/device/timers.go b/device/timers.go
index dbd4c6676999f7e8ff18771cc511e5ddc308acc5..ddc47ad2628a8a993c82fb66ca3d4826b3918167 100644 (file)
--- a/device/timers.go
+++ b/device/timers.go
@@ -78,7 +78,7 @@ func (peer *Peer) timersActive() bool {
 
 func expiredRetransmitHandshake(peer *Peer) {
        if atomic.LoadUint32(&peer.timers.handshakeAttempts) > MaxTimerHandshakes {
-               peer.device.log.Debug.Printf("%s - Handshake did not complete after %d attempts, giving up\n", peer, MaxTimerHandshakes+2)
+               peer.device.debugf("%s - Handshake did not complete after %d attempts, giving up", peer, MaxTimerHandshakes+2)
 
                if peer.timersActive() {
                        peer.timers.sendKeepalive.Del()
@@ -97,7 +97,7 @@ func expiredRetransmitHandshake(peer *Peer) {
                }
        } else {
                atomic.AddUint32(&peer.timers.handshakeAttempts, 1)
-               peer.device.log.Debug.Printf("%s - Handshake did not complete after %d seconds, retrying (try %d)\n", peer, int(RekeyTimeout.Seconds()), atomic.LoadUint32(&peer.timers.handshakeAttempts)+1)
+               peer.device.debugf("%s - Handshake did not complete after %d seconds, retrying (try %d)", peer, int(RekeyTimeout.Seconds()), atomic.LoadUint32(&peer.timers.handshakeAttempts)+1)
 
                /* We clear the endpoint address src address, in case this is the cause of trouble. */
                peer.Lock()
@@ -121,7 +121,7 @@ func expiredSendKeepalive(peer *Peer) {
 }
 
 func expiredNewHandshake(peer *Peer) {
-       peer.device.log.Debug.Printf("%s - Retrying handshake because we stopped hearing back after %d seconds\n", peer, int((KeepaliveTimeout + RekeyTimeout).Seconds()))
+       peer.device.debugf("%s - Retrying handshake because we stopped hearing back after %d seconds", peer, int((KeepaliveTimeout + RekeyTimeout).Seconds()))
        /* We clear the endpoint address src address, in case this is the cause of trouble. */
        peer.Lock()
        if peer.endpoint != nil {
@@ -133,7 +133,7 @@ func expiredNewHandshake(peer *Peer) {
 }
 
 func expiredZeroKeyMaterial(peer *Peer) {
-       peer.device.log.Debug.Printf("%s - Removing all keys, since we haven't received a new one in %d seconds\n", peer, int((RejectAfterTime * 3).Seconds()))
+       peer.device.debugf("%s - Removing all keys, since we haven't received a new one in %d seconds", peer, int((RejectAfterTime * 3).Seconds()))
        peer.ZeroAndFlushAll()
 }
 

diff --git a/device/tun.go b/device/tun.go
index 3816f9b2e44fbb28b5d62778c09061052ba5f483..97f12761f9133277b8c26fc58798d29806f149ca 100644 (file)
--- a/device/tun.go
+++ b/device/tun.go
@@ -15,41 +15,37 @@ const DefaultMTU = 1420
 
 func (device *Device) RoutineTUNEventReader() {
        setUp := false
-       logDebug := device.log.Debug
-       logInfo := device.log.Info
-       logError := device.log.Error
-
-       logDebug.Println("Routine: event worker - started")
+       device.debugf("Routine: event worker - started")
 
        for event := range device.tun.device.Events() {
                if event&tun.EventMTUUpdate != 0 {
                        mtu, err := device.tun.device.MTU()
                        old := atomic.LoadInt32(&device.tun.mtu)
                        if err != nil {
-                               logError.Println("Failed to load updated MTU of device:", err)
+                               device.errorf("Failed to load updated MTU of device: %v", err)
                        } else if int(old) != mtu {
                                if mtu+MessageTransportSize > MaxMessageSize {
-                                       logInfo.Println("MTU updated:", mtu, "(too large)")
+                                       device.infof("MTU updated: %v (too large)", mtu)
                                } else {
-                                       logInfo.Println("MTU updated:", mtu)
+                                       device.infof("MTU updated: %v", mtu)
                                }
                                atomic.StoreInt32(&device.tun.mtu, int32(mtu))
                        }
                }
 
                if event&tun.EventUp != 0 && !setUp {
-                       logInfo.Println("Interface set up")
+                       device.infof("Interface set up")
                        setUp = true
                        device.Up()
                }
 
                if event&tun.EventDown != 0 && setUp {
-                       logInfo.Println("Interface set down")
+                       device.infof("Interface set down")
                        setUp = false
                        device.Down()
                }
        }
 
-       logDebug.Println("Routine: event worker - stopped")
+       device.debugf("Routine: event worker - stopped")
        device.state.stopping.Done()
 }

diff --git a/device/uapi.go b/device/uapi.go
index 277c02f065c40882504b4610bdf527c25e5844f3..76b6fb8262afe24e669956c6206e8ac6f37e66cd 100644 (file)
--- a/device/uapi.go
+++ b/device/uapi.go
@@ -130,7 +130,7 @@ func (device *Device) IpcSetOperation(r io.Reader) (err error) {
 
        defer func() {
                if err != nil {
-                       device.log.Error.Println(err)
+                       device.errorf("%v", err)
                }
        }()
 
@@ -188,7 +188,7 @@ func (device *Device) handleDeviceLine(key, value string) error {
                if err != nil {
                        return ipcErrorf(ipc.IpcErrorInvalid, "failed to set private_key: %w", err)
                }
-               device.log.Debug.Println("UAPI: Updating private key")
+               device.debugf("UAPI: Updating private key")
                device.SetPrivateKey(sk)
 
        case "listen_port":
@@ -198,7 +198,7 @@ func (device *Device) handleDeviceLine(key, value string) error {
                }
 
                // update port and rebind
-               device.log.Debug.Println("UAPI: Updating listen port")
+               device.debugf("UAPI: Updating listen port")
 
                device.net.Lock()
                device.net.port = uint16(port)
@@ -214,7 +214,7 @@ func (device *Device) handleDeviceLine(key, value string) error {
                        return ipcErrorf(ipc.IpcErrorInvalid, "invalid fwmark: %w", err)
                }
 
-               device.log.Debug.Println("UAPI: Updating fwmark")
+               device.debugf("UAPI: Updating fwmark")
                if err := device.BindSetMark(uint32(mark)); err != nil {
                        return ipcErrorf(ipc.IpcErrorPortInUse, "failed to update fwmark: %w", err)
                }
@@ -223,7 +223,7 @@ func (device *Device) handleDeviceLine(key, value string) error {
                if value != "true" {
                        return ipcErrorf(ipc.IpcErrorInvalid, "failed to set replace_peers, invalid value: %v", value)
                }
-               device.log.Debug.Println("UAPI: Removing all peers")
+               device.debugf("UAPI: Removing all peers")
                device.RemoveAllPeers()
 
        default:
@@ -265,7 +265,7 @@ func (device *Device) handlePublicKeyLine(peer *ipcSetPeer, value string) error
                if err != nil {
                        return ipcErrorf(ipc.IpcErrorInvalid, "failed to create new peer: %w", err)
                }
-               device.log.Debug.Println(peer, "- UAPI: Created")
+               device.debugf("%v - UAPI: Created", peer.Peer)
        }
        return nil
 }
@@ -289,14 +289,14 @@ func (device *Device) handlePeerLine(peer *ipcSetPeer, key, value string) error
                        return ipcErrorf(ipc.IpcErrorInvalid, "failed to set remove, invalid value: %v", value)
                }
                if !peer.dummy {
-                       device.log.Debug.Println(peer, "- UAPI: Removing")
+                       device.debugf("%v - UAPI: Removing", peer.Peer)
                        device.RemovePeer(peer.handshake.remoteStatic)
                }
                peer.Peer = &Peer{}
                peer.dummy = true
 
        case "preshared_key":
-               device.log.Debug.Println(peer, "- UAPI: Updating preshared key")
+               device.debugf("%v - UAPI: Updating preshared key", peer.Peer)
 
                peer.handshake.mutex.Lock()
                err := peer.handshake.presharedKey.FromHex(value)
@@ -307,7 +307,7 @@ func (device *Device) handlePeerLine(peer *ipcSetPeer, key, value string) error
                }
 
        case "endpoint":
-               device.log.Debug.Println(peer, "- UAPI: Updating endpoint")
+               device.debugf("%v - UAPI: Updating endpoint", peer.Peer)
                endpoint, err := conn.CreateEndpoint(value)
                if err != nil {
                        return ipcErrorf(ipc.IpcErrorInvalid, "failed to set endpoint %v: %w", value, err)
@@ -317,7 +317,7 @@ func (device *Device) handlePeerLine(peer *ipcSetPeer, key, value string) error
                peer.endpoint = endpoint
 
        case "persistent_keepalive_interval":
-               device.log.Debug.Println(peer, "- UAPI: Updating persistent keepalive interval")
+               device.debugf("%v - UAPI: Updating persistent keepalive interval", peer.Peer)
 
                secs, err := strconv.ParseUint(value, 10, 16)
                if err != nil {
@@ -337,7 +337,7 @@ func (device *Device) handlePeerLine(peer *ipcSetPeer, key, value string) error
                }
 
        case "replace_allowed_ips":
-               device.log.Debug.Println(peer, "- UAPI: Removing all allowedips")
+               device.debugf("%v - UAPI: Removing all allowedips", peer.Peer)
                if value != "true" {
                        return ipcErrorf(ipc.IpcErrorInvalid, "failed to replace allowedips, invalid value: %v", value)
                }
@@ -347,7 +347,7 @@ func (device *Device) handlePeerLine(peer *ipcSetPeer, key, value string) error
                device.allowedips.RemoveByPeer(peer.Peer)
 
        case "allowed_ip":
-               device.log.Debug.Println(peer, "- UAPI: Adding allowedip")
+               device.debugf("%v - UAPI: Adding allowedip", peer.Peer)
 
                _, network, err := net.ParseCIDR(value)
                if err != nil {
@@ -414,7 +414,7 @@ func (device *Device) IpcHandle(socket net.Conn) {
                        }
                        err = device.IpcGetOperation(buffered.Writer)
                default:
-                       device.log.Error.Println("invalid UAPI operation:", op)
+                       device.errorf("invalid UAPI operation: %v", op)
                        return
                }
 
@@ -425,7 +425,7 @@ func (device *Device) IpcHandle(socket net.Conn) {
                        status = ipcErrorf(ipc.IpcErrorUnknown, "other UAPI error: %w", err)
                }
                if status != nil {
-                       device.log.Error.Println(status)
+                       device.errorf("%v", status)
                        fmt.Fprintf(buffered, "errno=%d\n\n", status.ErrorCode())
                } else {
                        fmt.Fprintf(buffered, "errno=0\n\n")

diff --git a/main.go b/main.go
index 75c922dfeba86a9e96be57448b7d56083e7ed126..3d7f23fc2d13e7a46126038b7c591f87c96916df 100644 (file)
--- a/main.go
+++ b/main.go
@@ -143,12 +143,11 @@ func main() {
                fmt.Sprintf("(%s) ", interfaceName),
        )
 
-       logger.Info.Println("Starting wireguard-go version", device.WireGuardGoVersion)
-
-       logger.Debug.Println("Debug log enabled")
+       logger.Infof("Starting wireguard-go version %v", device.WireGuardGoVersion)
+       logger.Debugf("Debug log enabled")
 
        if err != nil {
-               logger.Error.Println("Failed to create TUN device:", err)
+               logger.Errorf("Failed to create TUN device: %v", err)
                os.Exit(ExitSetupFailed)
        }
 
@@ -171,7 +170,7 @@ func main() {
        }()
 
        if err != nil {
-               logger.Error.Println("UAPI listen error:", err)
+               logger.Errorf("UAPI listen error: %v", err)
                os.Exit(ExitSetupFailed)
                return
        }
@@ -206,7 +205,7 @@ func main() {
 
                path, err := os.Executable()
                if err != nil {
-                       logger.Error.Println("Failed to determine executable:", err)
+                       logger.Errorf("Failed to determine executable: %v", err)
                        os.Exit(ExitSetupFailed)
                }
 
@@ -216,7 +215,7 @@ func main() {
                        attr,
                )
                if err != nil {
-                       logger.Error.Println("Failed to daemonize:", err)
+                       logger.Errorf("Failed to daemonize: %v", err)
                        os.Exit(ExitSetupFailed)
                }
                process.Release()
@@ -225,14 +224,14 @@ func main() {
 
        device := device.NewDevice(tun, logger)
 
-       logger.Info.Println("Device started")
+       logger.Infof("Device started")
 
        errs := make(chan error)
        term := make(chan os.Signal, 1)
 
        uapi, err := ipc.UAPIListen(interfaceName, fileUAPI)
        if err != nil {
-               logger.Error.Println("Failed to listen on uapi socket:", err)
+               logger.Errorf("Failed to listen on uapi socket: %v", err)
                os.Exit(ExitSetupFailed)
        }
 
@@ -247,7 +246,7 @@ func main() {
                }
        }()
 
-       logger.Info.Println("UAPI listener started")
+       logger.Infof("UAPI listener started")
 
        // wait for program to terminate
 
@@ -265,5 +264,5 @@ func main() {
        uapi.Close()
        device.Close()
 
-       logger.Info.Println("Shutting down")
+       logger.Infof("Shutting down")
 }

diff --git a/main_windows.go b/main_windows.go
index 291b00d883dd7adc000f25c1f7ba628d65198ffe..fea1b161657ec9e6a12f8d1995e7e67ab2dfcc00 100644 (file)
--- a/main_windows.go
+++ b/main_windows.go
@@ -34,8 +34,8 @@ func main() {
                device.LogLevelDebug,
                fmt.Sprintf("(%s) ", interfaceName),
        )
-       logger.Info.Println("Starting wireguard-go version", device.WireGuardGoVersion)
-       logger.Debug.Println("Debug log enabled")
+       logger.Infof("Starting wireguard-go version %v", device.WireGuardGoVersion)
+       logger.Debugf("Debug log enabled")
 
        tun, err := tun.CreateTUN(interfaceName, 0)
        if err == nil {
@@ -44,17 +44,17 @@ func main() {
                        interfaceName = realInterfaceName
                }
        } else {
-               logger.Error.Println("Failed to create TUN device:", err)
+               logger.Errorf("Failed to create TUN device: %v", err)
                os.Exit(ExitSetupFailed)
        }
 
        device := device.NewDevice(tun, logger)
        device.Up()
-       logger.Info.Println("Device started")
+       logger.Infof("Device started")
 
        uapi, err := ipc.UAPIListen(interfaceName)
        if err != nil {
-               logger.Error.Println("Failed to listen on uapi socket:", err)
+               logger.Errorf("Failed to listen on uapi socket: %v", err)
                os.Exit(ExitSetupFailed)
        }
 
@@ -71,7 +71,7 @@ func main() {
                        go device.IpcHandle(conn)
                }
        }()
-       logger.Info.Println("UAPI listener started")
+       logger.Infof("UAPI listener started")
 
        // wait for program to terminate
 
@@ -90,5 +90,5 @@ func main() {
        uapi.Close()
        device.Close()
 
-       logger.Info.Println("Shutting down")
+       logger.Infof("Shutting down")
 }