Skip to content

Commit

Permalink
device: combine debug and info log levels into 'verbose'
Browse files Browse the repository at this point in the history 
There are very few cases, if any, in which a user only wants one of
these levels, so combine it into a single level.

While we're at it, reduce indirection on the loggers by using an empty
function rather than a nil function pointer. It's not like we have
retpolines anyway, and we were always calling through a function with a
branch prior, so this seems like a net gain.

Signed-off-by: Jason A. Donenfeld <Jason@zx2c4.com>
  • Loading branch information
@zx2c4
zx2c4 committed Jan 26, 2021
1 parent 7139279 commit d669c78
Show file tree
Hide file tree
Showing 13 changed files with 109 additions and 133 deletions.
10 changes: 5 additions & 5 deletions device/device.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -177,7 +177,7 @@ func deviceUpdateState(device *Device) {
switch newIsUp {
case true:
if err := device.BindUpdate(); err != nil {
device.errorf("Unable to update bind: %v", err)
device.log.Errorf("Unable to update bind: %v", err)
device.isUp.Set(false)
break
}
Expand Down Expand Up @@ -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 {
device.errorf("Trouble determining MTU, assuming default: %v", err)
device.log.Errorf("Trouble determining MTU, assuming default: %v", err)
mtu = DefaultMTU
}
device.tun.mtu = int32(mtu)
Expand Down Expand Up @@ -397,7 +397,7 @@ func (device *Device) Close() {
return
}

device.infof("Device closing")
device.log.Verbosef("Device closing")
device.state.changing.Set(true)
device.state.Lock()
defer device.state.Unlock()
Expand All @@ -422,7 +422,7 @@ func (device *Device) Close() {
device.rate.limiter.Close()

device.state.changing.Set(false)
device.infof("Interface closed")
device.log.Verbosef("Interface closed")
}

func (device *Device) Wait() chan struct{} {
Expand Down Expand Up @@ -562,7 +562,7 @@ func (device *Device) BindUpdate() error {
go device.RoutineReceiveIncoming(ipv4.Version, netc.bind)
go device.RoutineReceiveIncoming(ipv6.Version, netc.bind)

device.debugf("UDP bind has been updated")
device.log.Verbosef("UDP bind has been updated")
}

return nil
Expand Down
2 changes: 1 addition & 1 deletion device/device_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -148,7 +148,7 @@ NextAttempt:
} else {
p.ip = net.ParseIP("1.0.0.2")
}
level := LogLevelDebug
level := LogLevelVerbose
if _, ok := tb.(*testing.B); ok && !testing.Verbose() {
level = LogLevelError
}
Expand Down
38 changes: 9 additions & 29 deletions device/logger.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,53 +16,33 @@ import (
// 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{})
Verbosef func(format string, args ...interface{})
Errorf func(format string, args ...interface{})
}

// Log levels for use with NewLogger.
const (
LogLevelSilent = iota
LogLevelError
LogLevelInfo
LogLevelDebug
LogLevelVerbose
)

// Function for use in Logger for discarding logged lines.
func DiscardLogf(format string, args ...interface{}) {}

// 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 {
logger := new(Logger)
logger := &Logger{DiscardLogf, DiscardLogf}
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 >= LogLevelVerbose {
logger.Verbosef = logf("DEBUG")
}
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...)
}
}
4 changes: 2 additions & 2 deletions device/noise-protocol.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -319,11 +319,11 @@ func (device *Device) ConsumeMessageInitiation(msg *MessageInitiation) *Peer {
flood := time.Since(handshake.lastInitiationConsumption) <= HandshakeInitationRate
handshake.mutex.RUnlock()
if replay {
device.debugf("%v - ConsumeMessageInitiation: handshake replay @ %v", peer, timestamp)
device.log.Verbosef("%v - ConsumeMessageInitiation: handshake replay @ %v", peer, timestamp)
return nil
}
if flood {
device.debugf("%v - ConsumeMessageInitiation: handshake flood", peer)
device.log.Verbosef("%v - ConsumeMessageInitiation: handshake flood", peer)
return nil
}

Expand Down
4 changes: 2 additions & 2 deletions device/peer.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -190,7 +190,7 @@ func (peer *Peer) Start() {
}

device := peer.device
device.debugf("%v - Starting...", peer)
device.log.Verbosef("%v - Starting...", peer)

// reset routine state

Expand Down Expand Up @@ -278,7 +278,7 @@ func (peer *Peer) Stop() {
peer.routines.Lock()
defer peer.routines.Unlock()

peer.device.debugf("%v - Stopping...", peer)
peer.device.log.Verbosef("%v - Stopping...", peer)

peer.timersStop()

Expand Down
56 changes: 28 additions & 28 deletions device/receive.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -79,12 +79,12 @@ func (peer *Peer) keepKeyFreshReceiving() {
*/
func (device *Device) RoutineReceiveIncoming(IP int, bind conn.Bind) {
defer func() {
device.debugf("Routine: receive incoming IPv%d - stopped", IP)
device.log.Verbosef("Routine: receive incoming IPv%d - stopped", IP)
device.queue.decryption.wg.Done()
device.net.stopping.Done()
}()

device.debugf("Routine: receive incoming IPv%d - started", IP)
device.log.Verbosef("Routine: receive incoming IPv%d - started", IP)

// receive datagrams until conn is closed

Expand Down Expand Up @@ -112,7 +112,7 @@ func (device *Device) RoutineReceiveIncoming(IP int, bind conn.Bind) {
if errors.Is(err, conn.NetErrClosed) {
return
}
device.errorf("Failed to receive packet: %v", err)
device.log.Errorf("Failed to receive packet: %v", err)
if deathSpiral < 10 {
deathSpiral++
time.Sleep(time.Second / 3)
Expand Down Expand Up @@ -199,7 +199,7 @@ func (device *Device) RoutineReceiveIncoming(IP int, bind conn.Bind) {
okay = len(packet) == MessageCookieReplySize

default:
device.debugf("Received message with unknown type")
device.log.Verbosef("Received message with unknown type")
}

if okay {
Expand All @@ -221,10 +221,10 @@ func (device *Device) RoutineReceiveIncoming(IP int, bind conn.Bind) {
func (device *Device) RoutineDecryption() {
var nonce [chacha20poly1305.NonceSize]byte
defer func() {
device.debugf("Routine: decryption worker - stopped")
device.log.Verbosef("Routine: decryption worker - stopped")
device.state.stopping.Done()
}()
device.debugf("Routine: decryption worker - started")
device.log.Verbosef("Routine: decryption worker - started")

for elem := range device.queue.decryption.c {
// split message into fields
Expand Down Expand Up @@ -256,14 +256,14 @@ func (device *Device) RoutineHandshake() {
var ok bool

defer func() {
device.debugf("Routine: handshake worker - stopped")
device.log.Verbosef("Routine: handshake worker - stopped")
device.state.stopping.Done()
if elem.buffer != nil {
device.PutMessageBuffer(elem.buffer)
}
}()

device.debugf("Routine: handshake worker - started")
device.log.Verbosef("Routine: handshake worker - started")

for {
if elem.buffer != nil {
Expand Down Expand Up @@ -293,7 +293,7 @@ func (device *Device) RoutineHandshake() {
reader := bytes.NewReader(elem.packet)
err := binary.Read(reader, binary.LittleEndian, &reply)
if err != nil {
device.debugf("Failed to decode cookie reply")
device.log.Verbosef("Failed to decode cookie reply")
return
}

Expand All @@ -308,9 +308,9 @@ func (device *Device) RoutineHandshake() {
// consume reply

if peer := entry.peer; peer.isRunning.Get() {
device.debugf("Receiving cookie response from %s", elem.endpoint.DstToString())
device.log.Verbosef("Receiving cookie response from %s", elem.endpoint.DstToString())
if !peer.cookieGenerator.ConsumeReply(&reply) {
device.debugf("Could not decrypt invalid cookie response")
device.log.Verbosef("Could not decrypt invalid cookie response")
}
}

Expand All @@ -321,7 +321,7 @@ func (device *Device) RoutineHandshake() {
// check mac fields and maybe ratelimit

if !device.cookieChecker.CheckMAC1(elem.packet) {
device.debugf("Received packet with invalid mac1")
device.log.Verbosef("Received packet with invalid mac1")
continue
}

Expand All @@ -344,7 +344,7 @@ func (device *Device) RoutineHandshake() {
}

default:
device.errorf("Invalid packet ended up in the handshake queue")
device.log.Errorf("Invalid packet ended up in the handshake queue")
continue
}

Expand All @@ -359,15 +359,15 @@ func (device *Device) RoutineHandshake() {
reader := bytes.NewReader(elem.packet)
err := binary.Read(reader, binary.LittleEndian, &msg)
if err != nil {
device.errorf("Failed to decode initiation message")
device.log.Errorf("Failed to decode initiation message")
continue
}

// consume initiation

peer := device.ConsumeMessageInitiation(&msg)
if peer == nil {
device.infof("Received invalid initiation message from %s", elem.endpoint.DstToString())
device.log.Verbosef("Received invalid initiation message from %s", elem.endpoint.DstToString())
continue
}

Expand All @@ -379,7 +379,7 @@ func (device *Device) RoutineHandshake() {
// update endpoint
peer.SetEndpointFromPacket(elem.endpoint)

device.debugf("%v - Received handshake initiation", peer)
device.log.Verbosef("%v - Received handshake initiation", peer)
atomic.AddUint64(&peer.stats.rxBytes, uint64(len(elem.packet)))

peer.SendHandshakeResponse()
Expand All @@ -392,22 +392,22 @@ func (device *Device) RoutineHandshake() {
reader := bytes.NewReader(elem.packet)
err := binary.Read(reader, binary.LittleEndian, &msg)
if err != nil {
device.errorf("Failed to decode response message")
device.log.Errorf("Failed to decode response message")
continue
}

// consume response

peer := device.ConsumeMessageResponse(&msg)
if peer == nil {
device.infof("Received invalid response message from %s", elem.endpoint.DstToString())
device.log.Verbosef("Received invalid response message from %s", elem.endpoint.DstToString())
continue
}

// update endpoint
peer.SetEndpointFromPacket(elem.endpoint)

device.debugf("%v - Received handshake response", peer)
device.log.Verbosef("%v - Received handshake response", peer)
atomic.AddUint64(&peer.stats.rxBytes, uint64(len(elem.packet)))

// update timers
Expand All @@ -420,7 +420,7 @@ func (device *Device) RoutineHandshake() {
err = peer.BeginSymmetricSession()

if err != nil {
device.errorf("%v - Failed to derive keypair: %v", peer, err)
device.log.Errorf("%v - Failed to derive keypair: %v", peer, err)
continue
}

Expand All @@ -440,15 +440,15 @@ func (peer *Peer) RoutineSequentialReceiver() {
var elem *QueueInboundElement

defer func() {
device.debugf("%v - Routine: sequential receiver - stopped", peer)
device.log.Verbosef("%v - Routine: sequential receiver - stopped", peer)
peer.routines.stopping.Done()
if elem != nil {
device.PutMessageBuffer(elem.buffer)
device.PutInboundElement(elem)
}
}()

device.debugf("%v - Routine: sequential receiver - started", peer)
device.log.Verbosef("%v - Routine: sequential receiver - started", peer)

for {
if elem != nil {
Expand Down Expand Up @@ -499,7 +499,7 @@ func (peer *Peer) RoutineSequentialReceiver() {
// check for keepalive

if len(elem.packet) == 0 {
device.debugf("%v - Receiving keepalive packet", peer)
device.log.Verbosef("%v - Receiving keepalive packet", peer)
continue
}
peer.timersDataReceived()
Expand Down Expand Up @@ -527,7 +527,7 @@ func (peer *Peer) RoutineSequentialReceiver() {

src := elem.packet[IPv4offsetSrc : IPv4offsetSrc+net.IPv4len]
if device.allowedips.LookupIPv4(src) != peer {
device.infof("IPv4 packet with disallowed source address from %v", peer)
device.log.Verbosef("IPv4 packet with disallowed source address from %v", peer)
continue
}

Expand All @@ -552,12 +552,12 @@ func (peer *Peer) RoutineSequentialReceiver() {

src := elem.packet[IPv6offsetSrc : IPv6offsetSrc+net.IPv6len]
if device.allowedips.LookupIPv6(src) != peer {
device.infof("IPv6 packet with disallowed source address from %v", peer)
device.log.Verbosef("IPv6 packet with disallowed source address from %v", peer)
continue
}

default:
device.infof("Packet with invalid IP version from %v", peer)
device.log.Verbosef("Packet with invalid IP version from %v", peer)
continue
}

Expand All @@ -566,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() {
device.errorf("Failed to write packet to TUN device: %v", err)
device.log.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.errorf("Unable to flush packets: %v", err)
peer.device.log.Errorf("Unable to flush packets: %v", err)
}
}
}
Expand Down
Loading

0 comments on commit d669c78

Please sign in to comment.