Logging

Logging

[J.R. Oldroyd]

Hi all,

New here.  Apologies if I am re-hashing something discussed before.
I did read back a few months of this list and didn't see any relevant
discussion.

Unlike many here who are providing anonymous VPN services and who
don't want logging at all, I am helping set up Wireguard in a corporate
VPN environment.  The logging requirements here are very different.

Specifically, there is a need for permanent logs.  And, the logs should
ideally include:

	- when a client connects
	- when a client disconnects
	- ideally also how much data was transferred in and out
	  during a session

So this is precisely the opposite logging requirement from those
who are managing anonymous VPNs.  That's understood, and my proposed
changes maintain current default no-logging behavior for those that
need no logging.

I have made replacements [1] for device/logger.go that allow syslog
to be used for logging if available.

There are two files, both are needed.  There are OS-dependent
compilation directives so that the syslog version is not used on
Windows or Plan9, which do not have syslog.

In both, the behavior is exactly the same as now by default.  If no
other config is used, logging is still at info level to stdout as is
current practice.  I.e., you can drop these in and nothing will change
for current users, even on systems that support syslog.

To use the new syslog logging, environment variables must be set.
Logging level and logging destination are controlled by the existing
variable LOG_LEVEL and the new WG_LOG_DEST and WG_LOG_FACILITY:

	LOG_LEVEL	"debug", "info", "error", "silent"
				(default is still "info")

	WG_LOG_DEST	"stdout", "syslog"
				(default is "stdout")

	WG_LOG_FACILITY
			any syslog facility, e.g., "daemon", "local0",
			"local1", etc (also "log_", prefix OK and
			either lower- or upper-case)
				(default is "daemon")

Note that when using syslog, your syslog.conf needs to be configured
to send messages from your chosen facility.level to somewhere useful.

Also, it's worth saying that wireguard-go's logging includes some
UTF-8 characters.  Certain OSs' syslogd don't handle 8-bit data
very well.  E.g., FreeBSD.  A patch for FreeBSD's syslogd is at [2].

Since this is backwards compatible, it would be great to see this
logger.go and logger_syslog.go replace the current logger.go.

I have also been playing with some patches to add the session start and
end log messages.  I realize that this is a stateless protocol and that
the idea of a session isn't really there.  While my current placement of
these session log messages in receive.go and in timers.go is close, it
isn't perfect.  Right now I am logging "session start" in the initial
handshake code and "session end" in the handshake timeout code.  Neither
are perfect but, as I said, close.  I need to look more at the peer
state information that is currently maintained in order to see if
there's a better place to put these log messages.  I realize also that
these session log messages must not be logged for those who don't want
any logging.  These session log patches are NOT part of the current
proposed logger.go changes.  If anyone wants to see these, I'll send
them along separately.

	-jr

[1] optional syslog logging for wireguard-go
    http://opal.com/jr/wireguard/logger.go
    http://opal.com/jr/wireguard/logger_syslog.go
	(both files are needed)

[2] Patch for FreeBSD's syslogd to support UTF-8 chars in messages
    https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=244226

Re: Logging

[Arti Zirk]

On P, 2020-03-15 at 14:16 +0100, J.R. Oldroyd wrote:
> New here.  Apologies if I am re-hashing something discussed before.
> I did read back a few months of this list and didn't see any relevant
> discussion.

Quite a lot of information can also be obtained via Linux Wireguard
module. wg(8) man page has a section on that. 

https://git.zx2c4.com/wireguard-tools/about/src/man/wg.8#DEBUGGING%20INFORMATION

Re: Logging

[Jason A. Donenfeld]

Hi JR,

Adding direct syslog support might make sense. I'll look into
integrating those files you sent, though, perhaps it'd be better if
you submitted those as a patch to the mailing list with a proper
Signed-off-by line? (Or even to Github?)

I'm curious to know: is there a reason why you prefer this to something like:

`LOG_LEVEL=debug wireguard-go -f wg0 2>&1 | logger &`

Jason

Re: Logging

[J.R. Oldroyd]

On Mon, 16 Mar 2020 13:30:17 -0600 "Jason A. Donenfeld" <Jason@zx2c4.com> wrote:
>
> Adding direct syslog support might make sense. I'll look into
> integrating those files you sent, though, perhaps it'd be better if
> you submitted those as a patch to the mailing list with a proper
> Signed-off-by line? (Or even to Github?)
>
Will do.
 
> I'm curious to know: is there a reason why you prefer this to something like:
> 
> `LOG_LEVEL=debug wireguard-go -f wg0 2>&1 | logger &`
> 
Since adding syslog support is so trivial, given the existing code
is already designed around logging levels and given Go's clean support
of syslog, why not just build it in so that wireguard's logging is done
consistently with all other UNIX daemons?  Piping stdout to logger
is non-standard and also loses the ability to filter the different
log levels to different log destinations.

	-jr

