alihan/fn-serverless
1
0
Fork 0
mirror of https://github.com/fnproject/fn.git synced 2022-10-28 21:29:17 +03:00
Code Issues Packages Projects Releases Wiki Activity

make fn logger more reasonable

Browse Source 
something still feels off with this, but i tinkered with it for a day-ish and
didn't come up with anything a whole lot better. doing a lot of the
maneuvering in the caller seemed better but it was just bloating up GetCall so
went back to having it basically like it was, but returning the limited
underlying buffer to read from so we can ship to the db.

some small changes to the LogStore interface, swapped it to take an
io.Reader instead of a string for more flexibility in the future while
essentially maintaining the same level of performance that we have now.
i'm guessing in the not so distant future we'll ship these to some s3 like
service and it would be better to stream them in than carry around a giant
string anyway. also, carrying around up to 1MB buffers in memory isn't great,
we may want to switch to file backed logs for calls, too. using io.Reader for
logs should make #279 more reasonable if/once we move to some s3-like thing,
we can stream from the log storage service direct to clients.

this fixes the span being out of whack and allows the 'right' context to be
used to upload logs (next to inserting the call). deletes the dbWriter we had,
and we just do this in call.End now (which makes sense to me at least).
removes the dupe code for making an stderr for hot / cold and simplifies the
way to get a func logger (no more 7 param methods yay).

closes #298
This commit is contained in:
Reed Allman
2017-09-06 12:52:40 -07:00
parent 0280df0cdf
commit 1811b4e230
9 changed files with 126 additions and 111 deletions
Download Patch File Download Diff File Expand all files Collapse all files

42
api/agent/agent.go
View File

