add FN_LOG_DEST for logs, fixup init (#663)

* add FN_LOG_DEST for logs, fixup init

* FN_LOG_DEST can point to a remote logging place (papertrail, whatever)
* FN_LOG_PREFIX can add a prefix onto each log line sent to FN_LOG_DEST

default remains stderr with no prefix. users need this to send to various
logging backends, though it could be done operationally, this is somewhat
simpler.

we were doing some configuration stuff inside of init() for some of the global
things. even though they're global, it's nice to keep them all in the normal
server init path.

we have had strange issues with the tracing setup, I tested the last repro of
this repeatedly and didn't have any luck reproducing it, though maybe it comes
back.

* add docs

api/common/logging.go

@@ -4,6 +4,7 @@ import (
 	"net/url"
 	"os"
 
+	"github.com/gin-gonic/gin"
 	"github.com/sirupsen/logrus"
 )
 
@@ -18,6 +19,12 @@ func SetLogLevel(ll string) {
 		logLevel = logrus.InfoLevel
 	}
 	logrus.SetLevel(logLevel)
+
+	// this effectively just adds more gin log goodies
+	gin.SetMode(gin.ReleaseMode)
+	if logLevel == logrus.DebugLevel {
+		gin.SetMode(gin.DebugMode)
+	}
 }
 
 func SetLogDest(to, prefix string) {

api/server/init.go

@@ -6,26 +6,13 @@ import (
 	"os/signal"
 	"strconv"
 
+	"github.com/fnproject/fn/api/common"
 	"github.com/gin-gonic/gin"
-	"github.com/sirupsen/logrus"
 )
 
 func init() {
-	logLevel, err := logrus.ParseLevel(getEnv(EnvLogLevel, DefaultLogLevel))
-	if err != nil {
-		logrus.WithError(err).Fatalln("Invalid log level.")
-	}
-	logrus.SetLevel(logLevel)
-
+	// gin is not nice by default, this can get set in logging initialization
 	gin.SetMode(gin.ReleaseMode)
-	if logLevel == logrus.DebugLevel {
-		gin.SetMode(gin.DebugMode)
-	}
-
-	// do this in init so that it's only run once & before server.New() which may
-	// start things that use spans, which are global.
-	// TODO there's not a great reason that our fn spans don't work w/ noop spans, should fix this really.
-	setupTracer(getEnv(EnvZipkinURL, ""))
 }
 
 func getEnv(key, fallback string) string {
@@ -56,11 +43,11 @@ func contextWithSignal(ctx context.Context, signals ...os.Signal) (context.Conte
 		for {
 			select {
 			case <-c:
-				logrus.Info("Halting...")
+				common.Logger(ctx).Info("Halting...")
 				halt()
 				return
 			case <-ctx.Done():
-				logrus.Info("Halting... Original server context canceled.")
+				common.Logger(ctx).Info("Halting... Original server context canceled.")
 				halt()
 				return
 			}

api/server/server.go

@@ -31,6 +31,8 @@ import (
 
 const (
 	EnvLogLevel  = "FN_LOG_LEVEL"
+	EnvLogDest   = "FN_LOG_DEST"
+	EnvLogPrefix = "FN_LOG_PREFIX"
 	EnvMQURL     = "FN_MQ_URL"
 	EnvDBURL     = "FN_DB_URL"
 	EnvLOGDBURL  = "FN_LOGSTORE_URL"
@@ -42,6 +44,7 @@ const (
 
 	// Defaults
 	DefaultLogLevel = "info"
+	DefaultLogDest  = "stderr"
 	DefaultPort     = 8080
 )
 
@@ -99,6 +102,9 @@ func NewFromEnv(ctx context.Context, opts ...ServerOption) *Server {
 		defaultDB = fmt.Sprintf("sqlite3://%s/data/fn.db", curDir)
 		defaultMQ = fmt.Sprintf("bolt://%s/data/fn.mq", curDir)
 	}
+	opts = append(opts, WithLogLevel(getEnv(EnvLogLevel, DefaultLogLevel)))
+	opts = append(opts, WithLogDest(getEnv(EnvLogDest, DefaultLogDest), getEnv(EnvLogPrefix, "")))
+	opts = append(opts, WithTracer(getEnv(EnvZipkinURL, ""))) // do this early on, so below can use these
 	opts = append(opts, WithDBURL(getEnv(EnvDBURL, defaultDB)))
 	opts = append(opts, WithMQURL(getEnv(EnvMQURL, defaultMQ)))
 	opts = append(opts, WithLogURL(getEnv(EnvLOGDBURL, "")))
@@ -116,6 +122,20 @@ func pwd() string {
 	return strings.Replace(cwd, "\\", "/", -1)
 }
 
+func WithLogLevel(ll string) ServerOption {
+	return func(ctx context.Context, s *Server) error {
+		common.SetLogLevel(ll)
+		return nil
+	}
+}
+
+func WithLogDest(dst, prefix string) ServerOption {
+	return func(ctx context.Context, s *Server) error {
+		common.SetLogDest(dst, prefix)
+		return nil
+	}
+}
+
 func WithDBURL(dbURL string) ServerOption {
 	return func(ctx context.Context, s *Server) error {
 		if dbURL != "" {
@@ -206,6 +226,9 @@ func WithAgent(agent agent.Agent) ServerOption {
 // New creates a new Functions server with the opts given. For convenience, users may
 // prefer to use NewFromEnv but New is more flexible if needed.
 func New(ctx context.Context, opts ...ServerOption) *Server {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "server_init")
+	defer span.Finish()
+
 	log := common.Logger(ctx)
 	s := &Server{
 		Router: gin.New(),
@@ -260,50 +283,53 @@ func New(ctx context.Context, opts ...ServerOption) *Server {
 }
 
 // TODO need to fix this to handle the nil case better
-func setupTracer(zipkinURL string) {
-	var (
-		debugMode          = false
-		serviceName        = "fnserver"
-		serviceHostPort    = "localhost:8080" // meh
-		zipkinHTTPEndpoint = zipkinURL
-		// ex: "http://zipkin:9411/api/v1/spans"
-	)
+func WithTracer(zipkinURL string) ServerOption {
+	return func(ctx context.Context, s *Server) error {
+		var (
+			debugMode          = false
+			serviceName        = "fnserver"
+			serviceHostPort    = "localhost:8080" // meh
+			zipkinHTTPEndpoint = zipkinURL
+			// ex: "http://zipkin:9411/api/v1/spans"
+		)
 
-	var collector zipkintracer.Collector
+		var collector zipkintracer.Collector
 
-	// custom Zipkin collector to send tracing spans to Prometheus
-	promCollector, promErr := NewPrometheusCollector()
-	if promErr != nil {
-		logrus.WithError(promErr).Fatalln("couldn't start Prometheus trace collector")
-	}
-
-	logger := zipkintracer.LoggerFunc(func(i ...interface{}) error { logrus.Error(i...); return nil })
-
-	if zipkinHTTPEndpoint != "" {
-		// Custom PrometheusCollector and Zipkin HTTPCollector
-		httpCollector, zipErr := zipkintracer.NewHTTPCollector(zipkinHTTPEndpoint, zipkintracer.HTTPLogger(logger))
-		if zipErr != nil {
-			logrus.WithError(zipErr).Fatalln("couldn't start Zipkin trace collector")
+		// custom Zipkin collector to send tracing spans to Prometheus
+		promCollector, promErr := NewPrometheusCollector()
+		if promErr != nil {
+			logrus.WithError(promErr).Fatalln("couldn't start Prometheus trace collector")
 		}
-		collector = zipkintracer.MultiCollector{httpCollector, promCollector}
-	} else {
-		// Custom PrometheusCollector only
-		collector = promCollector
+
+		logger := zipkintracer.LoggerFunc(func(i ...interface{}) error { logrus.Error(i...); return nil })
+
+		if zipkinHTTPEndpoint != "" {
+			// Custom PrometheusCollector and Zipkin HTTPCollector
+			httpCollector, zipErr := zipkintracer.NewHTTPCollector(zipkinHTTPEndpoint, zipkintracer.HTTPLogger(logger))
+			if zipErr != nil {
+				logrus.WithError(zipErr).Fatalln("couldn't start Zipkin trace collector")
+			}
+			collector = zipkintracer.MultiCollector{httpCollector, promCollector}
+		} else {
+			// Custom PrometheusCollector only
+			collector = promCollector
+		}
+
+		ziptracer, err := zipkintracer.NewTracer(zipkintracer.NewRecorder(collector, debugMode, serviceHostPort, serviceName),
+			zipkintracer.ClientServerSameSpan(true),
+			zipkintracer.TraceID128Bit(true),
+		)
+		if err != nil {
+			logrus.WithError(err).Fatalln("couldn't start tracer")
+		}
+
+		// wrap the Zipkin tracer in a FnTracer which will also send spans to Prometheus
+		fntracer := NewFnTracer(ziptracer)
+
+		opentracing.SetGlobalTracer(fntracer)
+		logrus.WithFields(logrus.Fields{"url": zipkinHTTPEndpoint}).Info("started tracer")
+		return nil
 	}
-
-	ziptracer, err := zipkintracer.NewTracer(zipkintracer.NewRecorder(collector, debugMode, serviceHostPort, serviceName),
-		zipkintracer.ClientServerSameSpan(true),
-		zipkintracer.TraceID128Bit(true),
-	)
-	if err != nil {
-		logrus.WithError(err).Fatalln("couldn't start tracer")
-	}
-
-	// wrap the Zipkin tracer in a FnTracer which will also send spans to Prometheus
-	fntracer := NewFnTracer(ziptracer)
-
-	opentracing.SetGlobalTracer(fntracer)
-	logrus.WithFields(logrus.Fields{"url": zipkinHTTPEndpoint}).Info("started tracer")
 }
 
 func setMachineID() {

docs/operating/options.md

@@ -26,6 +26,8 @@ docker run -e VAR_NAME=VALUE ...
 | `FN_API_URL` | The primary Fn API URL to that this instance will talk to. In a production environment, this would be your load balancer URL. | N/A |
 | `FN_PORT `| Sets the port to run on | 8080 |
 | `FN_LOG_LEVEL` | Set to DEBUG to enable debugging | INFO |
+| `FN_LOG_DEST` | Set a url to send logs to, instead of stderr. [scheme://][host][:port][/path]; default scheme to udp:// if none given, possible schemes: { udp, tcp, file }
+| `FN_LOG_PREFIX` | If supplying a syslog url in `FN_LOG_DEST`, a prefix to add to each log line
 | `FN_API_CORS` | A comma separated list of URLs to enable [CORS](https://developer.mozilla.org/en-US/docs/Web/HTTP/CORS) for (or `*` for all domains). This corresponds to the allowed origins in the `Acccess-Control-Allow-Origin` header.  | None |
 | `DOCKER_HOST` | Docker remote API URL. | /var/run/docker.sock |
 | `DOCKER_API_VERSION` | Docker remote API version. | 1.24 |