Merge pull request #241 from ijc25/logging-over-vsock

mac: Redirect syslog over vsock

alpine/Dockerfile

@@ -81,6 +81,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 && \
@@ -107,7 +108,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/etc/conf.d/syslog

@@ -0,0 +1,5 @@
+# Would prefer to check [ -S /var/run/syslog.vsock ] but it doesn't
+# always exist by the time we get here starts.
+if [ -e /var/run/vsudd.pid -a ! -d /sys/bus/vmbus ] ; then
+    SYSLOGD_OPTS="-R local:/var/run/syslog.vsock"
+fi

alpine/packages/go/vendor/github.com/rneugeba/virtsock/go/hvsock/hvsock.go

@@ -173,13 +173,13 @@ func (v *hvsockListener) Addr() net.Addr {
  */
 
 var (
-	errSocketClosed        = errors.New("HvSocket has already been closed")
-	errSocketWriteClosed   = errors.New("HvSocket has been closed for write")
-	errSocketReadClosed    = errors.New("HvSocket has been closed for read")
-	errSocketMsgSize       = errors.New("HvSocket message was of wrong size")
-	errSocketMsgWrite      = errors.New("HvSocket writing message")
-	errSocketNotEnoughData = errors.New("HvSocket not enough data written")
-	errSocketUnImplemented = errors.New("Function not implemented")
+	ErrSocketClosed        = errors.New("HvSocket has already been closed")
+	ErrSocketWriteClosed   = errors.New("HvSocket has been closed for write")
+	ErrSocketReadClosed    = errors.New("HvSocket has been closed for read")
+	ErrSocketMsgSize       = errors.New("HvSocket message was of wrong size")
+	ErrSocketMsgWrite      = errors.New("HvSocket writing message")
+	ErrSocketNotEnoughData = errors.New("HvSocket not enough data written")
+	ErrSocketUnImplemented = errors.New("Function not implemented")
 )
 
 type HVsockConn struct {
@@ -227,7 +227,7 @@ func (v *HVsockConn) Close() error {
 
 func (v *HVsockConn) CloseRead() error {
 	if v.readClosed {
-		return errSocketReadClosed
+		return ErrSocketReadClosed
 	}
 
 	prDebug("TX: Shutdown Read\n")
@@ -244,7 +244,7 @@ func (v *HVsockConn) CloseRead() error {
 
 func (v *HVsockConn) CloseWrite() error {
 	if v.writeClosed {
-		return errSocketWriteClosed
+		return ErrSocketWriteClosed
 	}
 
 	prDebug("TX: Shutdown Write\n")
@@ -284,7 +284,7 @@ func (v *HVsockConn) Read(buf []byte) (int, error) {
 			}
 
 			if n != 4 {
-				return n, errSocketMsgSize
+				return n, ErrSocketMsgSize
 			}
 
 			msg := int(binary.LittleEndian.Uint32(b))
@@ -333,7 +333,7 @@ func (v *HVsockConn) Read(buf []byte) (int, error) {
 
 func (v *HVsockConn) Write(buf []byte) (int, error) {
 	if v.writeClosed {
-		return 0, errSocketWriteClosed
+		return 0, ErrSocketWriteClosed
 	}
 
 	var err error
@@ -344,7 +344,7 @@ func (v *HVsockConn) Write(buf []byte) (int, error) {
 
 	for toWrite > 0 {
 		if v.writeClosed {
-			return 0, errSocketWriteClosed
+			return 0, ErrSocketWriteClosed
 		}
 
 		// We write batches of MSG + data which need to be
@@ -371,7 +371,7 @@ func (v *HVsockConn) Write(buf []byte) (int, error) {
 		}
 		if n != thisBatch {
 			prDebug("Write Error 4\n")
-			err = errSocketNotEnoughData
+			err = ErrSocketNotEnoughData
 			goto ErrOut
 		}
 		toWrite -= n
@@ -402,7 +402,7 @@ func (v *HVsockConn) sendMsg(msg uint32) error {
 		return err
 	}
 	if n != len(b) {
-		return errSocketMsgWrite
+		return ErrSocketMsgWrite
 	}
 	return nil
 }

alpine/packages/go/vendor/github.com/rneugeba/virtsock/go/hvsock/hvsock_darwin.go

@@ -1,6 +1,7 @@
 // Dummy implementation to compile on Mac OSX
 
 package hvsock
+
 import (
 	"errors"
 	"time"

alpine/packages/go/vendor/github.com/rneugeba/virtsock/go/hvsock/hvsock_windows.go

@@ -240,7 +240,7 @@ func (v *hvsockConn) closeHandle() {
 func (s *hvsockConn) prepareIo() (*ioOperation, error) {
 	s.wg.Add(1)
 	if s.closing {
-		return nil, errSocketClosed
+		return nil, ErrSocketClosed
 	}
 	c := &ioOperation{}
 	c.ch = make(chan ioResult)
@@ -299,7 +299,7 @@ func (v *hvsockConn) asyncIo(c *ioOperation, deadline time.Time, bytes uint32, e
 	err = r.err
 	if err == syscall.ERROR_OPERATION_ABORTED {
 		if v.closing {
-			err = errSocketClosed
+			err = ErrSocketClosed
 		} else if timedout {
 			err = errTimeout
 		}

alpine/packages/go/vendor/github.com/rneugeba/virtsock/go/vsock/vsock_linux.go

@@ -37,11 +37,33 @@ int accept_vm(int fd, struct sockaddr_vm *sa_vm, socklen_t *sa_vm_len) {
 import "C"
 
 const (
-	AF_VSOCK       = 40
-	VSOCK_CID_ANY  = 4294967295 /* 2^32-1 */
-	VSOCK_CID_SELF = 3
+	AF_VSOCK             = 40
+	VSOCK_CID_ANY        = 4294967295 /* 2^32-1 */
+	VSOCK_CID_HYPERVISOR = 0
+	VSOCK_CID_HOST       = 2
+	VSOCK_CID_SELF       = 3
 )
 
+func Dial(cid, port uint) (Conn, error) {
+	fd, err := syscall.Socket(AF_VSOCK, syscall.SOCK_STREAM, 0)
+	if err != nil {
+		return nil, err
+	}
+
+	sa := C.struct_sockaddr_vm{}
+	sa.svm_family = AF_VSOCK
+	sa.svm_port = C.uint(port)
+	sa.svm_cid = C.uint(cid)
+
+	if ret, errno := C.connect_sockaddr_vm(C.int(fd), &sa); ret != 0 {
+		return nil, errors.New(fmt.Sprintf(
+			"failed bind connect to %08x.%08x, returned %d, errno %d: %s",
+			sa.svm_cid, sa.svm_port, ret, errno, errno))
+	}
+
+	return newVsockConn(uintptr(fd), port)
+}
+
 // Listen returns a net.Listener which can accept connections on the given
 // vhan port.
 func Listen(port uint) (net.Listener, error) {
@@ -55,8 +77,10 @@ func Listen(port uint) (net.Listener, error) {
 	sa.svm_port = C.uint(port)
 	sa.svm_cid = VSOCK_CID_ANY
 
-	if ret := C.bind_sockaddr_vm(C.int(accept_fd), &sa); ret != 0 {
-		return nil, errors.New(fmt.Sprintf("failed bind vsock connection to %08x.%08x, returned %d", sa.svm_cid, sa.svm_port, ret))
+	if ret, errno := C.bind_sockaddr_vm(C.int(accept_fd), &sa); ret != 0 {
+		return nil, errors.New(fmt.Sprintf(
+			"failed bind vsock connection to %08x.%08x, returned %d, errno %d: %s",
+			sa.svm_cid, sa.svm_port, ret, errno, errno))
 	}
 
 	err = syscall.Listen(accept_fd, syscall.SOMAXCONN)

alpine/packages/go/vendor/manifest

@@ -5,7 +5,7 @@
 			"importpath": "github.com/rneugeba/virtsock/go",
 			"repository": "https://github.com/rneugeba/virtsock",
 			"vcs": "git",
-			"revision": "74097e05a883e89c70e6a27b342672c7fe6c846b",
+			"revision": "650ef8224a0c06b4b20e9bee1600dbf677c8176d",
 			"branch": "master",
 			"path": "/go",
 			"notests": true

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

@@ -4,28 +4,35 @@ description="vsock socket proxy client"
 
 depend()
 {
-	before docker
+	before logger docker
 }
 
 start()
 {
-	ebegin "Starting docker socket vsock passthrough"
+	ebegin "Starting vsock proxy"
 
 	if [ -d /sys/bus/vmbus ]; then
-		PORT=23a432c2-537a-4291-bcb5-d62504644739
+		DOCKER_PORT=23a432c2-537a-4291-bcb5-d62504644739
+		SYSLOG_PORT="" #TBD
 	else
-		PORT=2376
+		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}" \
-		-- -port "${PORT}" -sock /var/run/docker.sock
+		-- -inport "${DOCKER_PORT}:unix:/var/run/docker.sock" \
+		   ${SYSLOG_OPT} \
+		   -detach
 
 	eend $? "Failed to start vsudd"
 }

alpine/packages/vsudd/main.go

@@ -2,12 +2,15 @@ package main
 
 import (
 	"flag"
+	"fmt"
 	"io"
 	"log"
+	"log/syslog"
 	"net"
 	"os"
 	"strconv"
 	"strings"
+	"sync"
 	"syscall"
 	"time"
 
@@ -15,11 +18,19 @@ import (
 	"github.com/rneugeba/virtsock/go/vsock"
 )
 
+type forward struct {
+	vsock string
+	net   string // "unix" or "unixgram"
+	usock string
+}
+
+type forwards []forward
+
 var (
-	portstr   string
-	sock      string
-	detach    bool
-	useHVsock bool
+	inForwards forwards
+	detach     bool
+	useHVsock  bool
+	syslogFwd  string
 )
 
 type vConn interface {
@@ -28,9 +39,26 @@ type vConn interface {
 	CloseWrite() error
 }
 
+func (f *forwards) String() string {
+	return "Forwards"
+}
+
+func (f *forwards) Set(value string) error {
+	s := strings.SplitN(value, ":", 3)
+	if len(s) != 3 {
+		return fmt.Errorf("Failed to parse: %s", value)
+	}
+	var newF forward
+	newF.vsock = s[0]
+	newF.net = s[1]
+	newF.usock = s[2]
+	*f = append(*f, newF)
+	return nil
+}
+
 func init() {
-	flag.StringVar(&portstr, "port", "2376", "vsock port to forward")
-	flag.StringVar(&sock, "sock", "/var/run/docker.sock", "path of the local Unix domain socket to forward to")
+	flag.Var(&inForwards, "inport", "incoming port to forward")
+	flag.StringVar(&syslogFwd, "syslog", "", "enable syslog forwarding")
 	flag.BoolVar(&detach, "detach", false, "detach from terminal")
 }
 
@@ -39,61 +67,101 @@ func main() {
 	flag.Parse()
 
 	if detach {
-		logFile, err := os.Create("/var/log/vsudd.log")
+		syslog, err := syslog.New(syslog.LOG_INFO|syslog.LOG_DAEMON, "vsudd")
 		if err != nil {
-			log.Fatalln("Failed to open log file", err)
+			log.Fatalln("Failed to open syslog", err)
 		}
-		log.SetOutput(logFile)
+
 		null, err := os.OpenFile("/dev/null", os.O_RDWR, 0)
 		if err != nil {
 			log.Fatalln("Failed to open /dev/null", err)
 		}
+
+		/* Don't do this above since we aren't yet forwarding
+		/* syslog (if we've been asked to) so the above error
+		/* reporting wants to go via the default path
+		/* (stdio). */
+
+		log.SetOutput(syslog)
+		log.SetFlags(0)
+
 		fd := null.Fd()
 		syscall.Dup2(int(fd), int(os.Stdin.Fd()))
 		syscall.Dup2(int(fd), int(os.Stdout.Fd()))
 		syscall.Dup2(int(fd), int(os.Stderr.Fd()))
 	}
 
-	var l net.Listener
-	if strings.Contains(portstr, "-") {
-		svcid, err := hvsock.GuidFromString(portstr)
-		if err != nil {
-			log.Fatalln("Failed to parse GUID", portstr, err)
-		}
-		l, err = hvsock.Listen(hvsock.HypervAddr{VmId: hvsock.GUID_WILDCARD, ServiceId: svcid})
-		if err != nil {
-			log.Fatalf("Failed to bind to hvsock port: %#v", err)
-		}
-		log.Printf("Listening on ServiceId %s", svcid)
-		useHVsock = true
-	} else {
-		port, err := strconv.ParseUint(portstr, 10, 32)
-		if err != nil {
-			log.Fatalln("Can't convert %s to a uint.", portstr, err)
-		}
-		l, err = vsock.Listen(uint(port))
-		if err != nil {
-			log.Fatalf("Failed to bind to vsock port %u: %#v", port, err)
-		}
-		log.Printf("Listening on port %u", port)
-		useHVsock = false
+	var wg sync.WaitGroup
+
+	if syslogFwd != "" {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			handleSyslogForward(syslogFwd)
+		}()
 	}
 
 	connid := 0
-	for {
-		connid++
-		conn, err := l.Accept()
-		if err != nil {
-			log.Printf("Error accepting connection: %#v", err)
-			return // no more listening
-		}
-		log.Printf("Connection %d from: %s\n", connid, conn.RemoteAddr())
 
-		go handleOne(connid, conn.(vConn))
+	for _, inF := range inForwards {
+		var portstr = inF.vsock
+		var network = inF.net
+		var usock = inF.usock
+
+		var l net.Listener
+
+		if network != "unix" {
+			log.Fatalf("cannot forward incoming port to %s:%s", network, usock)
+		}
+
+		log.Printf("incoming port forward from %s to %s", portstr, usock)
+
+		if strings.Contains(portstr, "-") {
+			svcid, err := hvsock.GuidFromString(portstr)
+			if err != nil {
+				log.Fatalln("Failed to parse GUID", portstr, err)
+			}
+			l, err = hvsock.Listen(hvsock.HypervAddr{VmId: hvsock.GUID_WILDCARD, ServiceId: svcid})
+			if err != nil {
+				log.Fatalf("Failed to bind to hvsock port: %s", err)
+			}
+			log.Printf("Listening on ServiceId %s", svcid)
+			useHVsock = true
+		} else {
+			port, err := strconv.ParseUint(portstr, 10, 32)
+			if err != nil {
+				log.Fatalln("Can't convert %s to a uint.", portstr, err)
+			}
+			l, err = vsock.Listen(uint(port))
+			if err != nil {
+				log.Fatalf("Failed to bind to vsock port %d: %s", port, err)
+			}
+			log.Printf("Listening on port %s", portstr)
+			useHVsock = false
+		}
+
+		wg.Add(1)
+
+		go func() {
+			defer wg.Done()
+			for {
+				connid++
+				conn, err := l.Accept()
+				if err != nil {
+					log.Printf("Error accepting connection: %s", err)
+					return // no more listening
+				}
+				log.Printf("Connection %d to: %s from: %s\n", connid, portstr, conn.RemoteAddr())
+
+				go handleOneIn(connid, conn.(vConn), usock)
+			}
+		}()
 	}
+
+	wg.Wait()
 }
 
-func handleOne(connid int, conn vConn) {
+func handleOneIn(connid int, conn vConn, sock string) {
 	defer func() {
 		if err := conn.Close(); err != nil {
 			// On windows we get an EINVAL when the other end already closed

alpine/packages/vsudd/vsyslog.go

@@ -0,0 +1,179 @@
+/*
+ * 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 (
+	"errors"
+	"fmt"
+	"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
+)
+
+/* rfc5425 like scheme, see section 4.3 */
+func rfc5425Write(conn vConn, buf []byte) error {
+
+	msglen := fmt.Sprintf("%d ", len(buf))
+
+	_, err := conn.Write([]byte(msglen))
+	/* 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 := rfc5425Write(conn, lastMessage)
+				if err != nil {
+					conn.Close()
+					continue
+				}
+				lastMessage = nil
+			}
+
+			currentConn = conn
+		}
+
+		err := rfc5425Write(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]))
+		}
+	}
+}