continue the munging around, TODO figure out how to configure the env vars

Author: rdallman

api/agent/agent.go

@@ -1177,23 +1177,24 @@ func newHotContainer(ctx context.Context, evictor Evictor, call *call, cfg *Conf
 	// have to be read or *BOTH* blocked consistently. In other words, we cannot block one and continue
 	// reading from the other one without risking head-of-line blocking.
 
-	// TODO(reed): we should let the syslog driver pick this up really but our
-	// default story sucks there
-
 	// disable container logs if they're disabled on the call (pure_runner) -
 	// users may use syslog to get container logs, unrelated to this writer.
 	// otherwise, make a line writer and allow logrus DEBUG logs to host stderr
 	// between function invocations from the container.
 
 	var bufs []*bytes.Buffer
 	var stderr io.WriteCloser = call.stderr
-	if _, ok := stderr.(common.NoopReadWriteCloser); !ok {
+	if _, ok := stderr.(common.NoopReadWriteCloser); !ok && !cfg.DisableDebugUserLogs {
 		gw := common.NewGhostWriter()
 		buf1 := bufPool.Get().(*bytes.Buffer)
-		// TODO(reed): this logger may have garbage in it between calls, easy fix
-		// is to make a new one each swap, it's cheap enough to be doable.
+		// TODO(reed): this logger may have garbage in it between calls (without
+		// calling Close() to flush newlines, since we're swapping we can't), easy
+		// fix is to make a new one each swap, it's cheap enough to be doable.
+		// TODO(reed): we should only do this if they configure to log stderr, not if they use WithLogger(),
+		// for now use explicit disable with DisableDebugUserLogs
 		sec := &nopCloser{newLogWriter(
 			logrus.WithFields(logrus.Fields{"tag": "stderr", "app_id": call.AppID, "fn_id": call.FnID, "image": call.Image, "container_id": id}),
+			cfg.UserLogLevel,
 		)}
 		gw.Swap(newLineWriterWithBuffer(buf1, sec))
 		stderr = gw
@@ -1316,7 +1317,6 @@ func (c *container) DisableNet() bool                   { return c.disableNet }
 func (c *container) WriteStat(ctx context.Context, stat driver_stats.Stat) {
 	for key, value := range stat.Metrics {
 		if m, ok := dockerMeasures[key]; ok {
-			common.Logger(ctx).WithField(key, value).Info("container stats")
 			stats.Record(ctx, m.M(int64(value)))
 		}
 	}

api/agent/agent_test.go

@@ -275,65 +275,6 @@ func TestGetCallFromModelRoundTripACall(t *testing.T) {
 	}
 }
 
-func TestLoggerIsStringerAndWorks(t *testing.T) {
-	// TODO test limit writer, logrus writer, etc etc
-
-	var call models.Call
-	logger := setupLogger(context.Background(), 1*1024*1024, true, &call)
-
-	if _, ok := logger.(fmt.Stringer); !ok {
-		// NOTE: if you are reading, maybe what you've done is ok, but be aware we were relying on this for optimization...
-		t.Fatal("you turned the logger into something inefficient and possibly better all at the same time, how dare ye!")
-	}
-
-	str := "0 line\n1 line\n2 line\n\n4 line"
-	logger.Write([]byte(str))
-
-	strGot := logger.(fmt.Stringer).String()
-
-	if strGot != str {
-		t.Fatal("logs did not match expectations, like being an adult", strGot, str)
-	}
-
-	logger.Close() // idk maybe this would panic might as well ca this
-
-	// TODO we could check for the toilet to flush here to logrus
-}
-
-func TestLoggerTooBig(t *testing.T) {
-
-	var call models.Call
-	logger := setupLogger(context.Background(), 10, true, &call)
-
-	str := fmt.Sprintf("0 line\n1 l\n-----max log size 10 bytes exceeded, truncating log-----\n")
-
-	n, err := logger.Write([]byte(str))
-	if err != nil {
-		t.Fatalf("err returned, but should not fail err=%v n=%d", err, n)
-	}
-	if n != len(str) {
-		t.Fatalf("n should be %d, but got=%d", len(str), n)
-	}
-
-	// oneeeeee moreeee time... (cue in Daft Punk), the results appear as if we wrote
-	// again... But only "limit" bytes should succeed, ignoring the subsequent writes...
-	n, err = logger.Write([]byte(str))
-	if err != nil {
-		t.Fatalf("err returned, but should not fail err=%v n=%d", err, n)
-	}
-	if n != len(str) {
-		t.Fatalf("n should be %d, but got=%d", len(str), n)
-	}
-
-	strGot := logger.(fmt.Stringer).String()
-
-	if strGot != str {
-		t.Fatalf("logs did not match expectations, like being an adult got=\n%v\nexpected=\n%v\n", strGot, str)
-	}
-
-	logger.Close()
-}
-
 type testListener struct {
 	afterCall func(context.Context, *models.Call) error
 }

api/agent/call.go

@@ -213,10 +213,17 @@ func WithDockerAuth(auth docker.Auther) CallOpt {
 	}
 }
 
-func (a *agent) WithStderrLogger() CallOpt {
+// WithStderrLogger configures a call to have its container logs logged by fn.
+// Configure UserLogLevel or DisableDebugUserLogs on agent to change behavior.
+func WithStderrLogger() CallOpt {
+	// TODO(reed): we could take a context here which would allow request level logging vars on ctx to be used here too
 	return func(c *call) error {
-		// XXX(reed): allow configuring the level / turning off
-		c.stderr = setupLogger(c.Call)
+		// TODO(reed): fucking hell this is a pain to configure
+		if a.cfg.DisableDebugUserLogs {
+			return nil
+		}
+
+		c.stderr = setupLogger(a.cfg.UserLogLevel, c.Call)
 		return nil
 	}
 }
@@ -328,10 +335,6 @@ func (c *call) ResponseWriter() http.ResponseWriter {
 	return c.respWriter.(http.ResponseWriter)
 }
 
-func (c *call) StdErr() io.ReadWriteCloser {
-	return c.stderr
-}
-
 func (c *call) AddUserExecutionTime(dur time.Duration) {
 	if c.userExecTime == nil {
 		c.userExecTime = new(time.Duration)

api/agent/config.go

@@ -38,6 +38,7 @@ type Config struct {
 	MaxTmpFsInodes                uint64        `json:"max_tmpfs_inodes"`
 	DisableReadOnlyRootFs         bool          `json:"disable_readonly_rootfs"`
 	DisableDebugUserLogs          bool          `json:"disable_debug_user_logs"`
+	UserLogLevel                  string        `json:"user_log_level"`
 	IOFSEnableTmpfs               bool          `json:"iofs_enable_tmpfs"`
 	IOFSAgentPath                 string        `json:"iofs_path"`
 	IOFSMountRoot                 string        `json:"iofs_mount_root"`
@@ -69,16 +70,14 @@ const (
 	EnvHotPoll = "FN_HOT_POLL_MSECS"
 	// EnvHotLauncherTimeout is the timeout for a hot container queue to persist if idle
 	EnvHotLauncherTimeout = "FN_HOT_LAUNCHER_TIMEOUT_MSECS"
-	// EnvHotStartTimeout is the timeout for a hot container to be created including docker-pull
+	// EnvHotPullTimeout is the timeout for a hot container to be created including docker-pull
 	EnvHotPullTimeout = "FN_HOT_PULL_TIMEOUT_MSECS"
 	// EnvHotStartTimeout is the timeout for a hot container to become available for use for requests after EnvHotStartTimeout
 	EnvHotStartTimeout = "FN_HOT_START_TIMEOUT_MSECS"
 	// EnvMaxResponseSize is the maximum number of bytes that a function may return from an invocation
 	EnvMaxResponseSize = "FN_MAX_RESPONSE_SIZE"
-	// EnvHdrMaxResponseSize is the maximum number of bytes that a function may return in an invocation header
+	// EnvMaxHdrResponseSize is the maximum number of bytes that a function may return in an invocation header
 	EnvMaxHdrResponseSize = "FN_MAX_HDR_RESPONSE_SIZE"
-	// EnvMaxLogSize is the maximum size that a function's log may reach
-	EnvMaxLogSize = "FN_MAX_LOG_SIZE_BYTES"
 	// EnvMaxTotalCPU is the maximum CPU that will be reserved across all containers
 	EnvMaxTotalCPU = "FN_MAX_TOTAL_CPU_MCPUS"
 	// EnvMaxTotalMemory is the maximum memory that will be reserved across all containers
@@ -106,6 +105,8 @@ const (
 	EnvDisableReadOnlyRootFs = "FN_DISABLE_READONLY_ROOTFS"
 	// EnvDisableDebugUserLogs disables user function logs being logged at level debug. wise to enable for production.
 	EnvDisableDebugUserLogs = "FN_DISABLE_DEBUG_USER_LOGS"
+	// EnvUserLogLevel is the logging level to use for user's function logs to be logged by fn. to disable explicitly, use FN_DISABLE_DEBUG_USER_LOGS
+	EnvUserLogLevel = "FN_USER_LOG_LEVEL"
 
 	// EnvIOFSEnableTmpfs enables creating a per-container tmpfs mount for the IOFS
 	EnvIOFSEnableTmpfs = "FN_IOFS_TMPFS"
@@ -140,7 +141,6 @@ const (
 func NewConfig() (*Config, error) {
 	cfg := &Config{
 		MinDockerVersion: "17.10.0-ce",
-		MaxLogSize:       1 * 1024 * 1024,
 		PreForkImage:     "busybox",
 		PreForkCmd:       "tail -f /dev/null",
 	}
@@ -154,7 +154,6 @@ func NewConfig() (*Config, error) {
 	err = setEnvMsecs(err, EnvDetachedHeadroom, &cfg.DetachedHeadRoom, time.Duration(360)*time.Second)
 	err = setEnvUint(err, EnvMaxResponseSize, &cfg.MaxResponseSize)
 	err = setEnvUint(err, EnvMaxHdrResponseSize, &cfg.MaxHdrResponseSize)
-	err = setEnvUint(err, EnvMaxLogSize, &cfg.MaxLogSize)
 	err = setEnvUint(err, EnvMaxTotalCPU, &cfg.MaxTotalCPU)
 	err = setEnvUint(err, EnvMaxTotalMemory, &cfg.MaxTotalMemory)
 	err = setEnvUint(err, EnvMaxFsSize, &cfg.MaxFsSize)
@@ -176,6 +175,7 @@ func NewConfig() (*Config, error) {
 	err = setEnvBool(err, EnvEnableNBResourceTracker, &cfg.EnableNBResourceTracker)
 	err = setEnvBool(err, EnvDisableReadOnlyRootFs, &cfg.DisableReadOnlyRootFs)
 	err = setEnvBool(err, EnvDisableDebugUserLogs, &cfg.DisableDebugUserLogs)
+	err = setEnvStr(err, EnvUserLogLevel, &cfg.UserLogLevel)
 	err = setEnvUint(err, EnvImageCleanMaxSize, &cfg.ImageCleanMaxSize)
 	err = setEnvStr(err, EnvImageCleanExemptTags, &cfg.ImageCleanExemptTags)
 	err = setEnvBool(err, EnvImageEnableVolume, &cfg.ImageEnableVolume)
@@ -184,11 +184,6 @@ func NewConfig() (*Config, error) {
 		return cfg, err
 	}
 
-	if cfg.MaxLogSize > math.MaxInt64 {
-		// for safety during uint64 to int conversions in Write()/Read(), etc.
-		return cfg, fmt.Errorf("error invalid %s %v > %v", EnvMaxLogSize, cfg.MaxLogSize, math.MaxInt64)
-	}
-
 	return cfg, nil
 }
 

api/agent/func_logger.go

@@ -15,7 +15,7 @@ var (
 )
 
 // * [always] writes bytes per line to stderr as DEBUG
-func setupLogger(c *models.Call) io.WriteCloser {
+func setupLogger(level string, c *models.Call) io.WriteCloser {
 	lbuf := bufPool.Get().(*bytes.Buffer)
 
 	close := func() {
@@ -25,7 +25,7 @@ func setupLogger(c *models.Call) io.WriteCloser {
 	}
 
 	stderrLogger := logrus.WithFields(logrus.Fields{"user_log": true, "app_id": c.AppID, "fn_id": c.FnID, "image": c.Image, "call_id": c.ID})
-	loggo := newLogWriter(stderrLogger)
+	loggo := newLogWriter(stderrLogger, level)
 	linew := newLineWriterWithBuffer(lbuf, loggo)
 	linew = &fCloser{
 		close: func() error {
@@ -54,21 +54,27 @@ func (n *nopCloser) Close() error { return nil }
 // logWriter will log (to real stderr) every call to Write as a line. it should
 // be wrapped with a lineWriter so that the output makes sense.
 type logWriter struct {
-	// level string // XXX(reed):
-	logrus.FieldLogger
+	level  logrus.Level
+	logger logrus.FieldLogger
 	closed uint32
 }
 
-func newLogWriter(logger logrus.FieldLogger) io.WriteCloser {
-	return &logWriter{FieldLogger: logger}
+func newLogWriter(logger logrus.FieldLogger, level string) io.WriteCloser {
+	lv, err := logrus.ParseLevel(level)
+	if err != nil {
+		// TODO(reed): we should do this at the config level instead? it's an optional option to begin with tho (StderrLogger)
+		lv = logrus.InfoLevel // default
+	}
+
+	return &logWriter{logger: logger, level: lv}
 }
 
 func (l *logWriter) Write(b []byte) (int, error) {
 	if atomic.LoadUint32(&l.closed) == 1 {
 		// we don't want to return 0/error or the container will get shut down
 		return len(b), nil
 	}
-	l.Debug(string(b))
+	l.logger.WithFields(nil).Log(l.level, string(b))
 	return len(b), nil
 }
 

api/agent/lb_agent_test.go

@@ -125,10 +125,6 @@ func (c *mockRunnerCall) ResponseWriter() http.ResponseWriter {
 	return c.rw
 }
 
-func (c *mockRunnerCall) StdErr() io.ReadWriteCloser {
-	return c.stdErr
-}
-
 func (c *mockRunnerCall) Model() *models.Call {
 	return c.model
 }

api/runnerpool/runner_pool.go

@@ -59,7 +59,6 @@ type RunnerCall interface {
 	Extensions() map[string]string
 	RequestBody() io.ReadCloser
 	ResponseWriter() http.ResponseWriter
-	StdErr() io.ReadWriteCloser
 	Model() *models.Call
 	// For metrics/stats, add special accounting for time spent in customer code
 	AddUserExecutionTime(dur time.Duration)

api/server/runner_fninvoke.go

@@ -109,7 +109,7 @@ func (s *Server) fnInvoke(resp http.ResponseWriter, req *http.Request, app *mode
 		}
 	}
 
-	opts = append(opts, agent.WithWriter(rw))
+	opts = append(opts, agent.WithWriter(writer))
 	opts = append(opts, agent.WithStderrLogger())
 	if trig != nil {
 		opts = append(opts, agent.WithTrigger(trig))