vsudd: Forward syslog from /var/run/syslog.vsock to vsock 514

This is mac only (for now) and will not actually do anything until syslogd is
told to forward to /var/run/syslog.vsock.

syslog uses a SOCK_DGRAM connection to /var/run/syslog.vsock, however vsock
today is SOCK_STREAM only, so we need to "packetise" the stream. Do so by
writing the datagram length as a (little-endian) uint32 before the data itself.
This is slightly modelled after rfc6587 (syslog over TCP) but simplified by
using a 4-byte binary value rather than ASCII digits.

Arrange for vsudd to start before the logger so it is ready and waiting.

Note that the code in vsyslog.go needs to be rather careful about its own
logging, in particular logging forwarding failures over syslog seems likely to
make things worse. Instead this file logs to the console when errors occur,
this will be captured by the logging of the hyperkit VM console.

Signed-off-by: Ian Campbell <ian.campbell@docker.com>

alpine/Dockerfile

@@ -80,6 +80,7 @@ RUN \
   rc-update add bootmisc boot && \
   rc-update add urandom boot && \
   rc-update add hostname boot && \
+  rc-update add vsudd boot && \
   rc-update add syslog boot && \
   rc-update add hwclock boot && \
   rc-update add networking boot && \
@@ -106,7 +107,6 @@ RUN \
   rc-update add hostsettings boot && \
   rc-update add hv_kvp_daemon default && \
   rc-update add hv_vss_daemon default && \
-  rc-update add vsudd default && \
   rc-update add oom default && \
   true
 

alpine/packages/vsudd/etc/init.d/vsudd

@@ -4,7 +4,7 @@ description="vsock socket proxy client"
 
 depend()
 {
-	before docker
+	before logger docker
 }
 
 start()
@@ -13,19 +13,27 @@ start()
 
 	if [ -d /sys/bus/vmbus ]; then
 		DOCKER_PORT=23a432c2-537a-4291-bcb5-d62504644739
+		SYSLOG_PORT="" #TBD
 	else
 		DOCKER_PORT=2376
+		SYSLOG_PORT=514
 	fi
 
 	[ -n "${PIDFILE}" ] || PIDFILE=/var/run/vsudd.pid
 	[ -n "${LOGFILE}" ] || LOGFILE=/var/log/vsudd.log
 
+	if [ -n "$SYSLOG_PORT" ] ; then
+	   # Can be inlined below once Windows defines syslog port
+	   SYSLOG_OPT="-syslog ${SYSLOG_PORT}:/var/run/syslog.vsock"
+	fi
+
 	start-stop-daemon --start --quiet \
 		--background \
 		--exec /sbin/vsudd \
 		--make-pidfile --pidfile ${PIDFILE} \
 		--stderr "${LOGFILE}" --stdout "${LOGFILE}" \
-		-- -inport "${DOCKER_PORT}:unix:/var/run/docker.sock"
+		-- -inport "${DOCKER_PORT}:unix:/var/run/docker.sock" \
+		   ${SYSLOG_OPT}
 
 	eend $? "Failed to start vsudd"
 }

alpine/packages/vsudd/main.go