Re: Logging

[Luis Ressel]

On Tue, Mar 17, 2020 at 08:37:17AM +0100, J.R. Oldroyd wrote:
> Since adding syslog support is so trivial, given the existing code
> is already designed around logging levels and given Go's clean support
> of syslog, why not just build it in so that wireguard's logging is done
> consistently with all other UNIX daemons?  Piping stdout to logger
> is non-standard and also loses the ability to filter the different
> log levels to different log destinations.

If you're adding logging support, I'd prefer logs on stderr over a
centralized legacy mechanism such as syslog. That's much more flexible;
in particular, it makes it much easier to direct logs of different
daemons to different places, or run daemons in chroots.

Cheers,
Luis

Re: Logging

[J.R. Oldroyd]

On Tue, 17 Mar 2020 18:12:05 +0000 Luis Ressel <aranea@aixah.de> wrote:
>
> If you're adding logging support, I'd prefer logs on stderr over a
> centralized legacy mechanism such as syslog. That's much more flexible;
> in particular, it makes it much easier to direct logs of different
> daemons to different places, or run daemons in chroots.
> 

First, I should point out that the whole purpose of syslog(3) is
to do the flexible directing of different daemons' logs to different
places, including in chroots.

That said, adding logging to stderr is also very trivial, given the
current code.  I have updated the two files on my website [1] to include
this.  Just set environment variable WG_LOG_DEST to "stderr" and then
start wireguard-go.

Please test.  If this works as desired, I will update the git patch
that I sent in yesterday.

	-jr

[1] optional syslog logging for wireguard-go
    http://opal.com/jr/wireguard/logger.go
    http://opal.com/jr/wireguard/logger_syslog.go
	(both files are needed)

Re: Logging

[Luis Ressel]

On Wed, Mar 18, 2020 at 09:14:42AM +0100, J.R. Oldroyd wrote:
> First, I should point out that the whole purpose of syslog(3) is
> to do the flexible directing of different daemons' logs to different
> places, including in chroots.

By design, syslog funnels all logs through a single socket. Separating
them again requires matching the contents of log messages, which is
inefficient and error-prone. Getting syslog to work in chroots can be
annoying, since it requires opening the logging socket before chrooting
(which requires support by the daemon), or providing a /dev/log socket
inside the chroot.

That said, I'm aware that syslog is more convenient in some setups, so
offering both stderr and syslog logging sounds reasonable to me.

Cheers,
Luis

[PATCH 0/1] Re: Logging

[J.R. Oldroyd]

Here's the same syslog logging files sent from git.

J.R. Oldroyd (1):
  Add support for logging to syslog(3) on operating systems that support
    it (i.e., non-Windows, non-Plan9).

 device/logger.go        |  45 ++++++----------
 device/logger_syslog.go | 112 ++++++++++++++++++++++++++++++++++++++++
 2 files changed, 129 insertions(+), 28 deletions(-)
 create mode 100644 device/logger_syslog.go

-- 
2.24.0

[PATCH 1/1] Add support for logging to syslog(3) on operating systems that support it (i.e., non-Windows, non-Plan9).

[J.R. Oldroyd]

Signed-off-by: J.R. Oldroyd <wgrd@opal.com>
---
 device/logger.go        |  45 ++++++----------
 device/logger_syslog.go | 112 ++++++++++++++++++++++++++++++++++++++++
 2 files changed, 129 insertions(+), 28 deletions(-)
 create mode 100644 device/logger_syslog.go