@@ -428,7 +428,6 @@ type slot interface {
type coldSlot struct {
cookie drivers.Cookie
tok Token
stderr io.Closer
}
func (s *coldSlot) exec(ctx context.Context, call *call) error {
@@ -459,7 +458,6 @@ func (s *coldSlot) Close() error {
s.cookie.Close(context.Background()) // ensure container removal, separate ctx
}
s.tok.Close()
s.stderr.Close()
return nil
}
@@ -477,20 +475,11 @@ func (s *hotSlot) exec(ctx context.Context, call *call) error {
span, ctx := opentracing.StartSpanFromContext(ctx, "agent_hot_exec")
defer span.Finish()
stderr := NewFuncLogger(ctx, call.AppName, call.Path, call.Image, call.ID, call.ds)
if call.w == nil {
// send STDOUT to logs if no writer given (async...)
// TODO fuck func logger, change it to not need a context and make calls
// require providing their own stderr and writer instead of this crap. punting atm.
call.w = stderr
}
// link the container id and id in the logs [for us!]
common.Logger(ctx).WithField("container_id", s.container.id).Info("starting call")
// swap in the new id and the new stderr logger
s.container.swap(stderr)
defer stderr.Close() // TODO shove in Close / elsewhere (to upload logs after exec exits)
// swap in the new stderr logger
s.container.swap(call.stderr)
errApp := make(chan error, 1)
go func() {
@@ -541,15 +530,6 @@ func (a *agent) launch(ctx context.Context, slots chan<- slot, call *call, tok T
}
func (a *agent) prepCold(ctx context.Context, slots chan<- slot, call *call, tok Token) error {
// TODO dupe stderr code, reduce me
stderr := NewFuncLogger(ctx, call.AppName, call.Path, call.Image, call.ID, call.ds)
if call.w == nil {
// send STDOUT to logs if no writer given (async...)
// TODO fuck func logger, change it to not need a context and make calls
// require providing their own stderr and writer instead of this crap. punting atm.
call.w = stderr
}
container := &container{
id: id.New().String(), // XXX we could just let docker generate ids...
image: call.Image,
@@ -558,7 +538,7 @@ func (a *agent) prepCold(ctx context.Context, slots chan<- slot, call *call, tok
timeout: time.Duration(call.Timeout) * time.Second, // this is unnecessary, but in case removal fails...
stdin: call.req.Body,
stdout: call.w,
stderr: stderr,
stderr: call.stderr,
}
// pull & create container before we return a slot, so as to be friendly
@@ -569,7 +549,7 @@ func (a *agent) prepCold(ctx context.Context, slots chan<- slot, call *call, tok
return err
}
slot := &coldSlot{cookie, tok, stderr}
slot := &coldSlot{cookie, tok}
select {
case slots <- slot: // TODO need to make sure receiver will be ready (go routine race)
default:
@@ -600,19 +580,22 @@ func (a *agent) runHot(slots chan<- slot, call *call, tok Token) error {
ctx, shutdownContainer := context.WithCancel(context.Background())
defer shutdownContainer() // close this if our waiter returns
cid := id.New().String()
// set up the stderr for the first one to capture any logs before the slot is
// executed.
// TODO need to figure out stderr logging for hot functions at a high level
stderr := &ghostWriter{inner: newLineWriter(&logWriter{ctx: ctx, appName: call.AppName, path: call.Path, image: call.Image, reqID: call.ID})}
// executed and between hot functions TODO this is still a little tobias funke
stderr := newLineWriter(&logWriter{
logrus.WithFields(logrus.Fields{"between_log": true, "app_name": call.AppName, "path": call.Path, "image": call.Image, "container_id": cid}),
})
container := &container{
id: id.New().String(), // XXX we could just let docker generate ids...
id: cid, // XXX we could just let docker generate ids...
image: call.Image,
env: call.BaseEnv, // only base env
memory: call.Memory,
stdin: stdinRead,
stdout: stdoutWrite,
stderr: stderr,
stderr: &ghostWriter{inner: stderr},
}
logger := logrus.WithFields(logrus.Fields{"id": container.id, "app": call.AppName, "route": call.Path, "image": call.Image, "memory": call.Memory, "format": call.Format, "idle_timeout": call.IdleTimeout})
@@ -663,6 +646,7 @@ func (a *agent) runHot(slots chan<- slot, call *call, tok Token) error {
// wait for this call to finish
// NOTE do NOT select with shutdown / other channels. slot handles this.
<-done
container.swap(stderr) // log between tasks
}
}()

27
api/agent/agent_test.go
View File

@@ -2,6 +2,7 @@ package agent
import (
"bytes"
"fmt"
"io"
"net/http"
"net/http/httptest"
@@ -13,6 +14,7 @@ import (
"github.com/fnproject/fn/api/datastore"
"github.com/fnproject/fn/api/models"
"github.com/fnproject/fn/api/mqs"
"github.com/sirupsen/logrus"
)
func TestCallConfigurationRequest(t *testing.T) {
@@ -273,3 +275,28 @@ func TestCallConfigurationModel(t *testing.T) {
t.Fatal("expected payload to match, but it was a lie")
}
}
func TestLoggerIsStringerAndWorks(t *testing.T) {
// TODO test limit writer, logrus writer, etc etc
loggyloo := logrus.WithFields(logrus.Fields{"yodawg": true})
logger := setupLogger(loggyloo)
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 call this
// TODO we could check for the toilet to flush here to logrus
}

21
api/agent/call.go
View File

@@ -246,7 +246,6 @@ func (a *agent) GetCall(opts ...CallOpt) (Call, error) {
return nil, errors.New("no model or request provided for call")
}
// TODO move func logger here
// TODO add log store interface (yagni?)
c.ds = a.ds
c.mq = a.mq
@@ -255,6 +254,15 @@ func (a *agent) GetCall(opts ...CallOpt) (Call, error) {
logrus.Fields{"id": c.ID, "app": c.AppName, "route": c.Path})
c.req = c.req.WithContext(ctx)
// setup stderr logger separate (don't inherit ctx vars)
logger := logrus.WithFields(logrus.Fields{"user_log": true, "app_name": c.AppName, "path": c.Path, "image": c.Image, "call_id": c.ID})
c.stderr = setupLogger(logger)
if c.w == nil {
// send STDOUT to logs if no writer given (async...)
// TODO we could/should probably make this explicit to GetCall, ala 'WithLogger', but it's dupe code (who cares?)
c.w = c.stderr
}
return &c, nil
}
@@ -265,7 +273,7 @@ type call struct {
mq models.MessageQueue
w io.Writer
req *http.Request
stderr io.WriteCloser
stderr io.ReadWriteCloser
}
func (c *call) Model() *models.Call { return c.Call }
@@ -335,8 +343,15 @@ func (c *call) End(ctx context.Context, err error) {
// call that ran successfully [by a user's perspective]
// TODO: this should be update, really
if err := c.ds.InsertCall(ctx, c.Call); err != nil {
logrus.WithError(err).Error("error inserting call into datastore")
common.Logger(ctx).WithError(err).Error("error inserting call into datastore")
}
if err := c.ds.InsertLog(ctx, c.AppName, c.ID, c.stderr); err != nil {
common.Logger(ctx).WithError(err).Error("error uploading log")
}
// NOTE call this after InsertLog or the buffer will get reset
c.stderr.Close()
}
func fakeHandler(http.ResponseWriter, *http.Request, Params) {}

97
api/agent/func_logger.go
View File

@@ -2,15 +2,11 @@ package agent
import (
"bytes"
"context"
"errors"
"fmt"
"io"
"sync"
"github.com/fnproject/fn/api/common"
"github.com/fnproject/fn/api/models"
"github.com/opentracing/opentracing-go"
"github.com/sirupsen/logrus"
)
@@ -19,13 +15,10 @@ var (
logPool = &sync.Pool{New: func() interface{} { return new(bytes.Buffer) }}
)
// TODO we can have different types of these func loggers later
// TODO move this to a different package
// DefaultFuncLogger returns a WriteCloser that writes STDERR output from a
// container and outputs it in a parsed structured log format to attached
// STDERR as well as writing the log to the db when Close is called.
func NewFuncLogger(ctx context.Context, appName, path, image, reqID string, logDB models.LogStore) io.WriteCloser {
// setupLogger returns an io.ReadWriteCloser which may write to multiple io.Writer's,
// and may be read from the returned io.Reader (singular). After Close is called,
// the Reader is not safe to read from, nor the Writer to write to.
func setupLogger(logger logrus.FieldLogger) io.ReadWriteCloser {
lbuf := bufPool.Get().(*bytes.Buffer)
dbuf := logPool.Get().(*bytes.Buffer)
@@ -39,34 +32,33 @@ func NewFuncLogger(ctx context.Context, appName, path, image, reqID string, logD
}
// we don't need to limit the log writer, but we do need it to dispense lines
linew := newLineWriterWithBuffer(lbuf, &logWriter{
ctx: ctx,
appName: appName,
path: path,
image: image,
reqID: reqID,
})
linew := newLineWriterWithBuffer(lbuf, &logWriter{logger})
const MB = 1 * 1024 * 1024 // pick a number any number.. TODO configurable ?
// we don't need to log per line to db, but we do need to limit it
limitw := newLimitWriter(MB, &dbWriter{
Buffer: dbuf,
db: logDB,
ctx: ctx,
reqID: reqID,
appName: appName,
})
limitw := &nopCloser{newLimitWriter(MB, dbuf)}
// TODO / NOTE: we want linew to be first because limitw may error if limit
// is reached but we still want to log. we should probably ignore hitting the
// limit error since we really just want to not write too much to db and
// that's handled as is. put buffers back last to avoid misuse, if there's
// an error they won't get put back and that's really okay too.
return multiWriteCloser{linew, limitw, &fCloser{close}}
mw := multiWriteCloser{linew, limitw, &fCloser{close}}
return &rwc{mw, dbuf}
}
// implements passthrough Write & arbitrary func close to have a seat at the cool kids lunch table
// implements io.ReadWriteCloser, keeps the buffer for all its handy methods
type rwc struct {
io.WriteCloser
*bytes.Buffer
}
// these are explicit to override the *bytes.Buffer's methods
func (r *rwc) Write(b []byte) (int, error) { return r.WriteCloser.Write(b) }
func (r *rwc) Close() error { return r.WriteCloser.Close() }
// implements passthrough Write & closure call in Close
type fCloser struct {
close func() error
}
@@ -74,6 +66,12 @@ type fCloser struct {
func (f *fCloser) Write(b []byte) (int, error) { return len(b), nil }
func (f *fCloser) Close() error { return f.close() }
type nopCloser struct {
io.Writer
}
func (n *nopCloser) Close() error { return nil }
// multiWriteCloser returns the first write or close that returns a non-nil
// err, if no non-nil err is returned, then the returned bytes written will be
// from the last call to write.
@@ -102,17 +100,11 @@ func (m multiWriteCloser) Close() (err error) {
// 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 {
ctx context.Context
appName string
path string
image string
reqID string
logrus.FieldLogger
}
func (l *logWriter) Write(b []byte) (int, error) {
log := common.Logger(l.ctx)
log = log.WithFields(logrus.Fields{"user_log": true, "app_name": l.appName, "path": l.path, "image": l.image, "call_id": l.reqID})
log.Debug(string(b))
l.Debug(string(b))
return len(b), nil
}
@@ -171,37 +163,14 @@ func (li *lineWriter) Close() error {
return err
}
// dbWriter accumulates all calls to Write into an in memory buffer
// and writes them to the database when Close is called, returning
// any error from Close. it should be wrapped in a limitWriter to
// prevent blowing out the buffer and bloating the db.
type dbWriter struct {
*bytes.Buffer
db models.LogStore
ctx context.Context
reqID string
appName string
}
func (w *dbWriter) Close() error {
span, ctx := opentracing.StartSpanFromContext(context.Background(), "agent_log_write")
defer span.Finish()
return w.db.InsertLog(ctx, w.appName, w.reqID, w.String())
}
func (w *dbWriter) Write(b []byte) (int, error) {
return w.Buffer.Write(b)
}
// overrides Write, keeps Close
// io.Writer that allows limiting bytes written to w
type limitWriter struct {
n, max int
io.WriteCloser
io.Writer
}
func newLimitWriter(max int, w io.WriteCloser) io.WriteCloser {
return &limitWriter{max: max, WriteCloser: w}
func newLimitWriter(max int, w io.Writer) io.Writer {
return &limitWriter{max: max, Writer: w}
}
func (l *limitWriter) Write(b []byte) (int, error) {
@@ -212,11 +181,11 @@ func (l *limitWriter) Write(b []byte) (int, error) {
// cut off to prevent gigantic line attack
b = b[:l.max-l.n]
}
n, err := l.WriteCloser.Write(b)
n, err := l.Writer.Write(b)
l.n += n
if l.n >= l.max {
// write in truncation message to log once
l.WriteCloser.Write([]byte(fmt.Sprintf("\n-----max log size %d bytes exceeded, truncating log-----\n")))
l.Writer.Write([]byte(fmt.Sprintf("\n-----max log size %d bytes exceeded, truncating log-----\n")))
}
return n, err
}