@@ -29,6 +29,7 @@ var (
 	inForwards forwards
 	detach     bool
 	useHVsock  bool
+	syslogFwd  string
 )
 
 type vConn interface {
@@ -56,6 +57,7 @@ func (f *forwards) Set(value string) error {
 
 func init() {
 	flag.Var(&inForwards, "inport", "incoming port to forward")
+	flag.StringVar(&syslogFwd, "syslog", "", "enable syslog forwarding")
 	flag.BoolVar(&detach, "detach", false, "detach from terminal")
 }
 
@@ -81,6 +83,14 @@ func main() {
 
 	var wg sync.WaitGroup
 
+	if syslogFwd != "" {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			handleSyslogForward(syslogFwd)
+		}()
+	}
+
 	connid := 0
 
 	for _, inF := range inForwards {

alpine/packages/vsudd/vsyslog.go

@@ -0,0 +1,178 @@
+/*
+ * Functions in this file are used to forward syslog messages to the
+ * host and must be quite careful about their own logging. In general
+ * error messages should go via the console log.Logger defined in this
+ * file.
+ */
+package main
+
+import (
+	"encoding/binary"
+	"errors"
+	"log"
+	"net"
+	"os"
+	"strconv"
+	"strings"
+
+	"github.com/rneugeba/virtsock/go/hvsock"
+	"github.com/rneugeba/virtsock/go/vsock"
+)
+
+var (
+	console     *log.Logger
+	currentConn vConn
+
+	alreadyConnectedOnce bool
+
+	/* When writing we don't discover e.g. EPIPE until the _next_
+	 * attempt to write. Therefore we keep a copy of the last
+	 * message sent such that we can repeat it after an error.
+	 *
+	 * Note that this is imperfect since their can be multiple
+	 * messages in flight at the point a connection collapses
+	 * which will then be lost. This only handles the delayed
+	 * notification of such an error to this code.
+	 */
+	lastMessage []byte
+)
+
+func checkedWrite(conn vConn, buf []byte) error {
+
+	var l uint32 = uint32(len(buf))
+
+	err := binary.Write(conn, binary.LittleEndian, l)
+	/* XXX todo, check for serious vs retriable errors */
+	if err != nil {
+		console.Printf("Error in length write: %s", err)
+		return err
+	}
+
+	_, err = conn.Write(buf)
+	/* XXX todo, check for serious vs retriable errors */
+	if err != nil {
+		console.Printf("Error in buf write: %s", err)
+	}
+
+	return err
+}
+
+func forwardSyslogDatagram(buf []byte, portstr string) error {
+	for try := 0; try < 2; try++ {
+		conn := currentConn
+		if conn == nil {
+			if strings.Contains(portstr, "-") {
+				svcid, err := hvsock.GuidFromString(portstr)
+				if err != nil {
+					console.Fatalln("Failed to parse GUID", portstr, err)
+				}
+
+				conn, err = hvsock.Dial(hvsock.HypervAddr{VmId: hvsock.GUID_WILDCARD, ServiceId: svcid})
+				if err != nil {
+					console.Printf("Failed to dial hvsock port: %s", err)
+					continue
+				}
+			} else {
+				port, err := strconv.ParseUint(portstr, 10, 32)
+				if err != nil {
+					console.Fatalln("Can't convert %s to a uint.", portstr, err)
+				}
+
+				conn, err = vsock.Dial(vsock.VSOCK_CID_HOST, uint(port))
+				if err != nil {
+					console.Printf("Failed to dial vsock port %d: %s", port, err)
+					continue
+				}
+			}
+
+			conn.CloseRead()
+
+			/*
+			 * Only log on reconnection, not the initial connection since
+			 * that is mostly uninteresting
+			 */
+			if alreadyConnectedOnce {
+				console.Printf("Opened new conn to %s: %#v", portstr, conn)
+			}
+			alreadyConnectedOnce = true
+
+			if lastMessage != nil {
+				console.Printf("Replaying last message: %s", lastMessage)
+				err := checkedWrite(conn, lastMessage)
+				if err != nil {
+					conn.Close()
+					continue
+				}
+				lastMessage = nil
+			}
+
+			currentConn = conn
+		}
+
+		err := checkedWrite(conn, buf)
+		if err != nil {
+			currentConn.Close()
+			currentConn = nil
+			console.Printf("Failed to write: %s", string(buf))
+			continue
+		}
+
+		if try > 0 {
+			console.Printf("Forwarded on attempt %d: %s", try+1, string(buf))
+		}
+
+		// Keep a copy in case we get an EPIPE from the next write
+		lastMessage = make([]byte, len(buf))
+		copy(lastMessage, buf)
+
+		return nil
+	}
+
+	lastMessage = nil // No point repeating this now
+	return errors.New("Failed to send datagram, too many retries")
+}
+
+func handleSyslogForward(cfg string) {
+	// logging to the default syslog while trying to do syslog
+	// forwarding would result in infinite loops, so log all
+	// messages in this callchain to the console instead.
+	logFile, err := os.OpenFile("/dev/console", os.O_WRONLY, 0)
+	if err != nil {
+		/* What are the chances of this going anywhere useful... */
+		log.Fatalln("Failed to open /dev/console for syslog forward logging", err)
+	}
+
+	console = log.New(logFile, "vsyslog: ", log.LstdFlags)
+
+	s := strings.SplitN(cfg, ":", 2)
+	if len(s) != 2 {
+		console.Fatalf("Failed to parse: %s", cfg)
+	}
+	vsock := s[0]
+	usock := s[1]
+
+	err = os.Remove(usock)
+	if err != nil && !os.IsNotExist(err) {
+		console.Printf("Failed to remove %s: %s", usock, err)
+		/* Try and carry on... */
+	}
+
+	l, err := net.ListenUnixgram("unixgram", &net.UnixAddr{usock, "unixgram"})
+	if err != nil {
+		console.Fatalf("Failed to listen to unixgram:%s: %s", usock, err)
+	}
+
+	var buf [4096]byte // Ugh, no way to peek at the next message's size in Go
+	for {
+		r, err := l.Read(buf[:])
+		if err != nil {
+			console.Fatalf("Failed to read: %s", err)
+		}
+
+		err = forwardSyslogDatagram(buf[:r], vsock)
+		if err != nil {
+			console.Printf("Failed to send log: %s: %s",
+				err, string(buf[:r]))
+		}
+	}
+}