[wip] Improve logs for Docker for Mac

README.md

@@ -53,6 +53,8 @@ Notes:
   $ opam pin remove qcow
   ```
 
+- Go vendoring relies on [`dep`](https://github.com/golang/dep).  To install it, run `go get -u github.com/golang/dep/cmd/dep`.
+
 ## Tracing
 
 HyperKit defines a number of static DTrace probes to simplify investigation of

go/Gopkg.toml

@@ -0,0 +1,11 @@
+# Refer to https://golang.github.io/dep/docs/Gopkg.toml.html
+# for detailed Gopkg.toml documentation.
+
+[[constraint]]
+  branch = "master"
+  name = "github.com/mitchellh/go-ps"
+
+[prune]
+  non-go = true
+  go-tests = true
+  unused-packages = true

go/Makefile

@@ -64,8 +64,8 @@ vendor:
 
 vendor-local:
 	@echo "+ $@"
-	@go get github.com/LK4D4/vndr
-	@vndr init
+	@go get -u github.com/golang/dep/cmd/dep
+	@dep init
 
 .PHONY: ci setup
 setup:

go/log.go

@@ -1,57 +1,14 @@
 package hyperkit
 
 import (
-	"fmt"
-	golog "log"
+	"github.com/sirupsen/logrus"
 )
 
-// Logger is an interface for logging.
-type Logger interface {
-	// Debugf logs a message with "debug" severity (very verbose).
-	Debugf(format string, v ...interface{})
-	// Infof logs a message with "info" severity (less verbose).
-	Infof(format string, v ...interface{})
-	// Warnf logs a message with "warn" (non-fatal) severity.
-	Warnf(format string, v ...interface{})
-	// Errorf logs an (non-fatal) error.
-	Errorf(format string, v ...interface{})
-	// Fatalf logs a fatal error message, and exits 1.
-	Fatalf(format string, v ...interface{})
-}
-
-// StandardLogger makes the go standard logger comply to our Logger interface.
-type StandardLogger struct{}
-
-// Debugf logs a message with "debug" severity.
-func (*StandardLogger) Debugf(f string, v ...interface{}) {
-	golog.Printf("DEBUG: %v", fmt.Sprintf(f, v...))
-}
-
-// Infof logs a message with "info" severity.
-func (*StandardLogger) Infof(f string, v ...interface{}) {
-	golog.Printf("INFO : %v", fmt.Sprintf(f, v...))
-}
-
-// Warnf logs a message with "warn" (non-fatal) severity.
-func (*StandardLogger) Warnf(f string, v ...interface{}) {
-	golog.Printf("WARN : %v", fmt.Sprintf(f, v...))
-}
-
-// Errorf logs an (non-fatal) error.
-func (*StandardLogger) Errorf(f string, v ...interface{}) {
-	golog.Printf("ERROR: %v", fmt.Sprintf(f, v...))
-}
-
-// Fatalf logs a fatal error message, and exits 1.
-func (*StandardLogger) Fatalf(f string, v ...interface{}) {
-	golog.Fatalf("FATAL: %v", fmt.Sprintf(f, v...))
-}
-
-// Log receives stdout/stderr of the hyperkit process itself, if set.
+// log receives stdout/stderr of the hyperkit process itself, if set.
 // It defaults to the go standard logger.
-var log Logger = &StandardLogger{}
+var log = InsinuateSystemLogger(logrus.StandardLogger())
 
 // SetLogger sets the logger to use.
-func SetLogger(l Logger) {
+func SetLogger(l *logrus.Logger) {
 	log = l
 }

go/log_darwin.c

@@ -0,0 +1,55 @@
+#include <fcntl.h>
+#include <stdio.h>
+#include <time.h>
+#include <SystemConfiguration/SystemConfiguration.h>
+
+#include "log_darwin.h"
+
+// logs
+
+static aslclient asl = NULL;
+static aslmsg log_msg = NULL;
+
+// asl is deprecated in favor of os_log starting with macOS 10.12.
+#pragma GCC diagnostic ignored "-Wdeprecated-declarations"
+
+void apple_asl_logger_init(const char* sender, const char* facility) {
+    free(asl);
+    // I believe that these guys, sender and facility, are useless.  I
+    // never managed to have them show in the actual logs.
+    asl = asl_open(sender, facility, 0);
+    log_msg = asl_new(ASL_TYPE_MSG);
+}
+
+static int is_initialized() {
+  if (asl) {
+    return true;
+  } else {
+      aslclient tmp_asl = asl_open("Docker", "com.docker.docker", ASL_OPT_STDERR);
+      log_msg = asl_new(ASL_TYPE_MSG);
+      asl_log(tmp_asl, log_msg, ASL_LEVEL_ERR, "asl_logger_init must be called before asl_logger_log");
+      free(tmp_asl);
+      return false;
+  }
+}
+
+void apple_asl_logger_log(int level, const char *message) {
+  if (!is_initialized())
+    return;
+
+  // The max length for log entries is 1024 bytes.  Beyond, they are
+  // truncated.  In that case, split into several log entries.
+  const size_t len = strlen(message);
+  if (len < 1024)
+    asl_log(asl, log_msg, level, "%s", message);
+  else {
+    enum { step = 1000 };
+    for (int pos = 0; pos < len; pos += step) {
+      asl_log(asl, log_msg, level,
+              "%s%.*s%s",
+              pos ? "[...] " : "",
+              step, message + pos,
+              pos + step < len ? " [...]" : "");
+    }
+  }
+}

go/log_darwin.go

@@ -0,0 +1,78 @@
+package hyperkit
+
+import (
+	"io/ioutil"
+	"os"
+	"path/filepath"
+
+	"github.com/sirupsen/logrus"
+)
+
+/*
+#cgo CFLAGS: -I .
+#cgo LDFLAGS: -framework CoreFoundation -framework Foundation -framework ServiceManagement -framework SystemConfiguration -framework CoreServices -framework IOKit
+
+#include "log_darwin.h"
+*/
+import "C"
+
+// InsinuateSystemLogger modifies a logrus Logger to sent its logs to
+// the system's logger (e.g, Apple's ASL).
+func InsinuateSystemLogger(log *logrus.Logger) *logrus.Logger {
+	log.SetLevel(logrus.DebugLevel)
+	log.AddHook(NewLogrusASLHook())
+	// In addition to the default destiniation, our logs are sent
+	// to ASL via the previous hook.  But since our stderr is also
+	// redirected to ASL, each entry would appear twice: don't
+	// send logs to stderr.
+	log.Out = ioutil.Discard
+	return log
+}
+
+// LogrusASLHook defines a hook for Logrus that redirects logs
+// to ASL API (to be displayed in Console application)
+type LogrusASLHook struct {
+}
+
+// NewLogrusASLHook returns a new LogrusASLHook
+func NewLogrusASLHook() *LogrusASLHook {
+	hook := new(LogrusASLHook)
+	C.apple_asl_logger_init(C.CString("Docker"), C.CString(filepath.Base(os.Args[0])))
+	return hook
+}
+
+// Levels returns the available ASL log levels
+func (t *LogrusASLHook) Levels() []logrus.Level {
+	return []logrus.Level{
+		logrus.PanicLevel,
+		logrus.FatalLevel,
+		logrus.ErrorLevel,
+		logrus.WarnLevel,
+		logrus.InfoLevel,
+		logrus.DebugLevel,
+	}
+}
+
+func aslLevel(l logrus.Level) C.int {
+	switch l {
+	case logrus.PanicLevel:
+		return C.ASL_LEVEL_ALERT
+	case logrus.FatalLevel:
+		return C.ASL_LEVEL_CRIT
+	case logrus.ErrorLevel:
+		return C.ASL_LEVEL_ERR
+	case logrus.WarnLevel:
+		return C.ASL_LEVEL_WARNING
+	case logrus.InfoLevel:
+		return C.ASL_LEVEL_NOTICE
+	case logrus.DebugLevel:
+		return C.ASL_LEVEL_DEBUG
+	}
+	return C.ASL_LEVEL_DEBUG
+}
+
+// Fire sends a log entry to ASL
+func (t *LogrusASLHook) Fire(entry *logrus.Entry) error {
+	C.apple_asl_logger_log(aslLevel(entry.Level), C.CString(entry.Message))
+	return nil
+}

go/log_darwin.h

@@ -0,0 +1,9 @@
+#pragma once
+
+#include <asl.h>
+#include <pwd.h>
+
+// aslInit must called before calling aslLog.
+extern void apple_asl_logger_init(const char* sender, const char* facility);
+extern void apple_asl_logger_log(int level, const char *message);
+

go/log_fallback.go

@@ -0,0 +1,11 @@
+// +build !darwin
+
+package hyperkit
+
+import (
+	"github.com/sirupsen/logrus"
+)
+
+func InsinuateSystemLogger(log *logrus.Logger) *logrus.Logger {
+	return log
+}