Hesham/wireguard-go
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

device: change logging interface to use functions

Browse Source 
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>
This commit is contained in:
Josh Bleecher Snyder 2021-01-22 14:11:17 -08:00 committed by Jason A. Donenfeld
parent 37efdcaccf
commit 7139279cd0
11 changed files with 147 additions and 182 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
device/device.go
View File

@ -177,7 +177,7 @@ func deviceUpdateState(device *Device) {
switch newIsUp { switch newIsUp {
case true: case true:
if err := device.BindUpdate(); err != nil { 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) device.isUp.Set(false)
break break
} }
@ -303,7 +303,7 @@ func NewDevice(tunDevice tun.Device, logger *Logger) *Device {
device.tun.device = tunDevice device.tun.device = tunDevice
mtu, err := device.tun.device.MTU() mtu, err := device.tun.device.MTU()
if err != nil { if err != nil {
logger.Error.Println("Trouble determining MTU, assuming default:", err) device.errorf("Trouble determining MTU, assuming default: %v", err)
mtu = DefaultMTU mtu = DefaultMTU
} }
device.tun.mtu = int32(mtu) device.tun.mtu = int32(mtu)
@ -397,7 +397,7 @@ func (device *Device) Close() {
return return
} }
device.log.Info.Println("Device closing") device.infof("Device closing")
device.state.changing.Set(true) device.state.changing.Set(true)
device.state.Lock() device.state.Lock()
defer device.state.Unlock() defer device.state.Unlock()
@ -422,7 +422,7 @@ func (device *Device) Close() {
device.rate.limiter.Close() device.rate.limiter.Close()
device.state.changing.Set(false) device.state.changing.Set(false)
device.log.Info.Println("Interface closed") device.infof("Interface closed")
} }
func (device *Device) Wait() chan struct{} { 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(ipv4.Version, netc.bind)
go device.RoutineReceiveIncoming(ipv6.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 return nil

69
device/logger.go
View File

@ -6,12 +6,22 @@
package device package device
import ( import (
"io"
"io/ioutil"
"log" "log"
"os" "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 ( const (
LogLevelSilent = iota LogLevelSilent = iota
LogLevelError LogLevelError
@ -19,41 +29,40 @@ const (
LogLevelDebug LogLevelDebug
) )
type Logger struct { // NewLogger constructs a Logger that writes to stdout.
Debug *log.Logger // It logs at the specified log level and above.
Info *log.Logger // It decorates log lines with the log level, date, time, and prepend.
Error *log.Logger
}
func NewLogger(level int, prepend string) *Logger { func NewLogger(level int, prepend string) *Logger {
output := os.Stdout
logger := new(Logger) logger := new(Logger)
logf := func(prefix string) func(string, ...interface{}) {
logErr, logInfo, logDebug := func() (io.Writer, io.Writer, io.Writer) { return log.New(os.Stdout, prefix+": "+prepend, log.Ldate|log.Ltime).Printf
}
if level >= LogLevelDebug { if level >= LogLevelDebug {
return output, output, output logger.Debugf = logf("DEBUG")
} }
if level >= LogLevelInfo { if level >= LogLevelInfo {
return output, output, ioutil.Discard logger.Infof = logf("INFO")
} }
if level >= LogLevelError { if level >= LogLevelError {
return output, ioutil.Discard, ioutil.Discard logger.Errorf = logf("ERROR")
} }
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,
)
return logger 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...)
}
}

4
device/noise-protocol.go
View File

@ -319,11 +319,11 @@ func (device *Device) ConsumeMessageInitiation(msg *MessageInitiation) *Peer {
flood := time.Since(handshake.lastInitiationConsumption) <= HandshakeInitationRate flood := time.Since(handshake.lastInitiationConsumption) <= HandshakeInitationRate
handshake.mutex.RUnlock() handshake.mutex.RUnlock()
if replay { 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 return nil
} }
if flood { if flood {
device.log.Debug.Printf("%v - ConsumeMessageInitiation: handshake flood\n", peer) device.debugf("%v - ConsumeMessageInitiation: handshake flood", peer)
return nil return nil
} }

4
device/peer.go
View File

@ -190,7 +190,7 @@ func (peer *Peer) Start() {
} }
device := peer.device device := peer.device
device.log.Debug.Println(peer, "- Starting...") device.debugf("%v - Starting...", peer)
// reset routine state // reset routine state
@ -278,7 +278,7 @@ func (peer *Peer) Stop() {
peer.routines.Lock() peer.routines.Lock()
defer peer.routines.Unlock() defer peer.routines.Unlock()
peer.device.log.Debug.Println(peer, "- Stopping...") peer.device.debugf("%v - Stopping...", peer)
peer.timersStop() peer.timersStop()

84
device/receive.go
View File

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

57
device/send.go
View File

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

8
device/timers.go
View File

@ -78,7 +78,7 @@ func (peer *Peer) timersActive() bool {
func expiredRetransmitHandshake(peer *Peer) { func expiredRetransmitHandshake(peer *Peer) {
if atomic.LoadUint32(&peer.timers.handshakeAttempts) > MaxTimerHandshakes { 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() { if peer.timersActive() {
peer.timers.sendKeepalive.Del() peer.timers.sendKeepalive.Del()
@ -97,7 +97,7 @@ func expiredRetransmitHandshake(peer *Peer) {
} }
} else { } else {
atomic.AddUint32(&peer.timers.handshakeAttempts, 1) 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. */ /* We clear the endpoint address src address, in case this is the cause of trouble. */
peer.Lock() peer.Lock()
@ -121,7 +121,7 @@ func expiredSendKeepalive(peer *Peer) {
} }
func expiredNewHandshake(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. */ /* We clear the endpoint address src address, in case this is the cause of trouble. */
peer.Lock() peer.Lock()
if peer.endpoint != nil { if peer.endpoint != nil {
@ -133,7 +133,7 @@ func expiredNewHandshake(peer *Peer) {
} }
func expiredZeroKeyMaterial(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() peer.ZeroAndFlushAll()
} }

18
device/tun.go
View File

@ -15,41 +15,37 @@ const DefaultMTU = 1420
func (device *Device) RoutineTUNEventReader() { func (device *Device) RoutineTUNEventReader() {
setUp := false setUp := false
logDebug := device.log.Debug device.debugf("Routine: event worker - started")
logInfo := device.log.Info
logError := device.log.Error
logDebug.Println("Routine: event worker - started")
for event := range device.tun.device.Events() { for event := range device.tun.device.Events() {
if event&tun.EventMTUUpdate != 0 { if event&tun.EventMTUUpdate != 0 {
mtu, err := device.tun.device.MTU() mtu, err := device.tun.device.MTU()
old := atomic.LoadInt32(&device.tun.mtu) old := atomic.LoadInt32(&device.tun.mtu)
if err != nil { 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 { } else if int(old) != mtu {
if mtu+MessageTransportSize > MaxMessageSize { if mtu+MessageTransportSize > MaxMessageSize {
logInfo.Println("MTU updated:", mtu, "(too large)") device.infof("MTU updated: %v (too large)", mtu)
} else { } else {
logInfo.Println("MTU updated:", mtu) device.infof("MTU updated: %v", mtu)
} }
atomic.StoreInt32(&device.tun.mtu, int32(mtu)) atomic.StoreInt32(&device.tun.mtu, int32(mtu))
} }
} }
if event&tun.EventUp != 0 && !setUp { if event&tun.EventUp != 0 && !setUp {
logInfo.Println("Interface set up") device.infof("Interface set up")
setUp = true setUp = true
device.Up() device.Up()
} }
if event&tun.EventDown != 0 && setUp { if event&tun.EventDown != 0 && setUp {
logInfo.Println("Interface set down") device.infof("Interface set down")
setUp = false setUp = false
device.Down() device.Down()
} }
} }
logDebug.Println("Routine: event worker - stopped") device.debugf("Routine: event worker - stopped")
device.state.stopping.Done() device.state.stopping.Done()
} }

28
device/uapi.go
View File

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

21
main.go
View File

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

14
main_windows.go
View File

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