diff --git a/device/logger.go b/device/logger.go
index 7c8b704..8095b3d 100644
--- a/device/logger.go
+++ b/device/logger.go
@@ -1,3 +1,5 @@
+// +build windows,plan9
+
 /* SPDX-License-Identifier: MIT
  *
  * Copyright (C) 2017-2019 WireGuard LLC. All Rights Reserved.
@@ -6,7 +8,6 @@
 package device
 
 import (
-	"io"
 	"io/ioutil"
 	"log"
 	"os"
@@ -26,34 +27,22 @@ type Logger struct {
 }
 
 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,
-	)
+	nullLog := log.New(ioutil.Discard, "", 0)
+	logger.Debug = nullLog
+	logger.Info  = nullLog
+	logger.Error = nullLog
+
+	if level >= LogLevelDebug {
+		logger.Debug = log.New(os.Stdout, "DEBUG: "+prepend, log.Ldate|log.Ltime)
+	}
+	if level >= LogLevelInfo {
+		logger.Info = log.New(os.Stdout, "INFO: "+prepend, log.Ldate|log.Ltime)
+	}
+	if level >= LogLevelError {
+		logger.Error = log.New(os.Stdout, "ERROR: "+prepend, log.Ldate|log.Ltime)
+	}
+
 	return logger
 }
diff --git a/device/logger_syslog.go b/device/logger_syslog.go
new file mode 100644
index 0000000..1271155
--- /dev/null
+++ b/device/logger_syslog.go
@@ -0,0 +1,112 @@
+// +build !windows,!plan9
+
+/* SPDX-License-Identifier: MIT
+ *
+ * Copyright (C) 2017-2019 WireGuard LLC. All Rights Reserved.
+ */
+
+package device
+
+import (
+	"io/ioutil"
+	"log"
+	"log/syslog"
+	"os"
+	"strings"
+)
+
+const (
+	LogLevelSilent = iota
+	LogLevelError
+	LogLevelInfo
+	LogLevelDebug
+)
+
+type Logger struct {
+	Debug *log.Logger
+	Info  *log.Logger
+	Error *log.Logger
+}
+
+func NewLogger(level int, prepend string) *Logger {
+	logger := new(Logger)
+
+	nullLog := log.New(ioutil.Discard, "", 0)
+	logger.Debug = nullLog
+	logger.Info  = nullLog
+	logger.Error = nullLog
+
+	logdest := os.Getenv("WG_LOG_DEST")
+
+	logfacility := syslog.LOG_DAEMON
+	if logdest == "syslog" {
+		facility := os.Getenv("WG_LOG_FACILITY")
+		facility = strings.ToLower(facility)
+		facility = strings.TrimPrefix(facility, "log_")
+		// the commented-out ones exist on BSD but not in Go
+		switch facility {
+		case "auth":		logfacility = syslog.LOG_AUTH
+		case "authpriv":	logfacility = syslog.LOG_AUTHPRIV
+		//case "console":		logfacility = syslog.LOG_CONSOLE
+		case "cron":		logfacility = syslog.LOG_CRON
+		case "daemon":		logfacility = syslog.LOG_DAEMON
+		case "ftp":		logfacility = syslog.LOG_FTP
+		case "kern":		logfacility = syslog.LOG_KERN
+		case "local0":		logfacility = syslog.LOG_LOCAL0
+		case "local1":		logfacility = syslog.LOG_LOCAL1
+		case "local2":		logfacility = syslog.LOG_LOCAL2
+		case "local3":		logfacility = syslog.LOG_LOCAL3
+		case "local4":		logfacility = syslog.LOG_LOCAL4
+		case "local5":		logfacility = syslog.LOG_LOCAL5
+		case "local6":		logfacility = syslog.LOG_LOCAL6
+		case "local7":		logfacility = syslog.LOG_LOCAL7
+		case "lpr":		logfacility = syslog.LOG_LPR
+		case "mail":		logfacility = syslog.LOG_MAIL
+		//case "ntp":		logfacility = syslog.LOG_NTP
+		case "news":		logfacility = syslog.LOG_NEWS
+		//case "security":	logfacility = syslog.LOG_SECURITY
+		case "syslog":		logfacility = syslog.LOG_SYSLOG
+		case "user":		logfacility = syslog.LOG_USER
+		case "uucp":		logfacility = syslog.LOG_UUCP
+		}
+	}
+
+	if level >= LogLevelDebug {
+		if logdest == "syslog" {
+			sysLog, err := syslog.NewLogger(logfacility | syslog.LOG_DEBUG, 0)
+			if err == nil {
+				logger.Debug = sysLog
+			} else {
+				logger.Debug = log.New(os.Stdout, "DEBUG: "+prepend, log.Ldate|log.Ltime)
+			}
+		} else {
+			logger.Debug = log.New(os.Stdout, "DEBUG: "+prepend, log.Ldate|log.Ltime)
+		}
+	}
+	if level >= LogLevelInfo {
+		if logdest == "syslog" {
+			sysLog, err := syslog.NewLogger(logfacility | syslog.LOG_INFO, 0)
+			if err == nil {
+				logger.Info = sysLog
+			} else {
+				logger.Info = log.New(os.Stdout, "INFO: "+prepend, log.Ldate|log.Ltime)
+			}
+		} else {
+			logger.Info = log.New(os.Stdout, "INFO: "+prepend, log.Ldate|log.Ltime)
+		}
+	}
+	if level >= LogLevelError {
+		if logdest == "syslog" {
+			sysLog, err := syslog.NewLogger(logfacility | syslog.LOG_ERR, 0)
+			if err == nil {
+				logger.Error = sysLog
+			} else {
+				logger.Error = log.New(os.Stdout, "ERROR: "+prepend, log.Ldate|log.Ltime)
+			}
+		} else {
+			logger.Error = log.New(os.Stdout, "ERROR: "+prepend, log.Ldate|log.Ltime)
+		}
+	}
+
+	return logger
+}
-- 
2.24.0